Merge "logd: isMonotonic improvements"

This commit is contained in:
Mark Salyzyn 2015-12-30 21:31:58 +00:00 committed by Gerrit Code Review
commit 554630f94e
3 changed files with 57 additions and 41 deletions

View File

@ -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);
}

View File

@ -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);
}
}

View File

@ -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;
}