liblog: logd: support logd.timestamp = monotonic
if ro.logd.timestamp or persist.logd.timestamp are set to the value
monotonic then liblog writer, liblog printing and logd all switch to
recording/printing monotonic time rather than realtime. If reinit
detects a change for presist.logd.timestamp, correct the older entry
timestamps in place.
ToDo: A corner case condition where new log entries in monotonic time
occur before logd reinit detects persist.logd.timestamp, there
will be a few out-of-order entries, but with accurate
timestamps. This problem does not happen for ro.logd.timestamp
as it is set before logd starts.
NB: This offers a nano second time accuracy on all log entries
that may be more suitable for merging with other system
activities, such as systrace, that also use monotonic time. This
feature is for debugging.
Bug: 23668800
Change-Id: Iee6dab7140061b1a6627254921411f61b01aa5c2
diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp
index 2f7cbfb..143fb04 100644
--- a/logd/LogAudit.cpp
+++ b/logd/LogAudit.cpp
@@ -123,17 +123,19 @@
&& (*cp == ':')) {
memcpy(timeptr + sizeof(audit_str) - 1, "0.0", 3);
memmove(timeptr + sizeof(audit_str) - 1 + 3, cp, strlen(cp) + 1);
- //
- // 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.
- //
-# define EPOCH_PLUS_10_YEARS (10 * 1461 / 4 * 24 * 60 * 60)
- if (now.tv_sec < EPOCH_PLUS_10_YEARS) {
- LogKlog::convertMonotonicToReal(now);
+ if (!isMonotonic()) {
+ if (android::isMonotonic(now)) {
+ LogKlog::convertMonotonicToReal(now);
+ }
+ } else {
+ if (!android::isMonotonic(now)) {
+ LogKlog::convertRealToMonotonic(now);
+ }
}
+ } else if (isMonotonic()) {
+ now = log_time(CLOCK_MONOTONIC);
} else {
- now.strptime("", ""); // side effect of setting CLOCK_REALTIME
+ now = log_time(CLOCK_REALTIME);
}
static const char pid_str[] = " pid=";
diff --git a/logd/LogAudit.h b/logd/LogAudit.h
index 2342822..8a82630 100644
--- a/logd/LogAudit.h
+++ b/logd/LogAudit.h
@@ -29,6 +29,7 @@
public:
LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg);
int log(char *buf, size_t len);
+ bool isMonotonic() { return logbuf->isMonotonic(); }
protected:
virtual bool onDataAvailable(SocketClient *cli);
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 1de8e64..c661203 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -28,6 +28,7 @@
#include <log/logger.h>
#include "LogBuffer.h"
+#include "LogKlog.h"
#include "LogReader.h"
// Default
@@ -126,9 +127,48 @@
setSize(i, LOG_BUFFER_MIN_SIZE);
}
}
+ bool lastMonotonic = monotonic;
+ monotonic = android_log_timestamp() == 'm';
+ if (lastMonotonic == monotonic) {
+ return;
+ }
+
+ //
+ // Fixup all timestamps, may not be 100% accurate, but better than
+ // throwing what we have away when we get 'surprised' by a change.
+ // In-place element fixup so no need to check reader-lock. Entries
+ // should already be in timestamp order, but we could end up with a
+ // few out-of-order entries if new monotonics come in before we
+ // are notified of the reinit change in status. A Typical example would
+ // be:
+ // --------- beginning of system
+ // 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
+ // --------- beginning of kernel
+ // 0.000000 0 0 I : Initializing cgroup subsys cpuacct
+ // as the act of mounting /data would trigger persist.logd.timestamp to
+ // be corrected. 1/30 corner case YMMV.
+ //
+ pthread_mutex_lock(&mLogElementsLock);
+ LogBufferElementCollection::iterator it = mLogElements.begin();
+ while((it != mLogElements.end())) {
+ LogBufferElement *e = *it;
+ if (monotonic) {
+ if (!android::isMonotonic(e->mRealTime)) {
+ LogKlog::convertRealToMonotonic(e->mRealTime);
+ }
+ } else {
+ if (android::isMonotonic(e->mRealTime)) {
+ LogKlog::convertMonotonicToReal(e->mRealTime);
+ }
+ }
+ ++it;
+ }
+ pthread_mutex_unlock(&mLogElementsLock);
}
-LogBuffer::LogBuffer(LastLogTimes *times) : mTimes(*times) {
+LogBuffer::LogBuffer(LastLogTimes *times):
+ monotonic(android_log_timestamp() == 'm'),
+ mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
init();
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 7ed92e9..c1fec73 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -32,6 +32,21 @@
#include "LogStatistics.h"
#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.
+//
+namespace android {
+
+static bool isMonotonic(const log_time &mono) {
+ static const uint32_t EPOCH_PLUS_10_YEARS = 10 * 1461 / 4 * 24 * 60 * 60;
+
+ return mono.tv_sec < EPOCH_PLUS_10_YEARS;
+}
+
+}
+
typedef std::list<LogBufferElement *> LogBufferElementCollection;
class LogBuffer {
@@ -49,11 +64,14 @@
unsigned long mMaxSize[LOG_ID_MAX];
+ bool monotonic;
+
public:
LastLogTimes &mTimes;
LogBuffer(LastLogTimes *times);
void init();
+ bool isMonotonic() { return monotonic; }
int log(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index 30e43c6..09987ea 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -34,6 +34,9 @@
#define EXPIRE_RATELIMIT 10 // maximum rate in seconds to report expiration
class LogBufferElement {
+
+ friend LogBuffer;
+
const log_id_t mLogId;
const uid_t mUid;
const pid_t mPid;
@@ -44,7 +47,7 @@
unsigned short mDropped; // mMsg == NULL
};
const uint64_t mSequence;
- const log_time mRealTime;
+ log_time mRealTime;
static atomic_int_fast64_t sequence;
// assumption: mMsg == NULL
diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp
index d28161e..da5e78d 100644
--- a/logd/LogKlog.cpp
+++ b/logd/LogKlog.cpp
@@ -330,6 +330,10 @@
}
*buf = cp;
+ if (isMonotonic()) {
+ return;
+ }
+
const char *b;
if (((b = strnstr(cp, len, suspendStr)))
&& ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
@@ -376,7 +380,11 @@
convertMonotonicToReal(now);
} else {
- now = log_time(CLOCK_REALTIME);
+ if (isMonotonic()) {
+ now = log_time(CLOCK_MONOTONIC);
+ } else {
+ now = log_time(CLOCK_REALTIME);
+ }
}
}
diff --git a/logd/LogKlog.h b/logd/LogKlog.h
index 469affd..3c8cc87 100644
--- a/logd/LogKlog.h
+++ b/logd/LogKlog.h
@@ -43,7 +43,9 @@
int log(const char *buf, size_t len);
void synchronize(const char *buf, size_t len);
+ bool isMonotonic() { return logbuf->isMonotonic(); }
static void convertMonotonicToReal(log_time &real) { real += correction; }
+ static void convertRealToMonotonic(log_time &real) { real -= correction; }
protected:
void sniffTime(log_time &now, const char **buf, size_t len, bool reverse);
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 3833843..06135dd 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -114,15 +114,17 @@
log_time &start;
uint64_t &sequence;
uint64_t last;
+ bool isMonotonic;
public:
- LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence) :
+ LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence, bool isMonotonic) :
mPid(pid),
mLogMask(logMask),
startTimeSet(false),
start(start),
sequence(sequence),
- last(sequence) {
+ last(sequence),
+ isMonotonic(isMonotonic) {
}
static int callback(const LogBufferElement *element, void *obj) {
@@ -133,20 +135,24 @@
me->sequence = element->getSequence();
me->startTimeSet = true;
return -1;
- } else {
+ } else if (!me->isMonotonic ||
+ android::isMonotonic(element->getRealTime())) {
if (me->start < element->getRealTime()) {
me->sequence = me->last;
me->startTimeSet = true;
return -1;
}
me->last = element->getSequence();
+ } else {
+ me->last = element->getSequence();
}
}
return false;
}
bool found() { return startTimeSet; }
- } logFindStart(logMask, pid, start, sequence);
+ } logFindStart(logMask, pid, start, sequence,
+ logbuf().isMonotonic() && android::isMonotonic(start));
logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli),
logFindStart.callback, &logFindStart);
diff --git a/logd/README.property b/logd/README.property
index 05ef528..e4b23a9 100644
--- a/logd/README.property
+++ b/logd/README.property
@@ -25,6 +25,10 @@
"~!" which means to prune the oldest
entries of chattiest UID. At runtime
use: logcat -P "<string>"
+persist.logd.timestamp string The recording timestamp source. Default
+ is ro.logd.timestamp. "m[onotonic]" is
+ the only supported key character,
+ otherwise assumes realtime.
NB:
- Number support multipliers (K or M) for convenience. Range is limited
diff --git a/logd/main.cpp b/logd/main.cpp
index cf8cb8f..ad577d2 100644
--- a/logd/main.cpp
+++ b/logd/main.cpp
@@ -298,7 +298,7 @@
}
buf[--len] = '\0';
- if (kl) {
+ if (kl && kl->isMonotonic()) {
kl->synchronize(buf.get(), len);
}