From f6e229695375bda653a7f1b6f2470e054dc2d6bf Mon Sep 17 00:00:00 2001 From: Hao Wang Date: Mon, 4 Dec 2017 14:10:40 +0800 Subject: [PATCH] logd: enhance multiple blocking readers performance MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit logd suffers performance degradation when multiple blocking readers connect to it. Each time when the writer thread log new entries, all of the readers are notified regardless of which log id they are watching. In this case, only give notification to the readers who are actually watching new entries' log id. This decreases logd CPU consumption by skipping unnecessary LogBuffer::flushTo loops. Test: liblog-unit-tests, logd-unit-tests & CtsLiblogTestCases logcat-unit-tests Test: manual: 1.'logcat –b all' at constant heavy logging load level 2.simultaneously 'logcat –b crash' in another session, a healthy crash buffer usually keep empty 3.logd CPU consumption doesn't increase after step 2 Change-Id: I4ffc045c9feb7a0998f7e47ae2173f8f6aa28e8a --- logd/FlushCommand.cpp | 16 ++++------------ logd/FlushCommand.h | 30 +++++++++++++++++++++++++----- logd/LogAudit.cpp | 8 ++++---- logd/LogKlog.cpp | 2 +- logd/LogListener.cpp | 12 ++++++------ logd/LogReader.cpp | 6 +++--- logd/LogReader.h | 4 +++- logd/LogTimes.cpp | 5 ++--- logd/LogTimes.h | 13 +++++++++---- 9 files changed, 57 insertions(+), 39 deletions(-) mode change 100644 => 100755 logd/FlushCommand.cpp mode change 100644 => 100755 logd/FlushCommand.h mode change 100644 => 100755 logd/LogAudit.cpp mode change 100644 => 100755 logd/LogKlog.cpp mode change 100644 => 100755 logd/LogListener.cpp mode change 100644 => 100755 logd/LogReader.cpp mode change 100644 => 100755 logd/LogReader.h mode change 100644 => 100755 logd/LogTimes.cpp mode change 100644 => 100755 logd/LogTimes.h diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp old mode 100644 new mode 100755 index a9edc3ee6..70ecbe0a5 --- a/logd/FlushCommand.cpp +++ b/logd/FlushCommand.cpp @@ -26,18 +26,6 @@ #include "LogTimes.h" #include "LogUtils.h" -FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail, - unsigned int logMask, pid_t pid, log_time start, - uint64_t timeout) - : mReader(reader), - mNonBlock(nonBlock), - mTail(tail), - mLogMask(logMask), - mPid(pid), - mStart(start), - mTimeout((start != log_time::EPOCH) ? timeout : 0) { -} - // runSocketCommand is called once for every open client on the // log reader socket. Here we manage and associated the reader // client tracking and log region locks LastLogTimes list of @@ -56,6 +44,10 @@ void FlushCommand::runSocketCommand(SocketClient* client) { while (it != times.end()) { entry = (*it); if (entry->mClient == client) { + if (!entry->isWatchingMultiple(mLogMask)) { + LogTimeEntry::unlock(); + return; + } if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) { if (mReader.logbuf().isMonotonic()) { LogTimeEntry::unlock(); diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h old mode 100644 new mode 100755 index 7cdd03fdb..543dfc3d7 --- a/logd/FlushCommand.h +++ b/logd/FlushCommand.h @@ -29,16 +29,36 @@ class FlushCommand : public SocketClientCommand { LogReader& mReader; bool mNonBlock; unsigned long mTail; - unsigned int mLogMask; + log_mask_t mLogMask; pid_t mPid; 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, log_time start = log_time::EPOCH, - uint64_t timeout = 0); + // for opening a reader + explicit FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail, + log_mask_t logMask, pid_t pid, log_time start, + uint64_t timeout) + : mReader(reader), + mNonBlock(nonBlock), + mTail(tail), + mLogMask(logMask), + mPid(pid), + mStart(start), + mTimeout((start != log_time::EPOCH) ? timeout : 0) { + } + + // for notification of an update + explicit FlushCommand(LogReader& reader, log_mask_t logMask) + : mReader(reader), + mNonBlock(false), + mTail(-1), + mLogMask(logMask), + mPid(0), + mStart(log_time::EPOCH), + mTimeout(0) { + } + virtual void runSocketCommand(SocketClient* client); static bool hasReadLogs(SocketClient* client); diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp old mode 100644 new mode 100755 index cfcbaa5a8..1d0cc334a --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -365,7 +365,7 @@ int LogAudit::logPrint(const char* fmt, ...) { : LOGGER_ENTRY_MAX_PAYLOAD; size_t message_len = str_len + sizeof(android_log_event_string_t); - bool notify = false; + log_mask_t notify = 0; if (events) { // begin scope for event buffer uint32_t buffer[(message_len + sizeof(uint32_t) - 1) / sizeof(uint32_t)]; @@ -384,7 +384,7 @@ int LogAudit::logPrint(const char* fmt, ...) { (message_len <= USHRT_MAX) ? (unsigned short)message_len : USHRT_MAX); if (rc >= 0) { - notify = true; + notify |= 1 << LOG_ID_EVENTS; } // end scope for event buffer } @@ -440,7 +440,7 @@ int LogAudit::logPrint(const char* fmt, ...) { : USHRT_MAX); if (rc >= 0) { - notify = true; + notify |= 1 << LOG_ID_MAIN; } // end scope for main buffer } @@ -449,7 +449,7 @@ int LogAudit::logPrint(const char* fmt, ...) { free(str); if (notify) { - reader->notifyNewLog(); + reader->notifyNewLog(notify); if (rc < 0) { rc = message_len; } diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp old mode 100644 new mode 100755 index a7e72087f..7a7ac7da8 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -826,7 +826,7 @@ int LogKlog::log(const char* buf, ssize_t len) { // notify readers if (!rc) { - reader->notifyNewLog(); + reader->notifyNewLog(static_cast(1 << LOG_ID_KERNEL)); } return rc; diff --git a/logd/LogListener.cpp b/logd/LogListener.cpp old mode 100644 new mode 100755 index fcf2cd8a1..fc51dcf08 --- a/logd/LogListener.cpp +++ b/logd/LogListener.cpp @@ -94,12 +94,13 @@ bool LogListener::onDataAvailable(SocketClient* cli) { android_log_header_t* header = reinterpret_cast(buffer); - if (/* header->id < LOG_ID_MIN || */ header->id >= LOG_ID_MAX || - header->id == LOG_ID_KERNEL) { + log_id_t logId = static_cast(header->id); + if (/* logId < LOG_ID_MIN || */ logId >= LOG_ID_MAX || + logId == LOG_ID_KERNEL) { return false; } - if ((header->id == LOG_ID_SECURITY) && + if ((logId == LOG_ID_SECURITY) && (!__android_log_security() || !clientHasLogCredentials(cred->uid, cred->gid, cred->pid))) { return false; @@ -134,11 +135,10 @@ bool LogListener::onDataAvailable(SocketClient* cli) { if (logbuf != nullptr) { int res = logbuf->log( - (log_id_t)header->id, header->realtime, cred->uid, cred->pid, - header->tid, msg, + logId, header->realtime, cred->uid, cred->pid, header->tid, msg, ((size_t)n <= USHRT_MAX) ? (unsigned short)n : USHRT_MAX); if (res > 0 && reader != nullptr) { - reader->notifyNewLog(); + reader->notifyNewLog(static_cast(1 << logId)); } } diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp old mode 100644 new mode 100755 index 6d6931631..2b6556d7b --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -35,9 +35,9 @@ LogReader::LogReader(LogBuffer* logbuf) } // When we are notified a new log entry is available, inform -// all of our listening sockets. -void LogReader::notifyNewLog() { - FlushCommand command(*this); +// listening sockets who are watching this entry's log id. +void LogReader::notifyNewLog(log_mask_t logMask) { + FlushCommand command(*this, logMask); runOnEachSocket(&command); } diff --git a/logd/LogReader.h b/logd/LogReader.h old mode 100644 new mode 100755 index 271e08cdc..b5312b60d --- a/logd/LogReader.h +++ b/logd/LogReader.h @@ -19,6 +19,8 @@ #include +#include "LogTimes.h" + #define LOGD_SNDTIMEO 32 class LogBuffer; @@ -28,7 +30,7 @@ class LogReader : public SocketListener { public: explicit LogReader(LogBuffer* logbuf); - void notifyNewLog(); + void notifyNewLog(log_mask_t logMask); LogBuffer& logbuf(void) const { return mLogbuf; diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp old mode 100644 new mode 100755 index 25c2ad2b7..7a6f84b70 --- a/logd/LogTimes.cpp +++ b/logd/LogTimes.cpp @@ -28,9 +28,8 @@ 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, log_time start, - uint64_t timeout) + bool nonBlock, unsigned long tail, log_mask_t logMask, + pid_t pid, log_time start, uint64_t timeout) : mRefCount(1), mRelease(false), mError(false), diff --git a/logd/LogTimes.h b/logd/LogTimes.h old mode 100644 new mode 100755 index 9ca2aea5e..76d016c13 --- a/logd/LogTimes.h +++ b/logd/LogTimes.h @@ -26,6 +26,8 @@ #include #include +typedef unsigned int log_mask_t; + class LogReader; class LogBufferElement; @@ -41,7 +43,7 @@ class LogTimeEntry { LogReader& mReader; static void* threadStart(void* me); static void threadStop(void* me); - const unsigned int mLogMask; + const log_mask_t mLogMask; const pid_t mPid; unsigned int skipAhead[LOG_ID_MAX]; pid_t mLastTid[LOG_ID_MAX]; @@ -51,7 +53,7 @@ class LogTimeEntry { public: LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, - unsigned long tail, unsigned int logMask, pid_t pid, + unsigned long tail, log_mask_t logMask, pid_t pid, log_time start, uint64_t timeout); SocketClient* mClient; @@ -133,8 +135,11 @@ class LogTimeEntry { // No one else is holding a reference to this delete this; } - bool isWatching(log_id_t id) { - return (mLogMask & (1 << id)) != 0; + bool isWatching(log_id_t id) const { + return mLogMask & (1 << id); + } + bool isWatchingMultiple(log_mask_t logMask) const { + return mLogMask & logMask; } // flushTo filter callbacks static int FilterFirstPass(const LogBufferElement* element, void* me);