From c1e9d6dada4fe20c0537c13cf3ff5a010d208ba1 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 4 Jun 2015 13:35:30 -0700 Subject: [PATCH] logd: filters remove leading expire messages and rate (cherry pick from commit 047cc0729fd837a03b99db901941c1421ef15f96) - Cleanup resulting from experience and feedback - When filtering inside logd, drop any leading expire messages, they are cluttering up leading edge of tombstones (which filter by pid) - Increase and introduce EXPIRE_RATELIMIT from 1 to 10 seconds - Increase EXPIRE_THRESHOLD from 4 to 10 count - Improve the expire messages from: logd : uid=1000(system) too chatty comm=com.google.android.phone, expire 2800 lines change tag to be more descriptive, and reduce accusatory tone to: chatty : uid=1000(system) com.google.android.phone expire 2800 lines - if the UID name forms a prefix for comm name, then drop UID name Change-Id: Ied7cc04c0ab3ae02167649a0b97378e44ef7b588 --- logd/LogBuffer.cpp | 3 ++- logd/LogBufferElement.cpp | 24 +++++++++++++++--------- logd/LogBufferElement.h | 3 ++- logd/LogTimes.cpp | 19 +++++++++++++++++++ logd/LogTimes.h | 1 + 5 files changed, 39 insertions(+), 11 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 80fc9f593..4373e2a9d 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -281,7 +281,8 @@ public: } void clear(LogBufferElement *e) { - uint64_t current = e->getRealTime().nsec() - NS_PER_SEC; + uint64_t current = e->getRealTime().nsec() + - (EXPIRE_RATELIMIT * NS_PER_SEC); for(LogBufferElementMap::iterator it = map.begin(); it != map.end();) { LogBufferElement *l = it->second; if ((l->getDropped() >= EXPIRE_THRESHOLD) diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index 3d7237e24..8238a5222 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -104,8 +104,8 @@ char *android::tidToName(pid_t tid) { // assumption: mMsg == NULL size_t LogBufferElement::populateDroppedMessage(char *&buffer, LogBuffer *parent) { - static const char tag[] = "logd"; - static const char format_uid[] = "uid=%u%s too chatty%s, expire %u line%s"; + static const char tag[] = "chatty"; + static const char format_uid[] = "uid=%u%s%s expire %u line%s"; char *name = parent->uidToName(mUid); char *commName = android::tidToName(mTid); @@ -115,9 +115,15 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, if (!commName) { commName = parent->pidToName(mPid); } - if (name && commName && !strcmp(name, commName)) { - free(commName); - commName = NULL; + 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) { char *p = NULL; @@ -129,16 +135,16 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, } if (commName) { char *p = NULL; - asprintf(&p, " comm=%s", commName); + asprintf(&p, " %s", commName); if (p) { free(commName); commName = p; } } // identical to below to calculate the buffer size required - size_t len = snprintf(NULL, 0, format_uid, mUid, name ? name : "", - commName ? commName : "", - mDropped, (mDropped > 1) ? "s" : ""); + len = snprintf(NULL, 0, format_uid, mUid, name ? name : "", + commName ? commName : "", + mDropped, (mDropped > 1) ? "s" : ""); size_t hdrLen; if (mLogId == LOG_ID_EVENTS) { diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 3dcf9d1e2..ca2c3a62c 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -50,8 +50,9 @@ class LogBuffer; #define EXPIRE_HOUR_THRESHOLD 24 // Only expire chatty UID logs to preserve // non-chatty UIDs less than this age in hours -#define EXPIRE_THRESHOLD 4 // A smaller expire count is considered too +#define EXPIRE_THRESHOLD 10 // A smaller expire count is considered too // chatty for the temporal expire messages +#define EXPIRE_RATELIMIT 10 // maximum rate in seconds to report expiration class LogBufferElement { const log_id_t mLogId; diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index ec67c07e8..68a068008 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -31,6 +31,7 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, mRelease(false), mError(false), threadRunning(false), + leadingDropped(false), mReader(reader), mLogMask(logMask), mPid(pid), @@ -123,6 +124,8 @@ void *LogTimeEntry::threadStart(void *obj) { bool privileged = FlushCommand::hasReadLogs(client); + me->leadingDropped = true; + lock(); while (me->threadRunning && !me->isError_Locked()) { @@ -132,6 +135,7 @@ void *LogTimeEntry::threadStart(void *obj) { if (me->mTail) { logbuf.flushTo(client, start, privileged, FilterFirstPass, me); + me->leadingDropped = true; } start = logbuf.flushTo(client, start, privileged, FilterSecondPass, me); @@ -163,6 +167,14 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { LogTimeEntry::lock(); + if (me->leadingDropped) { + if (element->getDropped()) { + LogTimeEntry::unlock(); + return false; + } + me->leadingDropped = false; + } + if (me->mCount == 0) { me->mStart = element->getSequence(); } @@ -190,6 +202,13 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) { goto skip; } + if (me->leadingDropped) { + if (element->getDropped()) { + goto skip; + } + me->leadingDropped = false; + } + // Truncate to close race between first and second pass if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) { goto stop; diff --git a/logd/LogTimes.h b/logd/LogTimes.h index ae2f92b34..783bce675 100644 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -32,6 +32,7 @@ class LogTimeEntry { bool mRelease; bool mError; bool threadRunning; + bool leadingDropped; pthread_cond_t threadTriggeredCondition; pthread_t mThread; LogReader &mReader;