Merge changes Iec369a50,I3f9f8d56,I78959464,I72ea858e

am: 6ad16cda19

Change-Id: I3e44fdd82fb5ec8a1beffa759df82a67556ea16a

liblog/include/log/log_time.h

@@ -41,13 +41,12 @@ struct log_time {
   static const uint32_t tv_sec_max = 0xFFFFFFFFUL;
   static const uint32_t tv_nsec_max = 999999999UL;
 
-  log_time(const timespec& T) {
+  log_time(const timespec& T)
-    tv_sec = static_cast<uint32_t>(T.tv_sec);
+      : tv_sec(static_cast<uint32_t>(T.tv_sec)),
-    tv_nsec = static_cast<uint32_t>(T.tv_nsec);
+        tv_nsec(static_cast<uint32_t>(T.tv_nsec)) {
   }
-  log_time(uint32_t sec, uint32_t nsec) {
+  explicit log_time(uint32_t sec, uint32_t nsec = 0)
-    tv_sec = sec;
+      : tv_sec(sec), tv_nsec(nsec) {
-    tv_nsec = nsec;
   }
 #ifdef _SYSTEM_CORE_INCLUDE_PRIVATE_ANDROID_LOGGER_H_
 #define __struct_log_time_private_defined
@@ -56,14 +55,14 @@ struct log_time {
   log_time() {
   }
 #ifdef __linux__
-  log_time(clockid_t id) {
+  explicit log_time(clockid_t id) {
     timespec T;
     clock_gettime(id, &T);
     tv_sec = static_cast<uint32_t>(T.tv_sec);
     tv_nsec = static_cast<uint32_t>(T.tv_nsec);
   }
 #endif
-  log_time(const char* T) {
+  explicit log_time(const char* T) {
     const uint8_t* c = reinterpret_cast<const uint8_t*>(T);
     tv_sec = c[0] | (static_cast<uint32_t>(c[1]) << 8) |
              (static_cast<uint32_t>(c[2]) << 16) |

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 @@ 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;
 
@@ -693,7 +697,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
         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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
             mLastSet[id] = true;
         }
 
-        if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
+        if (oldest && (watermark <= element->getRealTime())) {
             busy = true;
             if (whitelist) {
                 break;
@@ -983,7 +987,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
                 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 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
         // 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;
@@ -1112,9 +1118,22 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
 
     log_time max = start;
 
+    LogBufferElement* lastElement = nullptr;  // iterator corruption paranoia
+    static const size_t maxSkip = 4194304;    // maximum entries to skip
+    size_t skip = maxSkip;
     for (; it != mLogElements.end(); ++it) {
         LogBufferElement* element = *it;
 
+        if (!--skip) {
+            android::prdebug("reader.per: too many elements skipped");
+            break;
+        }
+        if (element == lastElement) {
+            android::prdebug("reader.per: identical elements");
+            break;
+        }
+        lastElement = element;
+
         if (!privileged && (element->getUid() != uid)) {
             continue;
         }
@@ -1159,6 +1178,7 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
             return max;
         }
 
+        skip = maxSkip;
         pthread_mutex_lock(&mLogElementsLock);
     }
     pthread_mutex_unlock(&mLogElementsLock);

logd/LogBuffer.h

@@ -174,6 +174,7 @@ 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 prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);

logd/tests/logd_test.cpp

@@ -670,8 +670,12 @@ TEST(logd, timeout) {
     while (--i) {
         int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
                                      SOCK_SEQPACKET);
-        EXPECT_LT(0, fd);
+        int save_errno = errno;
-        if (fd < 0) _exit(fd);
+        if (fd < 0) {
+            fprintf(stderr, "failed to open /dev/socket/logdr %s\n",
+                    strerror(save_errno));
+            _exit(fd);
+        }
 
         std::string ask = android::base::StringPrintf(
             "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32
@@ -723,8 +727,12 @@ TEST(logd, timeout) {
         // active _or_ inactive during the test.
         if (content_timeout) {
             log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec);
-            EXPECT_FALSE(msg < now);
+            if (msg < now) {
-            if (msg < now) _exit(-1);
+                fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec,
+                        msg_timeout.entry.nsec, (unsigned)now.tv_sec,
+                        (unsigned)now.tv_nsec);
+                _exit(-1);
+            }
             if (msg > now) {
                 now = msg;
                 now.tv_sec += 30;