From f7c0f75275d0fde2d8b7614f1501f0ad0cd3a01c Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 3 Mar 2015 13:39:37 -0800 Subject: [PATCH] logd: replace internal CLOCK_MONOTONIC use with sequence numbers - switch to simpler and faster internal sequence number, drops a syscall overhead on 32-bit platforms. - add ability to break-out of flushTo loop with filter return -1 allowing in reduction in reader overhead. Change-Id: Ic5cb2b9afa4d9470153971fc9197b07279e2b79d --- logd/FlushCommand.cpp | 2 +- logd/FlushCommand.h | 4 ++-- logd/LogBuffer.cpp | 40 ++++++++++++++++++++++----------------- logd/LogBuffer.h | 4 ++-- logd/LogBufferElement.cpp | 9 +++++---- logd/LogBufferElement.h | 11 +++++++---- logd/LogReader.cpp | 38 ++++++++++++++++++------------------- logd/LogTimes.cpp | 24 ++++++++++++----------- logd/LogTimes.h | 11 +++++------ 9 files changed, 77 insertions(+), 66 deletions(-) diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp index 3be07c019..26a18610d 100644 --- a/logd/FlushCommand.cpp +++ b/logd/FlushCommand.cpp @@ -27,7 +27,7 @@ FlushCommand::FlushCommand(LogReader &reader, unsigned long tail, unsigned int logMask, pid_t pid, - log_time start) + uint64_t start) : mReader(reader) , mNonBlock(nonBlock) , mTail(tail) diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h index f34c06a67..61c6858c2 100644 --- a/logd/FlushCommand.h +++ b/logd/FlushCommand.h @@ -31,7 +31,7 @@ class FlushCommand : public SocketClientCommand { unsigned long mTail; unsigned int mLogMask; pid_t mPid; - log_time mStart; + uint64_t mStart; public: FlushCommand(LogReader &mReader, @@ -39,7 +39,7 @@ public: unsigned long tail = -1, unsigned int logMask = -1, pid_t pid = 0, - log_time start = LogTimeEntry::EPOCH); + uint64_t start = 1); virtual void runSocketCommand(SocketClient *client); static bool hasReadLogs(SocketClient *client); diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 2b495abfd..269358386 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -161,7 +161,7 @@ void LogBuffer::log(log_id_t log_id, log_time realtime, if (last == mLogElements.end()) { mLogElements.push_back(elem); } else { - log_time end = log_time::EPOCH; + uint64_t end = 1; bool end_set = false; bool end_always = false; @@ -184,7 +184,7 @@ void LogBuffer::log(log_id_t log_id, log_time realtime, } if (end_always - || (end_set && (end >= (*last)->getMonotonicTime()))) { + || (end_set && (end >= (*last)->getSequence()))) { mLogElements.push_back(elem); } else { mLogElements.insert(last,elem); @@ -241,7 +241,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { for(it = mLogElements.begin(); it != mLogElements.end();) { LogBufferElement *e = *it; - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { + if (oldest && (oldest->mStart <= e->getSequence())) { break; } @@ -293,7 +293,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { for(it = mLogElements.begin(); it != mLogElements.end();) { LogBufferElement *e = *it; - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { + if (oldest && (oldest->mStart <= e->getSequence())) { break; } @@ -334,7 +334,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { while((pruneRows > 0) && (it != mLogElements.end())) { LogBufferElement *e = *it; if (e->getLogId() == id) { - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { + if (oldest && (oldest->mStart <= e->getSequence())) { if (!whitelist) { if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island @@ -366,7 +366,7 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { while((it != mLogElements.end()) && (pruneRows > 0)) { LogBufferElement *e = *it; if (e->getLogId() == id) { - if (oldest && (oldest->mStart <= e->getMonotonicTime())) { + if (oldest && (oldest->mStart <= e->getSequence())) { if (stats.sizes(id) > (2 * log_buffer_size(id))) { // kick a misbehaving log reader client off the island oldest->release_Locked(); @@ -423,16 +423,16 @@ unsigned long LogBuffer::getSize(log_id_t id) { return retval; } -log_time LogBuffer::flushTo( - SocketClient *reader, const log_time start, bool privileged, - bool (*filter)(const LogBufferElement *element, void *arg), void *arg) { +uint64_t LogBuffer::flushTo( + SocketClient *reader, const uint64_t start, bool privileged, + int (*filter)(const LogBufferElement *element, void *arg), void *arg) { LogBufferElementCollection::iterator it; - log_time max = start; + uint64_t max = start; uid_t uid = reader->getUid(); pthread_mutex_lock(&mLogElementsLock); - if (start == LogTimeEntry::EPOCH) { + if (start <= 1) { // client wants to start from the beginning it = mLogElements.begin(); } else { @@ -441,7 +441,7 @@ log_time LogBuffer::flushTo( for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) { --it; LogBufferElement *element = *it; - if (element->getMonotonicTime() <= start) { + if (element->getSequence() <= start) { it++; break; } @@ -455,13 +455,19 @@ log_time LogBuffer::flushTo( continue; } - if (element->getMonotonicTime() <= start) { + if (element->getSequence() <= start) { continue; } // NB: calling out to another object with mLogElementsLock held (safe) - if (filter && !(*filter)(element, arg)) { - continue; + if (filter) { + int ret = (*filter)(element, arg); + if (ret == false) { + continue; + } + if (ret != true) { + break; + } } pthread_mutex_unlock(&mLogElementsLock); @@ -481,7 +487,7 @@ log_time LogBuffer::flushTo( } void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) { - log_time oldest(CLOCK_MONOTONIC); + uint64_t oldest = UINT64_MAX; pthread_mutex_lock(&mLogElementsLock); @@ -491,7 +497,7 @@ void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) { LogBufferElement *element = *it; if ((logMask & (1 << element->getLogId()))) { - oldest = element->getMonotonicTime(); + oldest = element->getSequence(); break; } } diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 86a2a2a68..13e6aa8f6 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -51,9 +51,9 @@ public: void log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char *msg, unsigned short len); - log_time flushTo(SocketClient *writer, const log_time start, + uint64_t flushTo(SocketClient *writer, const uint64_t start, bool privileged, - bool (*filter)(const LogBufferElement *element, void *arg) = NULL, + int (*filter)(const LogBufferElement *element, void *arg) = NULL, void *arg = NULL); void clear(log_id_t id, uid_t uid = AID_ROOT); diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index d959ceb46..5e780b557 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -24,7 +24,8 @@ #include "LogBufferElement.h" #include "LogReader.h" -const log_time LogBufferElement::FLUSH_ERROR((uint32_t)0, (uint32_t)0); +const uint64_t LogBufferElement::FLUSH_ERROR(0); +atomic_int_fast64_t LogBufferElement::sequence; LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, @@ -34,7 +35,7 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, , mPid(pid) , mTid(tid) , mMsgLen(len) - , mMonotonicTime(CLOCK_MONOTONIC) + , mSequence(sequence.fetch_add(1, memory_order_relaxed)) , mRealTime(realtime) { mMsg = new char[len]; memcpy(mMsg, msg, len); @@ -44,7 +45,7 @@ LogBufferElement::~LogBufferElement() { delete [] mMsg; } -log_time LogBufferElement::flushTo(SocketClient *reader) { +uint64_t LogBufferElement::flushTo(SocketClient *reader) { struct logger_entry_v3 entry; memset(&entry, 0, sizeof(struct logger_entry_v3)); entry.hdr_size = sizeof(struct logger_entry_v3); @@ -64,5 +65,5 @@ log_time LogBufferElement::flushTo(SocketClient *reader) { return FLUSH_ERROR; } - return mMonotonicTime; + return mSequence; } diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index fdca973fe..25f145082 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -18,6 +18,7 @@ #define _LOGD_LOG_BUFFER_ELEMENT_H__ #include +#include #include #include #include @@ -29,8 +30,9 @@ class LogBufferElement { const pid_t mTid; char *mMsg; const unsigned short mMsgLen; - const log_time mMonotonicTime; + const uint64_t mSequence; const log_time mRealTime; + static atomic_int_fast64_t sequence; public: LogBufferElement(log_id_t log_id, log_time realtime, @@ -43,11 +45,12 @@ public: pid_t getPid(void) const { return mPid; } pid_t getTid(void) const { return mTid; } unsigned short getMsgLen() const { return mMsgLen; } - log_time getMonotonicTime(void) const { return mMonotonicTime; } + 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 log_time FLUSH_ERROR; - log_time flushTo(SocketClient *writer); + static const uint64_t FLUSH_ERROR; + uint64_t flushTo(SocketClient *writer); }; #endif diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 26df0873f..f7df27558 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -100,50 +100,51 @@ bool LogReader::onDataAvailable(SocketClient *cli) { nonBlock = true; } - // Convert realtime to monotonic time - if (start == log_time::EPOCH) { - start = LogTimeEntry::EPOCH; - } else { + uint64_t sequence = 1; + // Convert realtime to sequence number + if (start != log_time::EPOCH) { class LogFindStart { const pid_t mPid; const unsigned mLogMask; bool startTimeSet; log_time &start; - log_time last; + uint64_t &sequence; + uint64_t last; public: - LogFindStart(unsigned logMask, pid_t pid, log_time &start) + LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence) : mPid(pid) , mLogMask(logMask) , startTimeSet(false) , start(start) - , last(LogTimeEntry::EPOCH) + , sequence(sequence) + , last(sequence) { } - static bool callback(const LogBufferElement *element, void *obj) { + static int callback(const LogBufferElement *element, void *obj) { LogFindStart *me = reinterpret_cast(obj); - if (!me->startTimeSet - && (!me->mPid || (me->mPid == element->getPid())) + if ((!me->mPid || (me->mPid == element->getPid())) && (me->mLogMask & (1 << element->getLogId()))) { if (me->start == element->getRealTime()) { - me->start = element->getMonotonicTime(); + me->sequence = element->getSequence(); me->startTimeSet = true; + return -1; } else { if (me->start < element->getRealTime()) { - me->start = me->last; + me->sequence = me->last; me->startTimeSet = true; + return -1; } - me->last = element->getMonotonicTime(); + me->last = element->getSequence(); } } return false; } bool found() { return startTimeSet; } - } logFindStart(logMask, pid, start); + } logFindStart(logMask, pid, start, sequence); - logbuf().flushTo(cli, LogTimeEntry::EPOCH, - FlushCommand::hasReadLogs(cli), + logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli), logFindStart.callback, &logFindStart); if (!logFindStart.found()) { @@ -151,12 +152,11 @@ bool LogReader::onDataAvailable(SocketClient *cli) { doSocketDelete(cli); return false; } - log_time now(CLOCK_MONOTONIC); - start = now; + sequence = LogBufferElement::getCurrentSequence(); } } - FlushCommand command(*this, nonBlock, tail, logMask, pid, start); + FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence); command.runSocketCommand(cli); return true; } diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp index 5f9db8da5..1b60b7ead 100644 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -23,12 +23,10 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER; -const struct timespec LogTimeEntry::EPOCH = { 0, 1 }; - LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - log_time start) + uint64_t start) : mRefCount(1) , mRelease(false) , mError(false) @@ -42,7 +40,7 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client, , mClient(client) , mStart(start) , mNonBlock(nonBlock) - , mEnd(CLOCK_MONOTONIC) + , mEnd(LogBufferElement::getCurrentSequence()) { pthread_cond_init(&threadTriggeredCondition, NULL); cleanSkip_Locked(); @@ -129,7 +127,7 @@ void *LogTimeEntry::threadStart(void *obj) { lock(); while (me->threadRunning && !me->isError_Locked()) { - log_time start = me->mStart; + uint64_t start = me->mStart; unlock(); @@ -161,13 +159,13 @@ void *LogTimeEntry::threadStart(void *obj) { } // A first pass to count the number of elements -bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { +int LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { LogTimeEntry *me = reinterpret_cast(obj); LogTimeEntry::lock(); if (me->mCount == 0) { - me->mStart = element->getMonotonicTime(); + me->mStart = element->getSequence(); } if ((!me->mPid || (me->mPid == element->getPid())) @@ -181,12 +179,12 @@ bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) { } // A second pass to send the selected elements -bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) { +int LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) { LogTimeEntry *me = reinterpret_cast(obj); LogTimeEntry::lock(); - me->mStart = element->getMonotonicTime(); + me->mStart = element->getSequence(); if (me->skipAhead[element->getLogId()]) { me->skipAhead[element->getLogId()]--; @@ -195,7 +193,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) // Truncate to close race between first and second pass if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) { - goto skip; + goto stop; } if (!me->isWatching(element->getLogId())) { @@ -207,7 +205,7 @@ bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) } if (me->isError_Locked()) { - goto skip; + goto stop; } if (!me->mTail) { @@ -234,6 +232,10 @@ ok: skip: LogTimeEntry::unlock(); return false; + +stop: + LogTimeEntry::unlock(); + return -1; } void LogTimeEntry::cleanSkip_Locked(void) { diff --git a/logd/LogTimes.h b/logd/LogTimes.h index 81aedfb68..ae2f92b34 100644 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -47,13 +47,12 @@ class LogTimeEntry { public: LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock, unsigned long tail, unsigned int logMask, pid_t pid, - log_time start); + uint64_t start); SocketClient *mClient; - static const struct timespec EPOCH; - log_time mStart; + uint64_t mStart; const bool mNonBlock; - const log_time mEnd; // only relevant if mNonBlock + const uint64_t mEnd; // only relevant if mNonBlock // Protect List manipulations static void lock(void) { pthread_mutex_lock(×Lock); } @@ -103,8 +102,8 @@ public: } bool isWatching(log_id_t id) { return (mLogMask & (1< LastLogTimes;