commit a354d42ec18f59a466b7ac57e456b1860e9e4f85
author Mark Salyzyn <salyzyn@google.com> Mon Apr 17 12:46:12 2017 -0700
committer Mark Salyzyn <salyzyn@google.com> Mon Apr 17 15:10:26 2017 -0700
tree 7be54b7c88ae710287b03c5875355bfd13e48c07
parent 7c94219422320348fa333e814d5e7c6cec3fa8c6

logd: regression in handling watermark boundary.

Deal with a regression introduced in commit
da1b4a18bbb3867ff71ff2b998b7d579e3ab2462 (logd: drop mSequence from
LogBufferElement) where log_time was compared against nsec() time
miscalculating the watermark boundary.  When dealing with logcat
-t/-T, or any tail reading, add a margin to prune to back off by a
period of 3 seconds (pruneMargin).

Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests
Bug: 37378309
Change-Id: I72ea858e4e7b5fa91741ea84c40d2e7c3c4aa031

logd/LogBuffer.cpp

diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 0c7019a..4a790c9 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -43,6 +43,8 @@
 // Default
 #define log_buffer_size(id) mMaxSize[id]
 
+const log_time LogBuffer::pruneMargin(3, 0);
+
 void LogBuffer::init() {
     log_id_for_each(i) {
         mLastSet[i] = false;
@@ -672,6 +674,8 @@
         }
         times++;
     }
+    log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max);
+    if (oldest) watermark = oldest->mStart - pruneMargin;
 
     LogBufferElementCollection::iterator it;
 
@@ -693,7 +697,7 @@
                 mLastSet[id] = true;
             }
 
-            if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
+            if (oldest && (watermark <= element->getRealTime())) {
                 busy = true;
                 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
                     oldest->triggerReader_Locked();
@@ -785,7 +789,7 @@
         while (it != mLogElements.end()) {
             LogBufferElement* element = *it;
 
-            if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
+            if (oldest && (watermark <= element->getRealTime())) {
                 busy = true;
                 if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
                     oldest->triggerReader_Locked();
@@ -939,7 +943,7 @@
             mLastSet[id] = true;
         }
 
-        if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
+        if (oldest && (watermark <= element->getRealTime())) {
             busy = true;
             if (whitelist) {
                 break;
@@ -983,7 +987,7 @@
                 mLastSet[id] = true;
             }
 
-            if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
+            if (oldest && (watermark <= element->getRealTime())) {
                 busy = true;
                 if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                     // kick a misbehaving log reader client off the island
@@ -1090,13 +1094,15 @@
         // client wants to start from the beginning
         it = mLogElements.begin();
     } else {
-        LogBufferElementCollection::iterator last;
         // 3 second limit to continue search for out-of-order entries.
-        log_time min = start - log_time(3, 0);
+        log_time min = start - pruneMargin;
+
         // Cap to 300 iterations we look back for out-of-order entries.
         size_t count = 300;
+
         // Client wants to start from some specified time. Chances are
         // we are better off starting from the end of the time sorted list.
+        LogBufferElementCollection::iterator last;
         for (last = it = mLogElements.end(); it != mLogElements.begin();
              /* do nothing */) {
             --it;