logd: replace internal CLOCK_MONOTONIC use with sequence numbers

- switch to simpler and faster internal sequence number, drops
  a syscall overhead on 32-bit platforms.
- add ability to break-out of flushTo loop with filter return -1
  allowing in reduction in reader overhead.

Change-Id: Ic5cb2b9afa4d9470153971fc9197b07279e2b79d

9 files changed, 77 insertions, 66 deletions

diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp
index 3be07c0..26a1861 100644
--- a/logd/FlushCommand.cpp
+++ b/logd/FlushCommand.cpp
@@ -27,7 +27,7 @@ FlushCommand::FlushCommand(LogReader &reader,
                            unsigned long tail,
                            unsigned int logMask,
                            pid_t pid,
-                           log_time start)
+                           uint64_t start)
         : mReader(reader)
         , mNonBlock(nonBlock)
         , mTail(tail)
diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h
index f34c06a..61c6858 100644
--- a/logd/FlushCommand.h
+++ b/logd/FlushCommand.h
@@ -31,7 +31,7 @@ class FlushCommand : public SocketClientCommand {
     unsigned long mTail;
     unsigned int mLogMask;
     pid_t mPid;
-    log_time mStart;
+    uint64_t mStart;
 
 public:
     FlushCommand(LogReader &mReader,
@@ -39,7 +39,7 @@ public:
                  unsigned long tail = -1,
                  unsigned int logMask = -1,
                  pid_t pid = 0,
-                 log_time start = LogTimeEntry::EPOCH);
+                 uint64_t start = 1);
     virtual void runSocketCommand(SocketClient *client);
 
     static bool hasReadLogs(SocketClient *client);
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 2b495ab..2693583 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -161,7 +161,7 @@ void LogBuffer::log(log_id_t log_id, log_time realtime,
     if (last == mLogElements.end()) {
         mLogElements.push_back(elem);
     } else {
-        log_time end = log_time::EPOCH;
+        uint64_t end = 1;
         bool end_set = false;
         bool end_always = false;
 
@@ -184,7 +184,7 @@ void LogBuffer::log(log_id_t log_id, log_time realtime,
         }
 
         if (end_always
-                || (end_set && (end >= (*last)->getMonotonicTime()))) {
+                || (end_set && (end >= (*last)->getSequence()))) {
             mLogElements.push_back(elem);
         } else {
             mLogElements.insert(last,elem);
@@ -241,7 +241,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         for(it = mLogElements.begin(); it != mLogElements.end();) {
             LogBufferElement *e = *it;
 
-            if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+            if (oldest && (oldest->mStart <= e->getSequence())) {
                 break;
             }
 
@@ -293,7 +293,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         for(it = mLogElements.begin(); it != mLogElements.end();) {
             LogBufferElement *e = *it;
 
-            if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+            if (oldest && (oldest->mStart <= e->getSequence())) {
                 break;
             }
 
@@ -334,7 +334,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
     while((pruneRows > 0) && (it != mLogElements.end())) {
         LogBufferElement *e = *it;
         if (e->getLogId() == id) {
-            if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+            if (oldest && (oldest->mStart <= e->getSequence())) {
                 if (!whitelist) {
                     if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                         // kick a misbehaving log reader client off the island
@@ -366,7 +366,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         while((it != mLogElements.end()) && (pruneRows > 0)) {
             LogBufferElement *e = *it;
             if (e->getLogId() == id) {
-                if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+                if (oldest && (oldest->mStart <= e->getSequence())) {
                     if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                         // kick a misbehaving log reader client off the island
                         oldest->release_Locked();
@@ -423,16 +423,16 @@ unsigned long LogBuffer::getSize(log_id_t id) {
     return retval;
 }
 
-log_time LogBuffer::flushTo(
-        SocketClient *reader, const log_time start, bool privileged,
-        bool (*filter)(const LogBufferElement *element, void *arg), void *arg) {
+uint64_t LogBuffer::flushTo(
+        SocketClient *reader, const uint64_t start, bool privileged,
+        int (*filter)(const LogBufferElement *element, void *arg), void *arg) {
     LogBufferElementCollection::iterator it;
-    log_time max = start;
+    uint64_t max = start;
     uid_t uid = reader->getUid();
 
     pthread_mutex_lock(&mLogElementsLock);
 
-    if (start == LogTimeEntry::EPOCH) {
+    if (start <= 1) {
         // client wants to start from the beginning
         it = mLogElements.begin();
     } else {
@@ -441,7 +441,7 @@ log_time LogBuffer::flushTo(
         for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) {
             --it;
             LogBufferElement *element = *it;
-            if (element->getMonotonicTime() <= start) {
+            if (element->getSequence() <= start) {
                 it++;
                 break;
             }
@@ -455,13 +455,19 @@ log_time LogBuffer::flushTo(
             continue;
         }
 
-        if (element->getMonotonicTime() <= start) {
+        if (element->getSequence() <= start) {
             continue;
         }
 
         // NB: calling out to another object with mLogElementsLock held (safe)
-        if (filter && !(*filter)(element, arg)) {
-            continue;
+        if (filter) {
+            int ret = (*filter)(element, arg);
+            if (ret == false) {
+                continue;
+            }
+            if (ret != true) {
+                break;
+            }
         }
 
         pthread_mutex_unlock(&mLogElementsLock);
@@ -481,7 +487,7 @@ log_time LogBuffer::flushTo(
 }
 
 void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
-    log_time oldest(CLOCK_MONOTONIC);
+    uint64_t oldest = UINT64_MAX;
 
     pthread_mutex_lock(&mLogElementsLock);
 
@@ -491,7 +497,7 @@ void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
         LogBufferElement *element = *it;
 
         if ((logMask & (1 << element->getLogId()))) {
-            oldest = element->getMonotonicTime();
+            oldest = element->getSequence();
             break;
         }
     }
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 86a2a2a..13e6aa8 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -51,9 +51,9 @@ public:
     void log(log_id_t log_id, log_time realtime,
              uid_t uid, pid_t pid, pid_t tid,
              const char *msg, unsigned short len);
-    log_time flushTo(SocketClient *writer, const log_time start,
+    uint64_t flushTo(SocketClient *writer, const uint64_t start,
                      bool privileged,
-                     bool (*filter)(const LogBufferElement *element, void *arg) = NULL,
+                     int (*filter)(const LogBufferElement *element, void *arg) = NULL,
                      void *arg = NULL);
 
     void clear(log_id_t id, uid_t uid = AID_ROOT);
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index d959ceb..5e780b5 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -24,7 +24,8 @@
 #include "LogBufferElement.h"
 #include "LogReader.h"
 
-const log_time LogBufferElement::FLUSH_ERROR((uint32_t)0, (uint32_t)0);
+const uint64_t LogBufferElement::FLUSH_ERROR(0);
+atomic_int_fast64_t LogBufferElement::sequence;
 
 LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
                                    uid_t uid, pid_t pid, pid_t tid,
@@ -34,7 +35,7 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
         , mPid(pid)
         , mTid(tid)
         , mMsgLen(len)
-        , mMonotonicTime(CLOCK_MONOTONIC)
+        , mSequence(sequence.fetch_add(1, memory_order_relaxed))
         , mRealTime(realtime) {
     mMsg = new char[len];
     memcpy(mMsg, msg, len);
@@ -44,7 +45,7 @@ LogBufferElement::~LogBufferElement() {
     delete [] mMsg;
 }
 
-log_time LogBufferElement::flushTo(SocketClient *reader) {
+uint64_t LogBufferElement::flushTo(SocketClient *reader) {
     struct logger_entry_v3 entry;
     memset(&entry, 0, sizeof(struct logger_entry_v3));
     entry.hdr_size = sizeof(struct logger_entry_v3);
@@ -64,5 +65,5 @@ log_time LogBufferElement::flushTo(SocketClient *reader) {
         return FLUSH_ERROR;
     }
 
-    return mMonotonicTime;
+    return mSequence;
 }
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index fdca973..25f1450 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -18,6 +18,7 @@
 #define _LOGD_LOG_BUFFER_ELEMENT_H__
 
 #include <sys/types.h>
+#include <stdatomic.h>
 #include <sysutils/SocketClient.h>
 #include <log/log.h>
 #include <log/log_read.h>
@@ -29,8 +30,9 @@ class LogBufferElement {
     const pid_t mTid;
     char *mMsg;
     const unsigned short mMsgLen;
-    const log_time mMonotonicTime;
+    const uint64_t mSequence;
     const log_time mRealTime;
+    static atomic_int_fast64_t sequence;
 
 public:
     LogBufferElement(log_id_t log_id, log_time realtime,
@@ -43,11 +45,12 @@ public:
     pid_t getPid(void) const { return mPid; }
     pid_t getTid(void) const { return mTid; }
     unsigned short getMsgLen() const { return mMsgLen; }
-    log_time getMonotonicTime(void) const { return mMonotonicTime; }
+    uint64_t getSequence(void) const { return mSequence; }
+    static uint64_t getCurrentSequence(void) { return sequence.load(memory_order_relaxed); }
     log_time getRealTime(void) const { return mRealTime; }
 
-    static const log_time FLUSH_ERROR;
-    log_time flushTo(SocketClient *writer);
+    static const uint64_t FLUSH_ERROR;
+    uint64_t flushTo(SocketClient *writer);
 };
 
 #endif
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 26df087..f7df275 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -100,50 +100,51 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
         nonBlock = true;
     }
 
-    // Convert realtime to monotonic time
-    if (start == log_time::EPOCH) {
-        start = LogTimeEntry::EPOCH;
-    } else {
+    uint64_t sequence = 1;
+    // Convert realtime to sequence number
+    if (start != log_time::EPOCH) {
         class LogFindStart {
             const pid_t mPid;
             const unsigned mLogMask;
             bool startTimeSet;
             log_time &start;
-            log_time last;
+            uint64_t &sequence;
+            uint64_t last;
 
         public:
-            LogFindStart(unsigned logMask, pid_t pid, log_time &start)
+            LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence)
                     : mPid(pid)
                     , mLogMask(logMask)
                     , startTimeSet(false)
                     , start(start)
-                    , last(LogTimeEntry::EPOCH)
+                    , sequence(sequence)
+                    , last(sequence)
             { }
 
-            static bool callback(const LogBufferElement *element, void *obj) {
+            static int callback(const LogBufferElement *element, void *obj) {
                 LogFindStart *me = reinterpret_cast<LogFindStart *>(obj);
-                if (!me->startTimeSet
-                        && (!me->mPid || (me->mPid == element->getPid()))
+                if ((!me->mPid || (me->mPid == element->getPid()))
                         && (me->mLogMask & (1 << element->getLogId()))) {
                     if (me->start == element->getRealTime()) {
-                        me->start = element->getMonotonicTime();
+                        me->sequence = element->getSequence();
                         me->startTimeSet = true;
+                        return -1;
                     } else {
                         if (me->start < element->getRealTime()) {
-                            me->start = me->last;
+                            me->sequence = me->last;
                             me->startTimeSet = true;
+                            return -1;
                         }
-                        me->last = element->getMonotonicTime();
+                        me->last = element->getSequence();
                     }
                 }
                 return false;
             }
 
             bool found() { return startTimeSet; }
-        } logFindStart(logMask, pid, start);
+        } logFindStart(logMask, pid, start, sequence);
 
-        logbuf().flushTo(cli, LogTimeEntry::EPOCH,
-                         FlushCommand::hasReadLogs(cli),
+        logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli),
                          logFindStart.callback, &logFindStart);
 
         if (!logFindStart.found()) {
@@ -151,12 +152,11 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
                 doSocketDelete(cli);
                 return false;
             }
-            log_time now(CLOCK_MONOTONIC);
-            start = now;
+            sequence = LogBufferElement::getCurrentSequence();
         }
     }
 
-    FlushCommand command(*this, nonBlock, tail, logMask, pid, start);
+    FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence);
     command.runSocketCommand(cli);
     return true;
 }
diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
index 5f9db8d..1b60b7e 100644
--- a/logd/LogTimes.cpp
+++ b/logd/LogTimes.cpp
@@ -23,12 +23,10 @@
 
 pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
 
-const struct timespec LogTimeEntry::EPOCH = { 0, 1 };
-
 LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
                            bool nonBlock, unsigned long tail,
                            unsigned int logMask, pid_t pid,
-                           log_time start)
+                           uint64_t start)
         : mRefCount(1)
         , mRelease(false)
         , mError(false)
@@ -42,7 +40,7 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
         , mClient(client)
         , mStart(start)
         , mNonBlock(nonBlock)
-        , mEnd(CLOCK_MONOTONIC)
+        , mEnd(LogBufferElement::getCurrentSequence())
 {
         pthread_cond_init(&threadTriggeredCondition, NULL);
         cleanSkip_Locked();
@@ -129,7 +127,7 @@ void *LogTimeEntry::threadStart(void *obj) {
     lock();
 
     while (me->threadRunning && !me->isError_Locked()) {
-        log_time start = me->mStart;
+        uint64_t start = me->mStart;
 
         unlock();
 
@@ -161,13 +159,13 @@ void *LogTimeEntry::threadStart(void *obj) {
 }
 
 // A first pass to count the number of elements
-bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) {
+int LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) {
     LogTimeEntry *me = reinterpret_cast<LogTimeEntry *>(obj);
 
     LogTimeEntry::lock();
 
     if (me->mCount == 0) {
-        me->mStart = element->getMonotonicTime();
+        me->mStart = element->getSequence();
     }
 
     if ((!me->mPid || (me->mPid == element->getPid()))
@@ -181,12 +179,12 @@ bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) {
 }
 
 // A second pass to send the selected elements
-bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) {
+int LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) {
     LogTimeEntry *me = reinterpret_cast<LogTimeEntry *>(obj);
 
     LogTimeEntry::lock();
 
-    me->mStart = element->getMonotonicTime();
+    me->mStart = element->getSequence();
 
     if (me->skipAhead[element->getLogId()]) {
         me->skipAhead[element->getLogId()]--;
@@ -195,7 +193,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj)
 
     // Truncate to close race between first and second pass
     if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) {
-        goto skip;
+        goto stop;
     }
 
     if (!me->isWatching(element->getLogId())) {
@@ -207,7 +205,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj)
     }
 
     if (me->isError_Locked()) {
-        goto skip;
+        goto stop;
     }
 
     if (!me->mTail) {
@@ -234,6 +232,10 @@ ok:
 skip:
     LogTimeEntry::unlock();
     return false;
+
+stop:
+    LogTimeEntry::unlock();
+    return -1;
 }
 
 void LogTimeEntry::cleanSkip_Locked(void) {
diff --git a/logd/LogTimes.h b/logd/LogTimes.h
index 81aedfb..ae2f92b 100644
--- a/logd/LogTimes.h
+++ b/logd/LogTimes.h
@@ -47,13 +47,12 @@ class LogTimeEntry {
 public:
     LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock,
                  unsigned long tail, unsigned int logMask, pid_t pid,
-                 log_time start);
+                 uint64_t start);
 
     SocketClient *mClient;
-    static const struct timespec EPOCH;
-    log_time mStart;
+    uint64_t mStart;
     const bool mNonBlock;
-    const log_time mEnd; // only relevant if mNonBlock
+    const uint64_t mEnd; // only relevant if mNonBlock
 
     // Protect List manipulations
     static void lock(void) { pthread_mutex_lock(&timesLock); }
@@ -103,8 +102,8 @@ public:
     }
     bool isWatching(log_id_t id) { return (mLogMask & (1<<id)) != 0; }
     // flushTo filter callbacks
-    static bool FilterFirstPass(const LogBufferElement *element, void *me);
-    static bool FilterSecondPass(const LogBufferElement *element, void *me);
+    static int FilterFirstPass(const LogBufferElement *element, void *me);
+    static int FilterSecondPass(const LogBufferElement *element, void *me);
 };
 
 typedef android::List<LogTimeEntry *> LastLogTimes;