Merge changes Iec369a50,I3f9f8d56,I78959464,I72ea858e am: 991ad3678c am: 7b45da1006
am: 732f30ee8e

Change-Id: I2aaac98558b8717c7dc339eccaa3215f40c2575a
diff --git a/liblog/include/log/log_time.h b/liblog/include/log/log_time.h
index 5f70f7d..9ece0b3 100644
--- a/liblog/include/log/log_time.h
+++ b/liblog/include/log/log_time.h
@@ -41,13 +41,12 @@
   static const uint32_t tv_sec_max = 0xFFFFFFFFUL;
   static const uint32_t tv_nsec_max = 999999999UL;
 
-  log_time(const timespec& T) {
-    tv_sec = static_cast<uint32_t>(T.tv_sec);
-    tv_nsec = static_cast<uint32_t>(T.tv_nsec);
+  log_time(const timespec& T)
+      : tv_sec(static_cast<uint32_t>(T.tv_sec)),
+        tv_nsec(static_cast<uint32_t>(T.tv_nsec)) {
   }
-  log_time(uint32_t sec, uint32_t nsec) {
-    tv_sec = sec;
-    tv_nsec = nsec;
+  explicit log_time(uint32_t sec, uint32_t nsec = 0)
+      : tv_sec(sec), tv_nsec(nsec) {
   }
 #ifdef _SYSTEM_CORE_INCLUDE_PRIVATE_ANDROID_LOGGER_H_
 #define __struct_log_time_private_defined
@@ -56,14 +55,14 @@
   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) |
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 8ef9328..4aa2c9f 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;
@@ -674,6 +676,8 @@
         }
         times++;
     }
+    log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max);
+    if (oldest) watermark = oldest->mStart - pruneMargin;
 
     LogBufferElementCollection::iterator it;
 
@@ -695,7 +699,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();
@@ -787,7 +791,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();
@@ -941,7 +945,7 @@
             mLastSet[id] = true;
         }
 
-        if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
+        if (oldest && (watermark <= element->getRealTime())) {
             busy = true;
             if (whitelist) {
                 break;
@@ -985,7 +989,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
@@ -1092,13 +1096,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;
@@ -1114,9 +1120,22 @@
 
     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;
         }
@@ -1161,6 +1180,7 @@
             return max;
         }
 
+        skip = maxSkip;
         pthread_mutex_lock(&mLogElementsLock);
     }
     pthread_mutex_unlock(&mLogElementsLock);
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 19d11cb..1272c20 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -174,6 +174,7 @@
    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);
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index 88cb67a..a1d154a 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -670,8 +670,12 @@
     while (--i) {
         int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED,
                                      SOCK_SEQPACKET);
-        EXPECT_LT(0, fd);
-        if (fd < 0) _exit(fd);
+        int save_errno = errno;
+        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 @@
         // 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) _exit(-1);
+            if (msg < now) {
+                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;