commit da6495d06f1798ea81cebbfbdd44f16135e1a3cd
author TraianX Schiau <traianx.schiau@intel.com> Wed Dec 17 10:53:41 2014 +0200
committer Mark Salyzyn <salyzyn@google.com> Wed Jan 14 19:12:47 2015 +0000
tree fe2b7bf4d3f15d06da42731645b8fe7115084b5b
parent da3dec3c19d1489f5997aea9dafd34b68c2b515b

logd: Fix pruning

In a scenario in which an on-line (blocking) client is running and
a clean is attempted (logcat -c), the following can be observed:

1) the on-line logger seems to freeze
2) any other clear attempt will have no effect

What is actually happening:

In this case prune function will "instruct" the oldest timeEntry
to skip a huge number (very close to ULONG_MAX) of messages, this
being the cause of 1.

Since the consumer thread will skip all the log entries, mStart
updating will also be skipped. So a new cleaning attempt will have
the same oldest entry, nothing will be done.

Fix description:
a. keep a separated skipAhead count for individual log buffers (log_id_t)
      LogTimeEntry::LogTimeEntry
      LogTimeEntry::FilterSecondPass
      LogTimeEntry::skipAhead
      LogTimeEntry::riggerSkip_Locked

b. update LogTimeEntry::mStart even if the current message is skipped
      LogTimeEntry::FilterSecondPass

c. while pruning, only take into account the LogTimeEntrys that are monitoring
   the log_id in question, and provide a public method of checking this.
      LogTimeEntry::isWatching
      LogTimeEntry::FilterFirstPass
      LogTimeEntry::FilterSecondPass

d. Reset the skip cont befor the client thtread starts to sleep, at this point
   we should be up to date.
      LogTimeEntry::cleanSkip_Locked
      LogTimeEntry::threadStart

Change-Id: I1b369dc5b02476e633e52578266a644e37e188a5
Signed-off-by: TraianX Schiau <traianx.schiau@intel.com>

logd/LogTimes.cpp

diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
index ea4e8c8..5f9db8d 100644
--- a/logd/LogTimes.cpp
+++ b/logd/LogTimes.cpp
@@ -36,7 +36,6 @@
         , mReader(reader)
         , mLogMask(logMask)
         , mPid(pid)
-        , skipAhead(0)
         , mCount(0)
         , mTail(tail)
         , mIndex(0)
@@ -46,6 +45,7 @@
         , mEnd(CLOCK_MONOTONIC)
 {
         pthread_cond_init(&threadTriggeredCondition, NULL);
+        cleanSkip_Locked();
 }
 
 void LogTimeEntry::startReader_Locked(void) {
@@ -148,6 +148,8 @@
             break;
         }
 
+        me->cleanSkip_Locked();
+
         pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
     }
 
@@ -169,7 +171,7 @@
     }
 
     if ((!me->mPid || (me->mPid == element->getPid()))
-            && (me->mLogMask & (1 << element->getLogId()))) {
+            && (me->isWatching(element->getLogId()))) {
         ++me->mCount;
     }
 
@@ -184,19 +186,19 @@
 
     LogTimeEntry::lock();
 
-    if (me->skipAhead) {
-        me->skipAhead--;
+    me->mStart = element->getMonotonicTime();
+
+    if (me->skipAhead[element->getLogId()]) {
+        me->skipAhead[element->getLogId()]--;
         goto skip;
     }
 
-    me->mStart = element->getMonotonicTime();
-
     // Truncate to close race between first and second pass
     if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) {
         goto skip;
     }
 
-    if ((me->mLogMask & (1 << element->getLogId())) == 0) {
+    if (!me->isWatching(element->getLogId())) {
         goto skip;
     }
 
@@ -223,7 +225,7 @@
     }
 
 ok:
-    if (!me->skipAhead) {
+    if (!me->skipAhead[element->getLogId()]) {
         LogTimeEntry::unlock();
         return true;
     }
@@ -233,3 +235,9 @@
     LogTimeEntry::unlock();
     return false;
 }
+
+void LogTimeEntry::cleanSkip_Locked(void) {
+    for (log_id_t i = LOG_ID_MIN; i < LOG_ID_MAX; i = (log_id_t) (i + 1)) {
+        skipAhead[i] = 0;
+    }
+}