logd: isMonotonic improvements
Use 1972 as a right delineation. Otherwise use half way point
between the monotonic and realtime. Treat correction factor as
unsigned, ensure that any wrapping to a negative value is
dropped or set to EPOCH. Acknowledge that we can get a more
accurate time track by acquiring the time rather than relying on
healthd timestamp.
Bug: 26331432
Change-Id: I09075fca58676a30cf7d87baf2d4b0f53795abaa
diff --git a/healthd/BatteryMonitor.cpp b/healthd/BatteryMonitor.cpp
index 0085a07..cdfe9c5 100644
--- a/healthd/BatteryMonitor.cpp
+++ b/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 @@
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);
}
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 0243749..2667e78 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -33,16 +33,42 @@
#include "LogWhiteBlackList.h"
//
-// We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to
-// differentiate without prejudice, we use 1980 to delineate, earlier
-// is monotonic, later is real.
+// We are either in 1970ish (MONOTONIC) or 2016+ish (REALTIME) so to
+// differentiate without prejudice, we use 1972 to delineate, earlier
+// 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);
}
}
diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index db7e682..ba0b6e5 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -206,7 +206,10 @@
// 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 @@
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 @@
memset(&tm, 0, sizeof(tm));
tm.tm_isdst = -1;
localtime_r(&now, &tm);
- real.tv_sec += tm.tm_gmtoff;
- correction = real - monotonic;
+ if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > real.tv_sec)) {
+ 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 @@
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 @@
&& ((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, worth the price to deal with
- // ntp-induced or hardware clock drift.
- // look for " 2???-??-?? ??:??:??.????????? ???"
- for (; len && *b && (*b != '\n'); ++b, --len) {
- if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) {
- calculateCorrection(now, b + 1, len - 1);
- break;
- }
- }
+ // NB: healthd is roughly 150us late, so we use it instead to
+ // trigger a check for ntp-induced or hardware clock drift.
+ log_time real(CLOCK_REALTIME);
+ log_time mono(CLOCK_MONOTONIC);
+ correction = (real < mono) ? log_time::EPOCH : (real - mono);
} else if (((b = strnstr(cp, len, suspendedStr)))
&& ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
len -= b - cp;
@@ -371,7 +377,11 @@
real.tv_nsec += (*endp - '0') * multiplier;
}
if (reverse) {
- correction -= real;
+ if (real > correction) {
+ correction = log_time::EPOCH;
+ } else {
+ correction -= real;
+ }
} else {
correction += real;
}