From 10b82b683405e9ccd0cc162fa44a2ec6a9f26448 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 28 Dec 2015 15:33:01 -0800 Subject: [PATCH] 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 --- healthd/BatteryMonitor.cpp | 20 ------------------ logd/LogBuffer.h | 36 +++++++++++++++++++++++++++----- logd/LogKlog.cpp | 42 +++++++++++++++++++++++--------------- 3 files changed, 57 insertions(+), 41 deletions(-) diff --git a/healthd/BatteryMonitor.cpp b/healthd/BatteryMonitor.cpp index 0085a078f..cdfe9c573 100644 --- a/healthd/BatteryMonitor.cpp +++ b/healthd/BatteryMonitor.cpp @@ -30,7 +30,6 @@ #include #include #include -#include #include #include #include @@ -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); } diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 0243749f9..2667e7828 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 db7e68218..ba0b6e5db 100644 --- a/logd/LogKlog.cpp +++ b/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; - 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 @@ 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, 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 @@ 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; }