logd: optimize code hotspots

Discovered that we had a few libc hotspots. Adjust code to generally
reduce or nullify the number of calls to malloc, free, strlen,
strcmp, strncmp, memcmp & strncasecmp. Total gain looks to be about
3% of logd's processing time. malloc still contributes to 3%, but all
others are now total 0.5%.

Bug: 23685592
Change-Id: Ife721121667969260cdb8b055524ae90f5911278
This commit is contained in:
Mark Salyzyn 2015-10-02 09:22:52 -07:00
parent 5ac5c6b193
commit ddda212faa
8 changed files with 72 additions and 50 deletions

View file

@ -24,6 +24,7 @@
#include <sys/uio.h>
#include <syslog.h>
#include <log/logger.h>
#include <private/android_filesystem_config.h>
#include <private/android_logger.h>
@ -153,15 +154,16 @@ int LogAudit::logPrint(const char *fmt, ...) {
// log to events
size_t l = strlen(str);
size_t l = strnlen(str, LOGGER_ENTRY_MAX_PAYLOAD);
size_t n = l + sizeof(android_log_event_string_t);
bool notify = false;
android_log_event_string_t *event = static_cast<android_log_event_string_t *>(malloc(n));
if (!event) {
rc = -ENOMEM;
} else {
{ // begin scope for event buffer
uint32_t buffer[(n + sizeof(uint32_t) - 1) / sizeof(uint32_t)];
android_log_event_string_t *event
= reinterpret_cast<android_log_event_string_t *>(buffer);
event->header.tag = htole32(AUDITD_LOG_TAG);
event->type = EVENT_TYPE_STRING;
event->length = htole32(l);
@ -170,11 +172,10 @@ int LogAudit::logPrint(const char *fmt, ...) {
rc = logbuf->log(LOG_ID_EVENTS, now, uid, pid, tid,
reinterpret_cast<char *>(event),
(n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX);
free(event);
if (rc >= 0) {
notify = true;
}
// end scope for event buffer
}
// log to main
@ -206,24 +207,28 @@ int LogAudit::logPrint(const char *fmt, ...) {
l = strlen(comm) + 1;
ecomm = "";
}
n = (estr - str) + strlen(ecomm) + l + 2;
size_t b = estr - str;
if (b > LOGGER_ENTRY_MAX_PAYLOAD) {
b = LOGGER_ENTRY_MAX_PAYLOAD;
}
size_t e = strnlen(ecomm, LOGGER_ENTRY_MAX_PAYLOAD - b);
n = b + e + l + 2;
{ // begin scope for main buffer
char newstr[n];
char *newstr = static_cast<char *>(malloc(n));
if (!newstr) {
rc = -ENOMEM;
} else {
*newstr = info ? ANDROID_LOG_INFO : ANDROID_LOG_WARN;
strlcpy(newstr + 1, comm, l);
strncpy(newstr + 1 + l, str, estr - str);
strcpy(newstr + 1 + l + (estr - str), ecomm);
strncpy(newstr + 1 + l, str, b);
strncpy(newstr + 1 + l + b, ecomm, e);
rc = logbuf->log(LOG_ID_MAIN, now, uid, pid, tid, newstr,
(n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX);
free(newstr);
if (rc >= 0) {
notify = true;
}
// end scope for main buffer
}
free(commfree);

View file

@ -91,7 +91,8 @@ char *android::tidToName(pid_t tid) {
size_t retval_len = strlen(retval);
size_t name_len = strlen(name);
// KISS: ToDo: Only checks prefix truncated, not suffix, or both
if ((retval_len < name_len) && !strcmp(retval, name + name_len - retval_len)) {
if ((retval_len < name_len)
&& !fast<strcmp>(retval, name + name_len - retval_len)) {
free(retval);
retval = name;
} else {
@ -123,14 +124,16 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
commName = parent->pidToName(mPid);
parent->unlock();
}
size_t len = name ? strlen(name) : 0;
if (len && commName && !strncmp(name, commName, len)) {
if (commName[len] == '\0') {
free(commName);
commName = NULL;
} else {
free(name);
name = NULL;
if (name && name[0] && commName && (name[0] == commName[0])) {
size_t len = strlen(name + 1);
if (!strncmp(name + 1, commName + 1, len)) {
if (commName[len + 1] == '\0') {
free(commName);
commName = NULL;
} else {
free(name);
name = NULL;
}
}
}
if (name) {
@ -150,9 +153,9 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
}
}
// identical to below to calculate the buffer size required
len = snprintf(NULL, 0, format_uid, mUid, name ? name : "",
commName ? commName : "",
mDropped, (mDropped > 1) ? "s" : "");
size_t len = snprintf(NULL, 0, format_uid, mUid, name ? name : "",
commName ? commName : "",
mDropped, (mDropped > 1) ? "s" : "");
size_t hdrLen;
if (mLogId == LOG_ID_EVENTS) {

View file

@ -64,7 +64,7 @@ public:
unsigned short getDropped(void) const { return mMsg ? 0 : mDropped; }
unsigned short setDropped(unsigned short value) {
if (mMsg) {
free(mMsg);
delete [] mMsg;
mMsg = NULL;
}
return mDropped = value;

View file

@ -306,7 +306,7 @@ static const char *strnstr(const char *s, size_t len, const char *needle) {
}
--len;
} while (*s++ != c);
} while (memcmp(s, needle, needleLen) != 0);
} while (fast<memcmp>(s, needle, needleLen));
s--;
}
return s;
@ -588,7 +588,7 @@ int LogKlog::log(const char *buf, size_t len) {
const char *bt, *et, *cp;
bt = p;
if (!strncmp(p, "[INFO]", 6)) {
if (!fast<strncmp>(p, "[INFO]", 6)) {
// <PRI>[<TIME>] "[INFO]"<tag> ":" message
bt = p + 6;
taglen -= 6;
@ -612,10 +612,10 @@ int LogKlog::log(const char *buf, size_t len) {
p = cp + 1;
} else if (taglen) {
size = et - bt;
if (strncmp(bt, cp, size)) {
if ((*bt == *cp) && fast<strncmp>(bt + 1, cp + 1, size - 1)) {
// <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
if (!strncmp(bt + size - 5, "_host", 5)
&& !strncmp(bt, cp, size - 5)) {
if (!fast<strncmp>(bt + size - 5, "_host", 5)
&& !fast<strncmp>(bt + 1, cp + 1, size - 6)) {
const char *b = cp;
cp += size - 5;
taglen -= size - 5;
@ -694,10 +694,10 @@ int LogKlog::log(const char *buf, size_t len) {
// register names like x18 but not driver names like en0
|| ((size == 3) && (isdigit(tag[1]) && isdigit(tag[2])))
// blacklist
|| ((size == 3) && !strncmp(tag, "CPU", 3))
|| ((size == 7) && !strncasecmp(tag, "WARNING", 7))
|| ((size == 5) && !strncasecmp(tag, "ERROR", 5))
|| ((size == 4) && !strncasecmp(tag, "INFO", 4))) {
|| ((size == 3) && !fast<strncmp>(tag, "CPU", 3))
|| ((size == 7) && !fast<strncasecmp>(tag, "WARNING", 7))
|| ((size == 5) && !fast<strncasecmp>(tag, "ERROR", 5))
|| ((size == 4) && !fast<strncasecmp>(tag, "INFO", 4))) {
p = start;
etag = tag = "";
}
@ -709,7 +709,7 @@ int LogKlog::log(const char *buf, size_t len) {
const char *mp = strnrchr(tag, ']', taglen);
if (mp && (++mp < etag)) {
size_t s = etag - mp;
if (((s + s) < taglen) && !memcmp(mp, mp - 1 - s, s)) {
if (((s + s) < taglen) && !fast<memcmp>(mp, mp - 1 - s, s)) {
taglen = mp - tag;
}
}
@ -727,6 +727,9 @@ int LogKlog::log(const char *buf, size_t len) {
p = " ";
b = 1;
}
if (b > LOGGER_ENTRY_MAX_PAYLOAD) {
b = LOGGER_ENTRY_MAX_PAYLOAD;
}
size_t n = 1 + taglen + 1 + b + 1;
int rc = n;
if ((taglen > n) || (b > n)) { // Can not happen ...
@ -734,12 +737,7 @@ int LogKlog::log(const char *buf, size_t len) {
return rc;
}
// Allocate a buffer to hold the interpreted log message
char *newstr = reinterpret_cast<char *>(malloc(n));
if (!newstr) {
rc = -ENOMEM;
return rc;
}
char newstr[n];
char *np = newstr;
// Convert priority into single-byte Android logger priority
@ -759,7 +757,6 @@ int LogKlog::log(const char *buf, size_t len) {
// Log message
rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr,
(n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX);
free(newstr);
// notify readers
if (!rc) {

View file

@ -95,7 +95,7 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
}
bool nonBlock = false;
if (strncmp(buffer, "dumpAndClose", 12) == 0) {
if (!fast<strncmp>(buffer, "dumpAndClose", 12)) {
// Allow writer to get some cycles, and wait for pending notifications
sched_yield();
LogTimeEntry::lock();

View file

@ -51,7 +51,7 @@ char *pidToName(pid_t pid) {
if (ret > 0) {
buffer[sizeof(buffer)-1] = '\0';
// frameworks intermediate state
if (strcmp(buffer, "<pre-initialized>")) {
if (fast<strcmp>(buffer, "<pre-initialized>")) {
retval = strdup(buffer);
}
}
@ -170,7 +170,7 @@ char *LogStatistics::uidToName(uid_t uid) {
if (n) {
if (!name) {
name = strdup(n);
} else if (strcmp(name, n)) {
} else if (fast<strcmp>(name, n)) {
free(name);
name = NULL;
break;

View file

@ -189,7 +189,7 @@ struct PidEntry : public EntryBaseDropped {
const char*getName() const { return name; }
inline void add(pid_t p) {
if (name && !strncmp(name, "zygote", 6)) {
if (name && !fast<strncmp>(name, "zygote", 6)) {
free(name);
name = NULL;
}
@ -241,7 +241,7 @@ struct TidEntry : public EntryBaseDropped {
const char*getName() const { return name; }
inline void add(pid_t t) {
if (name && !strncmp(name, "zygote", 6)) {
if (name && !fast<strncmp>(name, "zygote", 6)) {
free(name);
name = NULL;
}

View file

@ -42,4 +42,21 @@ static inline bool worstUidEnabledForLogid(log_id_t id) {
return (id != LOG_ID_CRASH) && (id != LOG_ID_KERNEL) && (id != LOG_ID_EVENTS);
}
template <int (*cmp)(const char *l, const char *r, const size_t s)>
static inline int fast(const char *l, const char *r, const size_t s) {
return (*l != *r) || cmp(l + 1, r + 1, s - 1);
}
template <int (*cmp)(const void *l, const void *r, const size_t s)>
static inline int fast(const void *lv, const void *rv, const size_t s) {
const char *l = static_cast<const char *>(lv);
const char *r = static_cast<const char *>(rv);
return (*l != *r) || cmp(l + 1, r + 1, s - 1);
}
template <int (*cmp)(const char *l, const char *r)>
static inline int fast(const char *l, const char *r) {
return (*l != *r) || cmp(l + 1, r + 1);
}
#endif // _LOGD_LOG_UTILS_H__