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 2b6c27688..1b79e89b9 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -181,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))) { @@ -374,18 +374,12 @@ 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; + log_time end = log_time::EPOCH; bool end_set = false; bool end_always = false; @@ -399,6 +393,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 +402,20 @@ void LogBuffer::log(LogBufferElement* elem) { times++; } - if (end_always || (end_set && (end >= (*last)->getSequence()))) { + if (end_always || (end_set && (end > (*it)->getRealTime()))) { mLogElements.push_back(elem); } else { + // should be short as timestamps are localized near end() + do { + last = it; + if (__predict_false(it == mLogElements.begin())) { + break; + } + --it; + } while (((*it)->getRealTime() > elem->getRealTime()) && + (!end_set || (end <= (*it)->getRealTime()))); mLogElements.insert(last, elem); } - LogTimeEntry::unlock(); } @@ -587,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; @@ -688,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(); @@ -780,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(); @@ -934,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; @@ -978,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 @@ -1071,32 +1074,37 @@ 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; 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 { + 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->getSequence() <= 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 }; @@ -1112,7 +1120,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 43990e835..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; - const 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) {