Merge "liblog: logd: support logd.timestamp = monotonic" am: 8897a3fffd
am: 55316200b8
* commit '55316200b89e2a862969b0fac02c5b717ae3414b':
liblog: logd: support logd.timestamp = monotonic
diff --git a/liblog/logd_write.c b/liblog/logd_write.c
index bdee28f..a4310ae 100644
--- a/liblog/logd_write.c
+++ b/liblog/logd_write.c
@@ -191,7 +191,11 @@
* };
*/
- clock_gettime(CLOCK_REALTIME, &ts);
+ if (android_log_timestamp() == 'm') {
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ } else {
+ clock_gettime(CLOCK_REALTIME, &ts);
+ }
pmsg_header.magic = LOGGER_MAGIC;
pmsg_header.len = sizeof(pmsg_header) + sizeof(header);
diff --git a/liblog/logprint.c b/liblog/logprint.c
index 0ea2269..9f12c96 100644
--- a/liblog/logprint.c
+++ b/liblog/logprint.c
@@ -203,7 +203,7 @@
p_ret->year_output = false;
p_ret->zone_output = false;
p_ret->epoch_output = false;
- p_ret->monotonic_output = false;
+ p_ret->monotonic_output = android_log_timestamp() == 'm';
return p_ret;
}
@@ -1261,10 +1261,13 @@
now = entry->tv_sec;
nsec = entry->tv_nsec;
if (p_format->monotonic_output) {
- struct timespec time;
- convertMonotonic(&time, entry);
- now = time.tv_sec;
- nsec = time.tv_nsec;
+ // prevent convertMonotonic from being called if logd is monotonic
+ if (android_log_timestamp() != 'm') {
+ struct timespec time;
+ convertMonotonic(&time, entry);
+ now = time.tv_sec;
+ nsec = time.tv_nsec;
+ }
}
if (now < 0) {
nsec = NS_PER_SEC - nsec;
diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp
index cb9a85b..4d7adf1 100644
--- a/logcat/logcat.cpp
+++ b/logcat/logcat.cpp
@@ -399,6 +399,10 @@
}
log_time now(CLOCK_REALTIME);
+ bool monotonic = android_log_timestamp() == 'm';
+ if (monotonic) {
+ now = log_time(CLOCK_MONOTONIC);
+ }
std::string directory;
char *file = strrchr(outputFileName, '/');
@@ -417,7 +421,11 @@
struct dirent *dp;
while ((dp = readdir(dir.get())) != NULL) {
if ((dp->d_type != DT_REG)
- || strncmp(dp->d_name, file, len)
+ // If we are using realtime, check all files that match the
+ // basename for latest time. If we are using monotonic time
+ // then only check the main file because time cycles on
+ // every reboot.
+ || strncmp(dp->d_name, file, len + monotonic)
|| (dp->d_name[len]
&& ((dp->d_name[len] != '.')
|| !isdigit(dp->d_name[len+1])))) {
diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp
index 610a6ec..153a3fd 100644
--- a/logcat/tests/logcat_test.cpp
+++ b/logcat/tests/logcat_test.cpp
@@ -75,6 +75,12 @@
}
TEST(logcat, year) {
+
+ if (android_log_timestamp() == 'm') {
+ fprintf(stderr, "Skipping test, logd is monotonic time\n");
+ return;
+ }
+
FILE *fp;
char needle[32];
@@ -108,7 +114,44 @@
ASSERT_EQ(3, count);
}
+// Return a pointer to each null terminated -v long time field.
+char *fgetLongTime(char *buffer, size_t buflen, FILE *fp) {
+ while (fgets(buffer, buflen, fp)) {
+ char *cp = buffer;
+ if (*cp != '[') {
+ continue;
+ }
+ while (*++cp == ' ') {
+ ;
+ }
+ char *ep = cp;
+ while (isdigit(*ep)) {
+ ++ep;
+ }
+ if ((*ep != '-') && (*ep != '.')) {
+ continue;
+ }
+ // Find PID field
+ while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) {
+ ;
+ }
+ if (!ep) {
+ continue;
+ }
+ ep -= 7;
+ *ep = '\0';
+ return cp;
+ }
+ return NULL;
+}
+
TEST(logcat, tz) {
+
+ if (android_log_timestamp() == 'm') {
+ fprintf(stderr, "Skipping test, logd is monotonic time\n");
+ return;
+ }
+
FILE *fp;
ASSERT_TRUE(NULL != (fp = popen(
@@ -119,11 +162,8 @@
int count = 0;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[2]) && isdigit(buffer[3])
- && (buffer[4] == '-')
- && (strstr(buffer, " -0700 ") || strstr(buffer, " -0800 "))) {
+ while (fgetLongTime(buffer, sizeof(buffer), fp)) {
+ if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
++count;
}
}
@@ -144,11 +184,8 @@
int count = 0;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[2]) && isdigit(buffer[3])
- && (buffer[4] == '-')
- && (strstr(buffer, " -0700 ") || strstr(buffer, " -0800 "))) {
+ while (fgetLongTime(buffer, sizeof(buffer), fp)) {
+ if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
++count;
}
}
@@ -169,12 +206,8 @@
int count = 0;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[2]) && isdigit(buffer[3])
- && (buffer[4] == '-')) {
- ++count;
- }
+ while (fgetLongTime(buffer, sizeof(buffer), fp)) {
+ ++count;
}
pclose(fp);
@@ -193,12 +226,8 @@
int count = 0;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[2]) && isdigit(buffer[3])
- && (buffer[4] == '-')) {
- ++count;
- }
+ while (fgetLongTime(buffer, sizeof(buffer), fp)) {
+ ++count;
}
pclose(fp);
@@ -217,12 +246,8 @@
int count = 0;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[2]) && isdigit(buffer[3])
- && (buffer[4] == '-')) {
- ++count;
- }
+ while (fgetLongTime(buffer, sizeof(buffer), fp)) {
+ ++count;
}
pclose(fp);
@@ -241,12 +266,8 @@
int count = 0;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[2]) && isdigit(buffer[3])
- && (buffer[4] == '-')) {
- ++count;
- }
+ while (fgetLongTime(buffer, sizeof(buffer), fp)) {
+ ++count;
}
pclose(fp);
@@ -263,21 +284,15 @@
char *last_timestamp = NULL;
char *first_timestamp = NULL;
int count = 0;
- const unsigned int time_length = 18;
- const unsigned int time_offset = 2;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1])
- && (buffer[time_offset + 2] == '-')) {
- ++count;
- buffer[time_length + time_offset] = '\0';
- if (!first_timestamp) {
- first_timestamp = strdup(buffer + time_offset);
- }
- free(last_timestamp);
- last_timestamp = strdup(buffer + time_offset);
+ char *cp;
+ while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
+ ++count;
+ if (!first_timestamp) {
+ first_timestamp = strdup(cp);
}
+ free(last_timestamp);
+ last_timestamp = strdup(cp);
}
pclose(fp);
@@ -292,28 +307,24 @@
int second_count = 0;
int last_timestamp_count = -1;
- while (fgets(buffer, sizeof(buffer), fp)) {
- if ((buffer[0] == '[') && (buffer[1] == ' ')
- && isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1])
- && (buffer[time_offset + 2] == '-')) {
- ++second_count;
- buffer[time_length + time_offset] = '\0';
- if (first_timestamp) {
- // we can get a transitory *extremely* rare failure if hidden
- // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000
- EXPECT_STREQ(buffer + time_offset, first_timestamp);
- free(first_timestamp);
- first_timestamp = NULL;
- }
- if (!strcmp(buffer + time_offset, last_timestamp)) {
- last_timestamp_count = second_count;
- }
+ while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
+ ++second_count;
+ if (first_timestamp) {
+ // we can get a transitory *extremely* rare failure if hidden
+ // underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000
+ EXPECT_STREQ(cp, first_timestamp);
+ free(first_timestamp);
+ first_timestamp = NULL;
+ }
+ if (!strcmp(cp, last_timestamp)) {
+ last_timestamp_count = second_count;
}
}
pclose(fp);
free(last_timestamp);
last_timestamp = NULL;
+ free(first_timestamp);
EXPECT_TRUE(first_timestamp == NULL);
EXPECT_LE(count, second_count);
@@ -601,6 +612,9 @@
}
}
pclose(fp);
+ if ((count != 7) && (count != 8)) {
+ fprintf(stderr, "count=%d\n", count);
+ }
EXPECT_TRUE(count == 7 || count == 8);
}
}
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 4ada788..fd5c066 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);
}