From da6495d06f1798ea81cebbfbdd44f16135e1a3cd Mon Sep 17 00:00:00 2001 From: TraianX Schiau Date: Wed, 17 Dec 2014 10:53:41 +0200 Subject: [PATCH] logd: Fix pruning In a scenario in which an on-line (blocking) client is running and a clean is attempted (logcat -c), the following can be observed: 1) the on-line logger seems to freeze 2) any other clear attempt will have no effect What is actually happening: In this case prune function will "instruct" the oldest timeEntry to skip a huge number (very close to ULONG_MAX) of messages, this being the cause of 1. Since the consumer thread will skip all the log entries, mStart updating will also be skipped. So a new cleaning attempt will have the same oldest entry, nothing will be done. Fix description: a. keep a separated skipAhead count for individual log buffers (log_id_t) LogTimeEntry::LogTimeEntry LogTimeEntry::FilterSecondPass LogTimeEntry::skipAhead LogTimeEntry::riggerSkip_Locked b. update LogTimeEntry::mStart even if the current message is skipped LogTimeEntry::FilterSecondPass c. while pruning, only take into account the LogTimeEntrys that are monitoring the log_id in question, and provide a public method of checking this. LogTimeEntry::isWatching LogTimeEntry::FilterFirstPass LogTimeEntry::FilterSecondPass d. Reset the skip cont befor the client thtread starts to sleep, at this point we should be up to date. LogTimeEntry::cleanSkip_Locked LogTimeEntry::threadStart Change-Id: I1b369dc5b02476e633e52578266a644e37e188a5 Signed-off-by: TraianX Schiau --- logd/LogBuffer.cpp | 6 +++--- logd/LogTimes.cpp | 24 ++++++++++++++++-------- logd/LogTimes.h | 8 +++++--- 3 files changed, 24 insertions(+), 14 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 1c74ba5ac..6307bed63 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -242,7 +242,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { LastLogTimes::iterator t = mTimes.begin(); while(t != mTimes.end()) { LogTimeEntry *entry = (*t); - if (entry->owned_Locked() + if (entry->owned_Locked() && entry->isWatching(id) && (!oldest || (oldest->mStart > entry->mStart))) { oldest = entry; } @@ -354,7 +354,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { // kick a misbehaving log reader client off the island oldest->release_Locked(); } else { - oldest->triggerSkip_Locked(pruneRows); + oldest->triggerSkip_Locked(id, pruneRows); } } break; @@ -385,7 +385,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { // kick a misbehaving log reader client off the island oldest->release_Locked(); } else { - oldest->triggerSkip_Locked(pruneRows); + oldest->triggerSkip_Locked(id, pruneRows); } break; } diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index ea4e8c83d..5f9db8da5 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -36,7 +36,6 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, , mReader(reader) , mLogMask(logMask) , mPid(pid) - , skipAhead(0) , mCount(0) , mTail(tail) , mIndex(0) @@ -46,6 +45,7 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, , mEnd(CLOCK_MONOTONIC) { pthread_cond_init(&threadTriggeredCondition, NULL); + cleanSkip_Locked(); } void LogTimeEntry::startReader_Locked(void) { @@ -148,6 +148,8 @@ void *LogTimeEntry::threadStart(void *obj) { break; } + me->cleanSkip_Locked(); + pthread_cond_wait(&me->threadTriggeredCondition, ×Lock); } @@ -169,7 +171,7 @@ bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { } if ((!me->mPid || (me->mPid == element->getPid())) - && (me->mLogMask & (1 << element->getLogId()))) { + && (me->isWatching(element->getLogId()))) { ++me->mCount; } @@ -184,19 +186,19 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) LogTimeEntry::lock(); - if (me->skipAhead) { - me->skipAhead--; + me->mStart = element->getMonotonicTime(); + + if (me->skipAhead[element->getLogId()]) { + me->skipAhead[element->getLogId()]--; goto skip; } - me->mStart = element->getMonotonicTime(); - // Truncate to close race between first and second pass if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) { goto skip; } - if ((me->mLogMask & (1 << element->getLogId())) == 0) { + if (!me->isWatching(element->getLogId())) { goto skip; } @@ -223,7 +225,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) } ok: - if (!me->skipAhead) { + if (!me->skipAhead[element->getLogId()]) { LogTimeEntry::unlock(); return true; } @@ -233,3 +235,9 @@ skip: LogTimeEntry::unlock(); return false; } + +void LogTimeEntry::cleanSkip_Locked(void) { + for (log_id_t i = LOG_ID_MIN; i < LOG_ID_MAX; i = (log_id_t) (i + 1)) { + skipAhead[i] = 0; + } +} diff --git a/logd/LogTimes.h b/logd/LogTimes.h index 0bfa7a22f..81aedfb68 100644 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -22,6 +22,7 @@ #include #include #include +#include class LogReader; @@ -38,7 +39,7 @@ class LogTimeEntry { static void threadStop(void *me); const unsigned int mLogMask; const pid_t mPid; - unsigned int skipAhead; + unsigned int skipAhead[LOG_ID_MAX]; unsigned long mCount; unsigned long mTail; unsigned long mIndex; @@ -67,7 +68,8 @@ public: pthread_cond_signal(&threadTriggeredCondition); } - void triggerSkip_Locked(unsigned int skip) { skipAhead = skip; } + void triggerSkip_Locked(log_id_t id, unsigned int skip) { skipAhead[id] = skip; } + void cleanSkip_Locked(void); // Called after LogTimeEntry removed from list, lock implicitly held void release_Locked(void) { @@ -99,7 +101,7 @@ public: // No one else is holding a reference to this delete this; } - + bool isWatching(log_id_t id) { return (mLogMask & (1<