Merge "logd: isMonotonic improvements"

am: 554630f94e

* commit '554630f94e07023fcb0e05c82dccd9a2e172f508':
  logd: isMonotonic improvements

healthd/BatteryMonitor.cpp

@@ -30,7 +30,6 @@
 #include <batteryservice/BatteryService.h>
 #include <cutils/klog.h>
 #include <cutils/properties.h>
-#include <log/log_read.h>
 #include <utils/Errors.h>
 #include <utils/String8.h>
 #include <utils/Vector.h>
@@ -313,25 +312,6 @@ bool BatteryMonitor::update(void) {
                  props.chargerUsbOnline ? "u" : "",
                  props.chargerWirelessOnline ? "w" : "");
 
-        log_time realtime(CLOCK_REALTIME);
-        time_t t = realtime.tv_sec;
-        struct tm *tmp = gmtime(&t);
-        if (tmp) {
-            static const char fmt[] = " %Y-%m-%d %H:%M:%S.XXXXXXXXX UTC";
-            len = strlen(dmesgline);
-            if ((len < (sizeof(dmesgline) - sizeof(fmt) - 8)) // margin
-                    && strftime(dmesgline + len, sizeof(dmesgline) - len,
-                                fmt, tmp)) {
-                char *usec = strchr(dmesgline + len, 'X');
-                if (usec) {
-                    len = usec - dmesgline;
-                    snprintf(dmesgline + len, sizeof(dmesgline) - len,
-                             "%09u", realtime.tv_nsec);
-                    usec[9] = ' ';
-                }
-            }
-        }
-
         KLOG_WARNING(LOG_TAG, "%s\n", dmesgline);
     }
 

logd/LogBuffer.h

@@ -33,16 +33,42 @@
 #include "LogWhiteBlackList.h"
 
 //
-// We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to
+// We are either in 1970ish (MONOTONIC) or 2016+ish (REALTIME) so to
-// differentiate without prejudice, we use 1980 to delineate, earlier
+// differentiate without prejudice, we use 1972 to delineate, earlier
-// is monotonic, later is real.
+// is likely monotonic, later is real. Otherwise we start using a
+// dividing line between monotonic and realtime if more than a minute
+// difference between them.
 //
 namespace android {
 
 static bool isMonotonic(const log_time &mono) {
-    static const uint32_t EPOCH_PLUS_10_YEARS = 10 * 1461 / 4 * 24 * 60 * 60;
+    static const uint32_t EPOCH_PLUS_2_YEARS = 2 * 24 * 60 * 60 * 1461 / 4;
+    static const uint32_t EPOCH_PLUS_MINUTE = 60;
 
-    return mono.tv_sec < EPOCH_PLUS_10_YEARS;
+    if (mono.tv_sec >= EPOCH_PLUS_2_YEARS) {
+        return false;
+    }
+
+    log_time now(CLOCK_REALTIME);
+
+    /* Timezone and ntp time setup? */
+    if (now.tv_sec >= EPOCH_PLUS_2_YEARS) {
+        return true;
+    }
+
+    /* no way to differentiate realtime from monotonic time */
+    if (now.tv_sec < EPOCH_PLUS_MINUTE) {
+        return false;
+    }
+
+    log_time cpu(CLOCK_MONOTONIC);
+    /* too close to call to differentiate monotonic times from realtime */
+    if ((cpu.tv_sec + EPOCH_PLUS_MINUTE) >= now.tv_sec) {
+        return false;
+    }
+
+    /* dividing line half way between monotonic and realtime */
+    return mono.tv_sec < ((cpu.tv_sec + now.tv_sec) / 2);
 }
 
 }

logd/LogKlog.cpp

@@ -206,7 +206,10 @@ char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) {
     // NOTREACHED
 }
 
-log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC);
+log_time LogKlog::correction =
+    (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTONIC))
+        ? log_time::EPOCH
+        : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC));
 
 LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) :
         SocketListener(fdRead, false),
@@ -272,7 +275,7 @@ void LogKlog::calculateCorrection(const log_time &monotonic,
                                   size_t len) {
     log_time real;
     const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC");
-    if (!ep || (ep > &real_string[len])) {
+    if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) {
         return;
     }
     // kernel report UTC, log_time::strptime is localtime from calendar.
@@ -283,8 +286,16 @@ void LogKlog::calculateCorrection(const log_time &monotonic,
     memset(&tm, 0, sizeof(tm));
     tm.tm_isdst = -1;
     localtime_r(&now, &tm);
-    real.tv_sec += tm.tm_gmtoff;
+    if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > real.tv_sec)) {
-    correction = real - monotonic;
+        real = log_time::EPOCH;
+    } else {
+        real.tv_sec += tm.tm_gmtoff;
+    }
+    if (monotonic > real) {
+        correction = log_time::EPOCH;
+    } else {
+        correction = real - monotonic;
+    }
 }
 
 static const char suspendStr[] = "PM: suspend entry ";
@@ -319,11 +330,11 @@ void LogKlog::sniffTime(log_time &now,
     if (cp && (cp >= &(*buf)[len])) {
         cp = NULL;
     }
-    len -= cp - *buf;
     if (cp) {
         static const char healthd[] = "healthd";
         static const char battery[] = ": battery ";
 
+        len -= cp - *buf;
         if (len && isspace(*cp)) {
             ++cp;
             --len;
@@ -347,16 +358,11 @@ void LogKlog::sniffTime(log_time &now,
                 && ((size_t)((b += sizeof(healthd) - 1) - cp) < len)
                 && ((b = strnstr(b, len -= b - cp, battery)))
                 && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) {
-            len -= b - cp;
+            // NB: healthd is roughly 150us late, so we use it instead to
-            // NB: healthd is roughly 150us late, worth the price to deal with
+            //     trigger a check for ntp-induced or hardware clock drift.
-            //     ntp-induced or hardware clock drift.
+            log_time real(CLOCK_REALTIME);
-            // look for " 2???-??-?? ??:??:??.????????? ???"
+            log_time mono(CLOCK_MONOTONIC);
-            for (; len && *b && (*b != '\n'); ++b, --len) {
+            correction = (real < mono) ? log_time::EPOCH : (real - mono);
-                if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) {
-                    calculateCorrection(now, b + 1, len - 1);
-                    break;
-                }
-            }
         } else if (((b = strnstr(cp, len, suspendedStr)))
                 && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
             len -= b - cp;
@@ -371,7 +377,11 @@ void LogKlog::sniffTime(log_time &now,
                     real.tv_nsec += (*endp - '0') * multiplier;
                 }
                 if (reverse) {
-                    correction -= real;
+                    if (real > correction) {
+                        correction = log_time::EPOCH;
+                    } else {
+                        correction -= real;
+                    }
                 } else {
                     correction += real;
                 }