logd: enhance multiple blocking readers performance

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

9 files changed, 57 insertions, 39 deletions

diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp
index a9edc3ee6..70ecbe0a5 100644..100755
--- 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
index 7cdd03fdb..543dfc3d7 100644..100755
--- 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
index cfcbaa5a8..1d0cc334a 100644..100755
--- 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
index a7e72087f..7a7ac7da8 100644..100755
--- 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<log_mask_t>(1 << LOG_ID_KERNEL));
     }
 
     return rc;
diff --git a/logd/LogListener.cpp b/logd/LogListener.cpp
index fcf2cd8a1..fc51dcf08 100644..100755
--- a/logd/LogListener.cpp
+++ b/logd/LogListener.cpp
@@ -94,12 +94,13 @@ bool LogListener::onDataAvailable(SocketClient* cli) {
 
     android_log_header_t* header =
         reinterpret_cast<android_log_header_t*>(buffer);
-    if (/* header->id < LOG_ID_MIN || */ header->id >= LOG_ID_MAX ||
-        header->id == LOG_ID_KERNEL) {
+    log_id_t logId = static_cast<log_id_t>(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<log_mask_t>(1 << logId));
         }
     }
 
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 6d6931631..2b6556d7b 100644..100755
--- 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
index 271e08cdc..b5312b60d 100644..100755
--- a/logd/LogReader.h
+++ b/logd/LogReader.h
@@ -19,6 +19,8 @@
 
 #include <sysutils/SocketListener.h>
 
+#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
index 25c2ad2b7..7a6f84b70 100644..100755
--- 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
index 9ca2aea5e..76d016c13 100644..100755
--- a/logd/LogTimes.h
+++ b/logd/LogTimes.h
@@ -26,6 +26,8 @@
 #include <log/log.h>
 #include <sysutils/SocketClient.h>
 
+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);