From 1d84f0b2afd36c4a6a367761c3d518789a424419 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Fri, 3 Mar 2017 10:21:23 -0800 Subject: [PATCH 1/3] logd: ensure LogBufferElement mSequence is monotonic - Improves accuracy of -t/-T '' behavior when out of order arrival of entries messes with mSequence as the list will now have monotonic sequence numbers enforced. - Out of order time entries still remain because of reader requiring the ability to receive newly arrived old entries. - -t/-T '' can still quit backward search prematurely because an old entry lands later in the list. - Adjust insert in place algorithm from two loops of scan placement and then limit against watermark, into one that does all of that plus iteratively swap update the sequence numbers to set monotonicity. Side effect will be that the read lock (which is actually the LogTimes lock) will be held longer while we search for a placement above the youngest LogTimes watermark. We need to hold the read (LogTimes) lock because we may be altering the sequence numbers affecting -t/-T '' search. Test: gTest logd-unit-tests liblog-unit-tests logcat-unit-tests Bug: 35373582 Change-Id: I79a385fc149bac2179128b53d4c8f71e429181ae --- logd/LogBuffer.cpp | 29 ++++++++++++++++++----------- logd/LogBufferElement.h | 2 +- 2 files changed, 19 insertions(+), 12 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 2b6c27688..fbd04ef8c 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -27,6 +27,7 @@ #include #include +#include #include #include @@ -374,15 +375,9 @@ void LogBuffer::log(LogBufferElement* elem) { // NB: if end is region locked, place element at end of list LogBufferElementCollection::iterator it = mLogElements.end(); LogBufferElementCollection::iterator last = it; - while (last != mLogElements.begin()) { - --it; - if ((*it)->getRealTime() <= elem->getRealTime()) { - break; - } - last = it; - } - - if (last == mLogElements.end()) { + if (__predict_true(it != mLogElements.begin())) --it; + if (__predict_false(it == mLogElements.begin()) || + __predict_true((*it)->getRealTime() <= elem->getRealTime())) { mLogElements.push_back(elem); } else { uint64_t end = 1; @@ -399,6 +394,7 @@ void LogBuffer::log(LogBufferElement* elem) { end_always = true; break; } + // it passing mEnd is blocked by the following checks. if (!end_set || (end <= entry->mEnd)) { end = entry->mEnd; end_set = true; @@ -407,12 +403,23 @@ void LogBuffer::log(LogBufferElement* elem) { times++; } - if (end_always || (end_set && (end >= (*last)->getSequence()))) { + if (end_always || (end_set && (end > (*it)->getSequence()))) { mLogElements.push_back(elem); } else { + // should be short as timestamps are localized near end() + do { + last = it; + if (__predict_false(it == mLogElements.begin())) { + break; + } + + std::swap((*it)->mSequence, elem->mSequence); + + --it; + } while (((*it)->getRealTime() > elem->getRealTime()) && + (!end_set || (end <= (*it)->getSequence()))); mLogElements.insert(last, elem); } - LogTimeEntry::unlock(); } diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 43990e835..90756dd4b 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -40,7 +40,7 @@ class LogBufferElement { const uint32_t mUid; const uint32_t mPid; const uint32_t mTid; - const uint64_t mSequence; + uint64_t mSequence; log_time mRealTime; char* mMsg; union { From 5a34d6ea43d28f3b5d27bf6dd5b9fa31ec033531 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Fri, 10 Mar 2017 08:44:14 -0800 Subject: [PATCH 2/3] logd: drop mSequence from LogBufferElement Use getRealTime() instead and leverage private liblog log_time comparison and math functions. This saves 8 bytes off each element in the logging database. Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests Bug: 35373582 Change-Id: Ia55ef8b95cbb2a841ccb1dae9a24f314735b076a --- logd/FlushCommand.cpp | 4 +-- logd/FlushCommand.h | 6 ++-- logd/LogBuffer.cpp | 38 +++++++++----------- logd/LogBuffer.h | 2 +- logd/LogBufferElement.cpp | 10 +++--- logd/LogBufferElement.h | 11 ++---- logd/LogReader.cpp | 76 ++++++++++++++++++++++----------------- logd/LogTimes.cpp | 14 ++++---- logd/LogTimes.h | 6 ++-- 9 files changed, 83 insertions(+), 84 deletions(-) diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp index 5a5c0d981..ff6bff8eb 100644 --- a/logd/FlushCommand.cpp +++ b/logd/FlushCommand.cpp @@ -27,7 +27,7 @@ #include "LogUtils.h" FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail, - unsigned int logMask, pid_t pid, uint64_t start, + unsigned int logMask, pid_t pid, log_time start, uint64_t timeout) : mReader(reader), mNonBlock(nonBlock), @@ -35,7 +35,7 @@ FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail, mLogMask(logMask), mPid(pid), mStart(start), - mTimeout((start > 1) ? timeout : 0) { + mTimeout((start != log_time::EPOCH) ? timeout : 0) { } // runSocketCommand is called once for every open client on the diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h index 45cb9c509..7cdd03fdb 100644 --- a/logd/FlushCommand.h +++ b/logd/FlushCommand.h @@ -16,7 +16,7 @@ #ifndef _FLUSH_COMMAND_H #define _FLUSH_COMMAND_H -#include +#include #include class LogBufferElement; @@ -31,13 +31,13 @@ class FlushCommand : public SocketClientCommand { unsigned long mTail; unsigned int mLogMask; pid_t mPid; - uint64_t mStart; + log_time mStart; uint64_t mTimeout; public: explicit FlushCommand(LogReader& mReader, bool nonBlock = false, unsigned long tail = -1, unsigned int logMask = -1, - pid_t pid = 0, uint64_t start = 1, + pid_t pid = 0, log_time start = log_time::EPOCH, uint64_t timeout = 0); virtual void runSocketCommand(SocketClient* client); diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index fbd04ef8c..0759e7afb 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -27,7 +27,6 @@ #include #include -#include #include #include @@ -182,7 +181,7 @@ static enum match_type identical(LogBufferElement* elem, lenr -= avcr - msgr; if (lenl != lenr) return DIFFERENT; // TODO: After b/35468874 is addressed, revisit "lenl > strlen(avc)" - // condition, it might become superflous. + // condition, it might become superfluous. if (lenl > strlen(avc) && fastcmp(avcl + strlen(avc), avcr + strlen(avc), lenl - strlen(avc))) { @@ -380,7 +379,7 @@ void LogBuffer::log(LogBufferElement* elem) { __predict_true((*it)->getRealTime() <= elem->getRealTime())) { mLogElements.push_back(elem); } else { - uint64_t end = 1; + log_time end = log_time::EPOCH; bool end_set = false; bool end_always = false; @@ -403,7 +402,7 @@ void LogBuffer::log(LogBufferElement* elem) { times++; } - if (end_always || (end_set && (end > (*it)->getSequence()))) { + if (end_always || (end_set && (end > (*it)->getRealTime()))) { mLogElements.push_back(elem); } else { // should be short as timestamps are localized near end() @@ -412,12 +411,9 @@ void LogBuffer::log(LogBufferElement* elem) { if (__predict_false(it == mLogElements.begin())) { break; } - - std::swap((*it)->mSequence, elem->mSequence); - --it; } while (((*it)->getRealTime() > elem->getRealTime()) && - (!end_set || (end <= (*it)->getSequence()))); + (!end_set || (end <= (*it)->getRealTime()))); mLogElements.insert(last, elem); } LogTimeEntry::unlock(); @@ -594,12 +590,12 @@ class LogBufferElementLast { } void clear(LogBufferElement* element) { - uint64_t current = - element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC); + log_time current = + element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0); for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) { LogBufferElement* mapElement = it->second; if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) && - (current > mapElement->getRealTime().nsec())) { + (current > mapElement->getRealTime())) { it = map.erase(it); } else { ++it; @@ -695,7 +691,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getSequence())) { + if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { busy = true; if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { oldest->triggerReader_Locked(); @@ -787,7 +783,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->getSequence())) { + if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { busy = true; if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) { oldest->triggerReader_Locked(); @@ -941,7 +937,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getSequence())) { + if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { busy = true; if (whitelist) { break; @@ -985,7 +981,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { mLastSet[id] = true; } - if (oldest && (oldest->mStart <= element->getSequence())) { + if (oldest && (oldest->mStart <= element->getRealTime().nsec())) { busy = true; if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island @@ -1078,16 +1074,16 @@ unsigned long LogBuffer::getSize(log_id_t id) { return retval; } -uint64_t LogBuffer::flushTo( - SocketClient* reader, const uint64_t start, bool privileged, bool security, +log_time LogBuffer::flushTo( + SocketClient* reader, const log_time& start, bool privileged, bool security, int (*filter)(const LogBufferElement* element, void* arg), void* arg) { LogBufferElementCollection::iterator it; - uint64_t max = start; + log_time max = start; uid_t uid = reader->getUid(); pthread_mutex_lock(&mLogElementsLock); - if (start <= 1) { + if (start == log_time::EPOCH) { // client wants to start from the beginning it = mLogElements.begin(); } else { @@ -1097,7 +1093,7 @@ uint64_t LogBuffer::flushTo( /* do nothing */) { --it; LogBufferElement* element = *it; - if (element->getSequence() <= start) { + if (element->getRealTime() <= start) { it++; break; } @@ -1119,7 +1115,7 @@ uint64_t LogBuffer::flushTo( continue; } - if (element->getSequence() <= start) { + if (element->getRealTime() <= start) { continue; } diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 92b0297e2..fcf6b9a22 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -115,7 +115,7 @@ class LogBuffer { int log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char* msg, unsigned short len); - uint64_t flushTo(SocketClient* writer, const uint64_t start, + log_time flushTo(SocketClient* writer, const log_time& start, bool privileged, bool security, int (*filter)(const LogBufferElement* element, void* arg) = NULL, diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index 5ba3a1514..81356fea5 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -30,7 +30,7 @@ #include "LogReader.h" #include "LogUtils.h" -const uint64_t LogBufferElement::FLUSH_ERROR(0); +const log_time LogBufferElement::FLUSH_ERROR((uint32_t)-1, (uint32_t)-1); atomic_int_fast64_t LogBufferElement::sequence(1); LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, @@ -39,7 +39,6 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, : mUid(uid), mPid(pid), mTid(tid), - mSequence(sequence.fetch_add(1, memory_order_relaxed)), mRealTime(realtime), mMsgLen(len), mLogId(log_id) { @@ -55,7 +54,6 @@ LogBufferElement::LogBufferElement(const LogBufferElement& elem) mUid(elem.mUid), mPid(elem.mPid), mTid(elem.mTid), - mSequence(elem.mSequence), mRealTime(elem.mRealTime), mMsgLen(elem.mMsgLen), mLogId(elem.mLogId) { @@ -206,7 +204,7 @@ size_t LogBufferElement::populateDroppedMessage(char*& buffer, LogBuffer* parent return retval; } -uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, +log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool privileged, bool lastSame) { struct logger_entry_v4 entry; @@ -229,7 +227,7 @@ uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, if (!mMsg) { entry.len = populateDroppedMessage(buffer, parent, lastSame); - if (!entry.len) return mSequence; + if (!entry.len) return mRealTime; iovec[1].iov_base = buffer; } else { entry.len = mMsgLen; @@ -237,7 +235,7 @@ uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, } iovec[1].iov_len = entry.len; - uint64_t retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mSequence; + log_time retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mRealTime; if (buffer) free(buffer); diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 90756dd4b..814ec8785 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -40,7 +40,6 @@ class LogBufferElement { const uint32_t mUid; const uint32_t mPid; const uint32_t mTid; - uint64_t mSequence; log_time mRealTime; char* mMsg; union { @@ -96,18 +95,12 @@ class LogBufferElement { const char* getMsg() const { return mMsg; } - uint64_t getSequence(void) const { - return mSequence; - } - static uint64_t getCurrentSequence(void) { - return sequence.load(memory_order_relaxed); - } log_time getRealTime(void) const { return mRealTime; } - static const uint64_t FLUSH_ERROR; - uint64_t flushTo(SocketClient* writer, LogBuffer* parent, bool privileged, + static const log_time FLUSH_ERROR; + log_time flushTo(SocketClient* writer, LogBuffer* parent, bool privileged, bool lastSame); }; diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 76f5798c6..620d4d047 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -116,57 +116,70 @@ bool LogReader::onDataAvailable(SocketClient* cli) { nonBlock = true; } - uint64_t sequence = 1; - // Convert realtime to sequence number - if (start != log_time::EPOCH) { - class LogFindStart { + log_time sequence = start; + // + // This somewhat expensive data validation operation is required + // for non-blocking, with timeout. The incoming timestamp must be + // in range of the list, if not, return immediately. This is + // used to prevent us from from getting stuck in timeout processing + // with an invalid time. + // + // Find if time is really present in the logs, monotonic or real, implicit + // conversion from monotonic or real as necessary to perform the check. + // Exit in the check loop ASAP as you find a transition from older to + // newer, but use the last entry found to ensure overlap. + // + if (nonBlock && (sequence != log_time::EPOCH) && timeout) { + class LogFindStart { // A lambda by another name + private: const pid_t mPid; const unsigned mLogMask; - bool startTimeSet; - log_time& start; - uint64_t& sequence; - uint64_t last; - bool isMonotonic; + bool mStartTimeSet; + log_time mStart; + log_time& mSequence; + log_time mLast; + bool mIsMonotonic; public: - LogFindStart(unsigned logMask, pid_t pid, log_time& start, - uint64_t& sequence, bool isMonotonic) + LogFindStart(pid_t pid, unsigned logMask, log_time& sequence, + bool isMonotonic) : mPid(pid), mLogMask(logMask), - startTimeSet(false), - start(start), - sequence(sequence), - last(sequence), - isMonotonic(isMonotonic) { + mStartTimeSet(false), + mStart(sequence), + mSequence(sequence), + mLast(sequence), + mIsMonotonic(isMonotonic) { } static int callback(const LogBufferElement* element, void* obj) { LogFindStart* me = reinterpret_cast(obj); if ((!me->mPid || (me->mPid == element->getPid())) && (me->mLogMask & (1 << element->getLogId()))) { - if (me->start == element->getRealTime()) { - me->sequence = element->getSequence(); - me->startTimeSet = true; + log_time real = element->getRealTime(); + if (me->mStart == real) { + me->mSequence = real; + me->mStartTimeSet = true; return -1; - } else if (!me->isMonotonic || - android::isMonotonic(element->getRealTime())) { - if (me->start < element->getRealTime()) { - me->sequence = me->last; - me->startTimeSet = true; + } else if (!me->mIsMonotonic || android::isMonotonic(real)) { + if (me->mStart < real) { + me->mSequence = me->mLast; + me->mStartTimeSet = true; return -1; } - me->last = element->getSequence(); + me->mLast = real; } else { - me->last = element->getSequence(); + me->mLast = real; } } return false; } bool found() { - return startTimeSet; + return mStartTimeSet; } - } logFindStart(logMask, pid, start, sequence, + + } logFindStart(pid, logMask, sequence, logbuf().isMonotonic() && android::isMonotonic(start)); logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli), @@ -174,11 +187,8 @@ bool LogReader::onDataAvailable(SocketClient* cli) { logFindStart.callback, &logFindStart); if (!logFindStart.found()) { - if (nonBlock) { - doSocketDelete(cli); - return false; - } - sequence = LogBufferElement::getCurrentSequence(); + doSocketDelete(cli); + return false; } } diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index bdaeb751c..04e531f86 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -17,6 +17,8 @@ #include #include +#include + #include "FlushCommand.h" #include "LogBuffer.h" #include "LogReader.h" @@ -26,7 +28,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER; LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, unsigned long tail, - unsigned int logMask, pid_t pid, uint64_t start, + unsigned int logMask, pid_t pid, log_time start, uint64_t timeout) : mRefCount(1), mRelease(false), @@ -42,7 +44,7 @@ LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, mClient(client), mStart(start), mNonBlock(nonBlock), - mEnd(LogBufferElement::getCurrentSequence()) { + mEnd(log_time(android_log_clockid())) { mTimeout.tv_sec = timeout / NS_PER_SEC; mTimeout.tv_nsec = timeout % NS_PER_SEC; pthread_cond_init(&threadTriggeredCondition, NULL); @@ -132,7 +134,7 @@ void* LogTimeEntry::threadStart(void* obj) { lock(); - uint64_t start = me->mStart; + log_time start = me->mStart; while (me->threadRunning && !me->isError_Locked()) { if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) { @@ -163,7 +165,7 @@ void* LogTimeEntry::threadStart(void* obj) { break; } - me->mStart = start + 1; + me->mStart = start + log_time(0, 1); if (me->mNonBlock || !me->threadRunning || me->isError_Locked()) { break; @@ -198,7 +200,7 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement* element, void* obj) { } if (me->mCount == 0) { - me->mStart = element->getSequence(); + me->mStart = element->getRealTime(); } if ((!me->mPid || (me->mPid == element->getPid())) && @@ -217,7 +219,7 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) { LogTimeEntry::lock(); - me->mStart = element->getSequence(); + me->mStart = element->getRealTime(); if (me->skipAhead[element->getLogId()]) { me->skipAhead[element->getLogId()]--; diff --git a/logd/LogTimes.h b/logd/LogTimes.h index 23fdf4eea..9a3ddab39 100644 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -51,13 +51,13 @@ class LogTimeEntry { public: LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - uint64_t start, uint64_t timeout); + log_time start, uint64_t timeout); SocketClient* mClient; - uint64_t mStart; + log_time mStart; struct timespec mTimeout; const bool mNonBlock; - const uint64_t mEnd; // only relevant if mNonBlock + const log_time mEnd; // only relevant if mNonBlock // Protect List manipulations static void lock(void) { From 3b941d457b7071254a2e68e86db06edf86754ddf Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Fri, 10 Mar 2017 10:31:48 -0800 Subject: [PATCH 3/3] logd: continue search out-of-order entries timestamp tail Regression from commit 8e8e8db549ffa6e692246abce6f5560c3a1e93c2 For liblogcat reader -t or -T tail requests, continue search for pertinent out-of-order entries for an additional 30 seconds back into logging history to find a more inclusive starting point. For example, if you have an out of order landing like [..., 3, 6, 1, 8, 2, 5] and ask for 3 you used to get only 5, and now you get 3, 6, 8, 5 as 'expected' Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests Bug: 35373582 Change-Id: I2a0732933fa371aed383d49c8d48d01f33db2a79 --- logd/LogBuffer.cpp | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 0759e7afb..1b79e89b9 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -1078,7 +1078,6 @@ log_time LogBuffer::flushTo( SocketClient* reader, const log_time& start, bool privileged, bool security, int (*filter)(const LogBufferElement* element, void* arg), void* arg) { LogBufferElementCollection::iterator it; - log_time max = start; uid_t uid = reader->getUid(); pthread_mutex_lock(&mLogElementsLock); @@ -1087,19 +1086,25 @@ log_time LogBuffer::flushTo( // client wants to start from the beginning it = mLogElements.begin(); } else { + LogBufferElementCollection::iterator last = mLogElements.begin(); + // 30 second limit to continue search for out-of-order entries. + log_time min = start - log_time(30, 0); // Client wants to start from some specified time. Chances are // we are better off starting from the end of the time sorted list. for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { --it; LogBufferElement* element = *it; - if (element->getRealTime() <= start) { - it++; + if (element->getRealTime() > start) { + last = it; + } else if (element->getRealTime() < min) { break; } } + it = last; } + log_time max = start; // Help detect if the valid message before is from the same source so // we can differentiate chatty filter types. pid_t lastTid[LOG_ID_MAX] = { 0 };