diff --git a/liblog/include/log/log_time.h b/liblog/include/log/log_time.h index 5f70f7d4c..9ece0b328 100644 --- a/liblog/include/log/log_time.h +++ b/liblog/include/log/log_time.h @@ -41,13 +41,12 @@ struct log_time { static const uint32_t tv_sec_max = 0xFFFFFFFFUL; static const uint32_t tv_nsec_max = 999999999UL; - log_time(const timespec& T) { - tv_sec = static_cast(T.tv_sec); - tv_nsec = static_cast(T.tv_nsec); + log_time(const timespec& T) + : tv_sec(static_cast(T.tv_sec)), + tv_nsec(static_cast(T.tv_nsec)) { } - log_time(uint32_t sec, uint32_t nsec) { - tv_sec = sec; - tv_nsec = nsec; + explicit log_time(uint32_t sec, uint32_t nsec = 0) + : tv_sec(sec), tv_nsec(nsec) { } #ifdef _SYSTEM_CORE_INCLUDE_PRIVATE_ANDROID_LOGGER_H_ #define __struct_log_time_private_defined @@ -56,14 +55,14 @@ struct log_time { log_time() { } #ifdef __linux__ - log_time(clockid_t id) { + explicit log_time(clockid_t id) { timespec T; clock_gettime(id, &T); tv_sec = static_cast(T.tv_sec); tv_nsec = static_cast(T.tv_nsec); } #endif - log_time(const char* T) { + explicit log_time(const char* T) { const uint8_t* c = reinterpret_cast(T); tv_sec = c[0] | (static_cast(c[1]) << 8) | (static_cast(c[2]) << 16) | diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 0c7019ad8..a6bea0cdf 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -43,6 +43,8 @@ // Default #define log_buffer_size(id) mMaxSize[id] +const log_time LogBuffer::pruneMargin(3, 0); + void LogBuffer::init() { log_id_for_each(i) { mLastSet[i] = false; @@ -672,6 +674,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } times++; } + log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max); + if (oldest) watermark = oldest->mStart - pruneMargin; LogBufferElementCollection::iterator it; @@ -693,7 +697,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { oldest->triggerReader_Locked(); @@ -785,7 +789,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { while (it != mLogElements.end()) { LogBufferElement* element = *it; - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { oldest->triggerReader_Locked(); @@ -939,7 +943,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (whitelist) { break; @@ -983,7 +987,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { + if (oldest && (watermark <= element->getRealTime())) { busy = true; if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island @@ -1090,13 +1094,15 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, // client wants to start from the beginning it = mLogElements.begin(); } else { - LogBufferElementCollection::iterator last; // 3 second limit to continue search for out-of-order entries. - log_time min = start - log_time(3, 0); + log_time min = start - pruneMargin; + // Cap to 300 iterations we look back for out-of-order entries. size_t count = 300; + // Client wants to start from some specified time. Chances are // we are better off starting from the end of the time sorted list. + LogBufferElementCollection::iterator last; for (last = it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { --it; @@ -1112,9 +1118,22 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, log_time max = start; + LogBufferElement* lastElement = nullptr; // iterator corruption paranoia + static const size_t maxSkip = 4194304; // maximum entries to skip + size_t skip = maxSkip; for (; it != mLogElements.end(); ++it) { LogBufferElement* element = *it; + if (!--skip) { + android::prdebug("reader.per: too many elements skipped"); + break; + } + if (element == lastElement) { + android::prdebug("reader.per: identical elements"); + break; + } + lastElement = element; + if (!privileged && (element->getUid() != uid)) { continue; } @@ -1159,6 +1178,7 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start, return max; } + skip = maxSkip; pthread_mutex_lock(&mLogElementsLock); } pthread_mutex_unlock(&mLogElementsLock); diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 19d11cb7f..1272c20f6 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -174,6 +174,7 @@ class LogBuffer { private: static constexpr size_t minPrune = 4; static constexpr size_t maxPrune = 256; + static const log_time pruneMargin; void maybePrune(log_id_t id); bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT); diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index 88cb67a96..a1d154ae7 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -670,8 +670,12 @@ TEST(logd, timeout) { while (--i) { int fd = socket_local_client("logdr", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET); - EXPECT_LT(0, fd); - if (fd < 0) _exit(fd); + int save_errno = errno; + if (fd < 0) { + fprintf(stderr, "failed to open /dev/socket/logdr %s\n", + strerror(save_errno)); + _exit(fd); + } std::string ask = android::base::StringPrintf( "dumpAndClose lids=0,1,2,3,4,5 timeout=6 start=%" PRIu32 @@ -723,8 +727,12 @@ TEST(logd, timeout) { // active _or_ inactive during the test. if (content_timeout) { log_time msg(msg_timeout.entry.sec, msg_timeout.entry.nsec); - EXPECT_FALSE(msg < now); - if (msg < now) _exit(-1); + if (msg < now) { + fprintf(stderr, "%u.%09u < %u.%09u\n", msg_timeout.entry.sec, + msg_timeout.entry.nsec, (unsigned)now.tv_sec, + (unsigned)now.tv_nsec); + _exit(-1); + } if (msg > now) { now = msg; now.tv_sec += 30;