Log when binder thread pool is starved

Log when the number of threads executing binder commands is equal to the
maximium size of the thread pool for >100ms.

Bug: 28201939
Change-Id: I892863d8a81c06e362d4ae18ab08485fdec3c0bb

3 files changed, 18 insertions, 0 deletions

diff --git a/include/binder/ProcessState.h b/include/binder/ProcessState.h
index f9edc2a691..64cf72e170 100644
--- a/include/binder/ProcessState.h
+++ b/include/binder/ProcessState.h
@@ -91,6 +91,8 @@ private:
             size_t              mExecutingThreadsCount;
             // Maximum number for binder threads allowed for this process.
             size_t              mMaxThreads;
+            // Time when thread pool was emptied
+            int64_t             mStarvationStartTimeMs;
 
     mutable Mutex               mLock;  // protects everything below.
 
diff --git a/libs/binder/IPCThreadState.cpp b/libs/binder/IPCThreadState.cpp
index 1cbcfe4de5..d90798f51e 100644
--- a/libs/binder/IPCThreadState.cpp
+++ b/libs/binder/IPCThreadState.cpp
@@ -24,12 +24,14 @@
 
 #include <cutils/sched_policy.h>
 #include <utils/Log.h>
+#include <utils/SystemClock.h>
 #include <utils/threads.h>
 
 #include <private/binder/binder_module.h>
 #include <private/binder/Static.h>
 
 #include <errno.h>
+#include <inttypes.h>
 #include <pthread.h>
 #include <sched.h>
 #include <signal.h>
@@ -434,12 +436,25 @@ status_t IPCThreadState::getAndExecuteCommand()
 
         pthread_mutex_lock(&mProcess->mThreadCountLock);
         mProcess->mExecutingThreadsCount++;
+        if (mProcess->mExecutingThreadsCount >= mProcess->mMaxThreads &&
+                mProcess->mStarvationStartTimeMs == 0) {
+            mProcess->mStarvationStartTimeMs = uptimeMillis();
+        }
         pthread_mutex_unlock(&mProcess->mThreadCountLock);
 
         result = executeCommand(cmd);
 
         pthread_mutex_lock(&mProcess->mThreadCountLock);
         mProcess->mExecutingThreadsCount--;
+        if (mProcess->mExecutingThreadsCount < mProcess->mMaxThreads &&
+                mProcess->mStarvationStartTimeMs != 0) {
+            int64_t starvationTimeMs = uptimeMillis() - mProcess->mStarvationStartTimeMs;
+            if (starvationTimeMs > 100) {
+                ALOGE("binder thread pool (%zu threads) starved for %" PRId64 " ms",
+                      mProcess->mMaxThreads, starvationTimeMs);
+            }
+            mProcess->mStarvationStartTimeMs = 0;
+        }
         pthread_cond_broadcast(&mProcess->mThreadCountDecrement);
         pthread_mutex_unlock(&mProcess->mThreadCountLock);
 
diff --git a/libs/binder/ProcessState.cpp b/libs/binder/ProcessState.cpp
index b221e51811..f13f49fe93 100644
--- a/libs/binder/ProcessState.cpp
+++ b/libs/binder/ProcessState.cpp
@@ -343,6 +343,7 @@ ProcessState::ProcessState()
     , mThreadCountDecrement(PTHREAD_COND_INITIALIZER)
     , mExecutingThreadsCount(0)
     , mMaxThreads(DEFAULT_MAX_BINDER_THREADS)
+    , mStarvationStartTimeMs(0)
     , mManagesContexts(false)
     , mBinderContextCheckFunc(NULL)
     , mBinderContextUserData(NULL)