logd: prune maintain per-id watermark

Without this change LogBuffer::prune and LogBuffer::erase
contributes 16.7% and 1.79% respectively. With this change,
they contributes 3.06 and 2.33% respectively. Pruning is
performed roughly 1 in every 255 log entries, a periodic
tamer latency spike.

Bug: 23685592
Change-Id: I6ae1cf9f3559bca4cf448efe8bcb2b96a1914c54

2 files changed, 39 insertions, 4 deletions

diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 707527b4e..cdf5d08fb 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -109,6 +109,9 @@ void LogBuffer::init() {
     }
 
     log_id_for_each(i) {
+        mLastSet[i] = false;
+        mLast[i] = mLogElements.begin();
+
         char key[PROP_NAME_MAX];
 
         snprintf(key, sizeof(key), "%s.%s",
@@ -329,7 +332,15 @@ LogBufferElementCollection::iterator LogBuffer::erase(
         }
     }
 
+    bool setLast = mLastSet[id] && (it == mLast[id]);
     it = mLogElements.erase(it);
+    if (setLast) {
+        if (it == mLogElements.end()) { // unlikely
+            mLastSet[id] = false;
+        } else {
+            mLast[id] = it;
+        }
+    }
     if (coalesce) {
         stats.erase(element);
     } else {
@@ -490,7 +501,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
 
     if (caller_uid != AID_ROOT) {
         // Only here if clearAll condition (pruneRows == ULONG_MAX)
-        for(it = mLogElements.begin(); it != mLogElements.end();) {
+        it = mLastSet[id] ? mLast[id] : mLogElements.begin();
+        while (it != mLogElements.end()) {
             LogBufferElement *element = *it;
 
             if ((element->getLogId() != id) || (element->getUid() != caller_uid)) {
@@ -498,6 +510,11 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 continue;
             }
 
+            if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
+                mLast[id] = it;
+                mLastSet[id] = true;
+            }
+
             if (oldest && (oldest->mStart <= element->getSequence())) {
                 busy = true;
                 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
@@ -566,7 +583,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
 
         bool kick = false;
         bool leading = true;
-        it = mLogElements.begin();
+        it = mLastSet[id] ? mLast[id] : mLogElements.begin();
         // Perform at least one mandatory garbage collection cycle in following
         // - clear leading chatty tags
         // - coalesce chatty tags
@@ -615,6 +632,11 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 continue;
             }
 
+            if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) {
+                mLast[id] = it;
+                mLastSet[id] = true;
+            }
+
             unsigned short dropped = element->getDropped();
 
             // remove any leading drops
@@ -725,7 +747,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
 
     bool whitelist = false;
     bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll;
-    it = mLogElements.begin();
+    it = mLastSet[id] ? mLast[id] : mLogElements.begin();
     while((pruneRows > 0) && (it != mLogElements.end())) {
         LogBufferElement *element = *it;
 
@@ -734,6 +756,11 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
             continue;
         }
 
+        if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
+            mLast[id] = it;
+            mLastSet[id] = true;
+        }
+
         if (oldest && (oldest->mStart <= element->getSequence())) {
             busy = true;
             if (whitelist) {
@@ -764,7 +791,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
 
     // Do not save the whitelist if we are reader range limited
     if (whitelist && (pruneRows > 0)) {
-        it = mLogElements.begin();
+        it = mLastSet[id] ? mLast[id] : mLogElements.begin();
         while((it != mLogElements.end()) && (pruneRows > 0)) {
             LogBufferElement *element = *it;
 
@@ -773,6 +800,11 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 continue;
             }
 
+            if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
+                mLast[id] = it;
+                mLastSet[id] = true;
+            }
+
             if (oldest && (oldest->mStart <= element->getSequence())) {
                 busy = true;
                 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 2667e7828..03739c7eb 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -82,6 +82,9 @@ class LogBuffer {
     LogStatistics stats;
 
     PruneList mPrune;
+    // watermark for last per log id
+    LogBufferElementCollection::iterator mLast[LOG_ID_MAX];
+    bool mLastSet[LOG_ID_MAX];
     // watermark of any worst/chatty uid processing
     typedef std::unordered_map<uid_t,
                                LogBufferElementCollection::iterator>