From 5836379b2114f47c53485b42ab157104c29b2c4e Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 17 Apr 2017 12:46:12 -0700 Subject: [PATCH] logd: regression in handling watermark boundary. Deal with a regression introduced in commit 5a34d6ea43d28f3b5d27bf6dd5b9fa31ec033531 (logd: drop mSequence from LogBufferElement) where log_time was compared against nsec() time miscalculating the watermark boundary. When dealing with logcat -t/-T, or any tail reading, add a margin to prune to back off by a period of 3 seconds (pruneMargin). Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests Bug: 37378309 Change-Id: I72ea858e4e7b5fa91741ea84c40d2e7c3c4aa031 --- logd/LogBuffer.cpp | 18 ++++++++++++------ logd/LogBuffer.h | 1 + 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 0c7019ad8..4a790c9f5 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; 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);