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