Merge changes If1a62a90,Ibce79cf1,Ia2bbf01a,I1763be56,I56762747, ...

Tom Cherry · Gerrit Code Review · commit 56cd920ff80d · 2020-04-09T17:24:12.000Z
* changes:
  logd: don't send logs before the start time on the first flushTo()
  Revert "logd: drop mSequence from LogBufferElement"
  Revert "logd: regression in handling watermark boundary."
  Revert "logd: logcat --clear respect pruneMargin"
  logd: wait for timeout via CLOCK_MONOTONIC
  Revert "logd: wakeup wrap timeout if realtime changes drastically"
  logd: do not attempt to sort log messages by time
diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp
@@ -49,18 +49,8 @@ void FlushCommand::runSocketCommand(SocketClient* client) {
                 return;
             }
             if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) {
-                if (mReader.logbuf().isMonotonic()) {
-                    LogTimeEntry::unlock();
-                    return;
-                }
-                // If the user changes the time in a gross manner that
-                // invalidates the timeout, fall through and trigger.
-                log_time now(CLOCK_REALTIME);
-                if (((entry->mEnd + entry->mTimeout) > now) &&
-                    (now > entry->mEnd)) {
-                    LogTimeEntry::unlock();
-                    return;
-                }
+                LogTimeEntry::unlock();
+                return;
             }
             entry->triggerReader_Locked();
             LogTimeEntry::unlock();
diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h
@@ -16,7 +16,7 @@
 #ifndef _FLUSH_COMMAND_H
 #define _FLUSH_COMMAND_H
 
-#include <private/android_logger.h>
+#include <android/log.h>
 #include <sysutils/SocketClientCommand.h>
 
 class LogBufferElement;
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
@@ -27,6 +27,7 @@
 #include <unistd.h>
 
 #include <unordered_map>
+#include <utility>
 
 #include <cutils/properties.h>
 #include <private/android_logger.h>
@@ -43,8 +44,6 @@
 // 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;
@@ -390,59 +389,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
 
 // assumes LogBuffer::wrlock() held, owns elem, look after garbage collection
 void LogBuffer::log(LogBufferElement* elem) {
-    // cap on how far back we will sort in-place, otherwise append
-    static uint32_t too_far_back = 5;  // five seconds
-    // Insert elements in time sorted order if possible
-    //  NB: if end is region locked, place element at end of list
-    LogBufferElementCollection::iterator it = mLogElements.end();
-    LogBufferElementCollection::iterator last = it;
-    if (__predict_true(it != mLogElements.begin())) --it;
-    if (__predict_false(it == mLogElements.begin()) ||
-        __predict_true((*it)->getRealTime() <= elem->getRealTime()) ||
-        __predict_false((((*it)->getRealTime().tv_sec - too_far_back) >
-                         elem->getRealTime().tv_sec) &&
-                        (elem->getLogId() != LOG_ID_KERNEL) &&
-                        ((*it)->getLogId() != LOG_ID_KERNEL))) {
-        mLogElements.push_back(elem);
-    } else {
-        log_time end(log_time::EPOCH);
-        bool end_set = false;
-        bool end_always = false;
-
-        LogTimeEntry::rdlock();
-
-        LastLogTimes::iterator times = mTimes.begin();
-        while (times != mTimes.end()) {
-            LogTimeEntry* entry = times->get();
-            if (!entry->mNonBlock) {
-                end_always = true;
-                break;
-            }
-            // it passing mEnd is blocked by the following checks.
-            if (!end_set || (end <= entry->mEnd)) {
-                end = entry->mEnd;
-                end_set = true;
-            }
-            times++;
-        }
-
-        if (end_always || (end_set && (end > (*it)->getRealTime()))) {
-            mLogElements.push_back(elem);
-        } else {
-            // should be short as timestamps are localized near end()
-            do {
-                last = it;
-                if (__predict_false(it == mLogElements.begin())) {
-                    break;
-                }
-                --it;
-            } while (((*it)->getRealTime() > elem->getRealTime()) &&
-                     (!end_set || (end <= (*it)->getRealTime())));
-            mLogElements.insert(last, elem);
-        }
-        LogTimeEntry::unlock();
-    }
-
+    mLogElements.push_back(elem);
     stats.add(elem);
     maybePrune(elem->getLogId());
 }
@@ -614,12 +561,11 @@ class LogBufferElementLast {
     }
 
     void clear(LogBufferElement* element) {
-        log_time current =
-            element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0);
+        uint64_t current = element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC);
         for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
             LogBufferElement* mapElement = it->second;
-            if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) &&
-                (current > mapElement->getRealTime())) {
+            if (mapElement->getDropped() >= EXPIRE_THRESHOLD &&
+                current > mapElement->getRealTime().nsec()) {
                 it = map.erase(it);
             } else {
                 ++it;
@@ -628,16 +574,6 @@ class LogBufferElementLast {
     }
 };
 
-// Determine if watermark is within pruneMargin + 1s from the end of the list,
-// the caller will use this result to set an internal busy flag indicating
-// the prune operation could not be completed because a reader is blocking
-// the request.
-bool LogBuffer::isBusy(log_time watermark) {
-    LogBufferElementCollection::iterator ei = mLogElements.end();
-    --ei;
-    return watermark < ((*ei)->getRealTime() - pruneMargin - log_time(1, 0));
-}
-
 // If the selected reader is blocking our pruning progress, decide on
 // what kind of mitigation is necessary to unblock the situation.
 void LogBuffer::kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows) {
@@ -726,8 +662,6 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         }
         times++;
     }
-    log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max);
-    if (oldest) watermark = oldest->mStart - pruneMargin;
 
     LogBufferElementCollection::iterator it;
 
@@ -749,9 +683,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 mLastSet[id] = true;
             }
 
-            if (oldest && (watermark <= element->getRealTime())) {
-                busy = isBusy(watermark);
-                if (busy) kickMe(oldest, id, pruneRows);
+            if (oldest && oldest->mStart <= element->getSequence()) {
+                busy = true;
+                kickMe(oldest, id, pruneRows);
                 break;
             }
 
@@ -837,8 +771,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         while (it != mLogElements.end()) {
             LogBufferElement* element = *it;
 
-            if (oldest && (watermark <= element->getRealTime())) {
-                busy = isBusy(watermark);
+            if (oldest && oldest->mStart <= element->getSequence()) {
+                busy = true;
                 // Do not let chatty eliding trigger any reader mitigation
                 break;
             }
@@ -989,9 +923,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
             mLastSet[id] = true;
         }
 
-        if (oldest && (watermark <= element->getRealTime())) {
-            busy = isBusy(watermark);
-            if (!whitelist && busy) kickMe(oldest, id, pruneRows);
+        if (oldest && oldest->mStart <= element->getSequence()) {
+            busy = true;
+            if (!whitelist) kickMe(oldest, id, pruneRows);
             break;
         }
 
@@ -1022,9 +956,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 mLastSet[id] = true;
             }
 
-            if (oldest && (watermark <= element->getRealTime())) {
-                busy = isBusy(watermark);
-                if (busy) kickMe(oldest, id, pruneRows);
+            if (oldest && oldest->mStart <= element->getSequence()) {
+                busy = true;
+                kickMe(oldest, id, pruneRows);
                 break;
             }
 
@@ -1111,43 +1045,32 @@ unsigned long LogBuffer::getSize(log_id_t id) {
     return retval;
 }
 
-log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
-                            pid_t* lastTid, bool privileged, bool security,
-                            int (*filter)(const LogBufferElement* element,
-                                          void* arg),
-                            void* arg) {
+uint64_t LogBuffer::flushTo(SocketClient* reader, uint64_t start, pid_t* lastTid, bool privileged,
+                            bool security,
+                            int (*filter)(const LogBufferElement* element, void* arg), void* arg) {
     LogBufferElementCollection::iterator it;
     uid_t uid = reader->getUid();
 
     rdlock();
 
-    if (start == log_time::EPOCH) {
+    if (start <= 1) {
         // client wants to start from the beginning
         it = mLogElements.begin();
     } else {
-        // 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();
+        for (it = mLogElements.end(); it != mLogElements.begin();
              /* do nothing */) {
             --it;
             LogBufferElement* element = *it;
-            if (element->getRealTime() > start) {
-                last = it;
-            } else if (element->getRealTime() == start) {
-                last = ++it;
-                break;
-            } else if (!--count) {
+            if (element->getSequence() <= start) {
+                it++;
                 break;
             }
         }
-        it = last;
     }
 
-    log_time curr = start;
+    uint64_t curr = start;
 
     LogBufferElement* lastElement = nullptr;  // iterator corruption paranoia
     static const size_t maxSkip = 4194304;    // maximum entries to skip
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
@@ -118,11 +118,10 @@ class LogBuffer {
     // lastTid is an optional context to help detect if the last previous
     // valid message was from the same source so we can differentiate chatty
     // filter types (identical or expired)
-    log_time flushTo(SocketClient* writer, const log_time& start,
+    uint64_t flushTo(SocketClient* writer, uint64_t start,
                      pid_t* lastTid,  // &lastTid[LOG_ID_MAX] or nullptr
                      bool privileged, bool security,
-                     int (*filter)(const LogBufferElement* element,
-                                   void* arg) = nullptr,
+                     int (*filter)(const LogBufferElement* element, void* arg) = nullptr,
                      void* arg = nullptr);
 
     bool clear(log_id_t id, uid_t uid = AID_ROOT);
@@ -175,10 +174,8 @@ class LogBuffer {
    private:
     static constexpr size_t minPrune = 4;
     static constexpr size_t maxPrune = 256;
-    static const log_time pruneMargin;
 
     void maybePrune(log_id_t id);
-    bool isBusy(log_time watermark);
     void kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows);
 
     bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
@@ -30,15 +30,15 @@
 #include "LogReader.h"
 #include "LogUtils.h"
 
-const log_time LogBufferElement::FLUSH_ERROR((uint32_t)-1, (uint32_t)-1);
+const uint64_t LogBufferElement::FLUSH_ERROR(0);
 atomic_int_fast64_t LogBufferElement::sequence(1);
 
-LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
-                                   uid_t uid, pid_t pid, pid_t tid,
-                                   const char* msg, uint16_t len)
+LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
+                                   pid_t tid, const char* msg, uint16_t len)
     : mUid(uid),
       mPid(pid),
       mTid(tid),
+      mSequence(sequence.fetch_add(1, memory_order_relaxed)),
       mRealTime(realtime),
       mMsgLen(len),
       mLogId(log_id),
@@ -51,6 +51,7 @@ LogBufferElement::LogBufferElement(const LogBufferElement& elem)
     : mUid(elem.mUid),
       mPid(elem.mPid),
       mTid(elem.mTid),
+      mSequence(elem.mSequence),
       mRealTime(elem.mRealTime),
       mMsgLen(elem.mMsgLen),
       mLogId(elem.mLogId),
@@ -244,7 +245,7 @@ size_t LogBufferElement::populateDroppedMessage(char*& buffer, LogBuffer* parent
     return retval;
 }
 
-log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool lastSame) {
+uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool lastSame) {
     struct logger_entry entry = {};
 
     entry.hdr_size = sizeof(struct logger_entry);
@@ -263,17 +264,15 @@ log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool
 
     if (mDropped) {
         entry.len = populateDroppedMessage(buffer, parent, lastSame);
-        if (!entry.len) return mRealTime;
+        if (!entry.len) return mSequence;
         iovec[1].iov_base = buffer;
     } else {
         entry.len = mMsgLen;
         iovec[1].iov_base = mMsg;
     }
     iovec[1].iov_len = entry.len;
 
-    log_time retval = reader->sendDatav(iovec, 1 + (entry.len != 0))
-                          ? FLUSH_ERROR
-                          : mRealTime;
+    uint64_t retval = reader->sendDatav(iovec, 1 + (entry.len != 0)) ? FLUSH_ERROR : mSequence;
 
     if (buffer) free(buffer);
 
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
@@ -39,6 +39,7 @@ class __attribute__((packed)) LogBufferElement {
     const uint32_t mUid;
     const uint32_t mPid;
     const uint32_t mTid;
+    uint64_t mSequence;
     log_time mRealTime;
     union {
         char* mMsg;    // mDropped == false
@@ -90,10 +91,12 @@ class __attribute__((packed)) LogBufferElement {
     const char* getMsg() const {
         return mDropped ? nullptr : mMsg;
     }
+    uint64_t getSequence() const { return mSequence; }
+    static uint64_t getCurrentSequence() { return sequence.load(memory_order_relaxed); }
     log_time getRealTime(void) const {
         return mRealTime;
     }
 
-    static const log_time FLUSH_ERROR;
-    log_time flushTo(SocketClient* writer, LogBuffer* parent, bool lastSame);
+    static const uint64_t FLUSH_ERROR;
+    uint64_t flushTo(SocketClient* writer, LogBuffer* parent, bool lastSame);
 };
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
diff --git a/logd/LogTimes.h b/logd/LogTimes.h
