From b6bee33182cedea49199eb2252b3f3b442899c6d Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 8 Sep 2015 08:56:32 -0700 Subject: [PATCH] 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 --- liblog/logd_write.c | 6 +- liblog/logprint.c | 13 ++-- logcat/logcat.cpp | 10 ++- logcat/tests/logcat_test.cpp | 140 +++++++++++++++++++---------------- logd/LogAudit.cpp | 20 ++--- logd/LogAudit.h | 1 + logd/LogBuffer.cpp | 42 ++++++++++- logd/LogBuffer.h | 18 +++++ logd/LogBufferElement.h | 5 +- logd/LogKlog.cpp | 10 ++- logd/LogKlog.h | 2 + logd/LogReader.cpp | 14 +++- logd/README.property | 4 + logd/main.cpp | 2 +- 14 files changed, 200 insertions(+), 87 deletions(-) diff --git a/liblog/logd_write.c b/liblog/logd_write.c index bdee28f50..a4310aee1 100644 --- a/liblog/logd_write.c +++ b/liblog/logd_write.c @@ -191,7 +191,11 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr) * }; */ - 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 0ea2269ea..9f12c96db 100644 --- a/liblog/logprint.c +++ b/liblog/logprint.c @@ -203,7 +203,7 @@ AndroidLogFormat *android_log_format_new() 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 @@ char *android_log_formatLogLine ( 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 cb9a85bff..4d7adf139 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -399,6 +399,10 @@ static log_time lastLogTime(char *outputFileName) { } 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 @@ static log_time lastLogTime(char *outputFileName) { 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 610a6ec70..153a3fd2b 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -75,6 +75,12 @@ TEST(logcat, buckets) { } 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 @@ TEST(logcat, year) { 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 @@ TEST(logcat, tz) { 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 @@ TEST(logcat, ntz) { 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 @@ TEST(logcat, tail_3) { 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 @@ TEST(logcat, tail_10) { 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 @@ TEST(logcat, tail_100) { 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 @@ TEST(logcat, tail_1000) { 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 @@ TEST(logcat, tail_time) { 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 @@ TEST(logcat, tail_time) { 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 @@ TEST(logcat, logrotate) { } } 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 2f7cbfb1a..143fb0429 100644 --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -123,17 +123,19 @@ int LogAudit::logPrint(const char *fmt, ...) { && (*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 23428228a..8a82630f5 100644 --- a/logd/LogAudit.h +++ b/logd/LogAudit.h @@ -29,6 +29,7 @@ class LogAudit : public SocketListener { 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 1de8e640f..c661203fc 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -28,6 +28,7 @@ #include #include "LogBuffer.h" +#include "LogKlog.h" #include "LogReader.h" // Default @@ -126,9 +127,48 @@ void LogBuffer::init() { 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 7ed92e999..c1fec73bb 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 LogBufferElementCollection; class LogBuffer { @@ -49,11 +64,14 @@ class LogBuffer { 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 30e43c680..09987ea75 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -34,6 +34,9 @@ class LogBuffer; #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 @@ class LogBufferElement { 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 d28161e5a..da5e78d66 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -330,6 +330,10 @@ void LogKlog::sniffTime(log_time &now, } *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 @@ void LogKlog::sniffTime(log_time &now, 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 469affdd0..3c8cc8789 100644 --- a/logd/LogKlog.h +++ b/logd/LogKlog.h @@ -43,7 +43,9 @@ public: 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 383384389..06135ddc0 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -114,15 +114,17 @@ bool LogReader::onDataAvailable(SocketClient *cli) { 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 @@ bool LogReader::onDataAvailable(SocketClient *cli) { 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 05ef52852..e4b23a9b9 100644 --- a/logd/README.property +++ b/logd/README.property @@ -25,6 +25,10 @@ persist.logd.filter string Pruning filter to optimize content, "~!" which means to prune the oldest entries of chattiest UID. At runtime use: logcat -P "" +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 cf8cb8f59..ad577d203 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -298,7 +298,7 @@ static void readDmesg(LogAudit *al, LogKlog *kl) { } buf[--len] = '\0'; - if (kl) { + if (kl && kl->isMonotonic()) { kl->synchronize(buf.get(), len); }