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

5 files changed, 39 insertions, 11 deletions

diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 80fc9f5..4373e2a 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 3d7237e..8238a52 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 3dcf9d1..ca2c3a6 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 ec67c07..68a0680 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 ae2f92b..783bce6 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;