Extend the BIND_APPLICATION_TIMEOUT

We're reporting an ANR if the app process doesn't finish
the handling of bindApplication within the BIND_APPLICATION_TIMEOUT.
But very often, due to the contended system resources, the app
process just doesn't get enough CPU time to run. So now we'll
extend the timeout by the time that this process is waiting for
run.

Also given the bindApplication includes the time the app spends
on Application#onCreate(), relax the timeout to 15s by default.

Bug: 304484667
Test: Manual
Change-Id: I442e997fa6f30445ddeb2922146e837cc24d4174

2 files changed, 49 insertions, 14 deletions

diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index d3ce47c56e49..ffbbf7cd4e4e 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -377,6 +377,7 @@ import android.util.FeatureFlagUtils;
 import android.util.IndentingPrintWriter;
 import android.util.IntArray;
 import android.util.Log;
+import android.util.MathUtils;
 import android.util.Pair;
 import android.util.PrintWriterPrinter;
 import android.util.Slog;
@@ -562,7 +563,7 @@ public class ActivityManagerService extends IActivityManager.Stub
     static final int PROC_START_TIMEOUT = 10 * 1000 * Build.HW_TIMEOUT_MULTIPLIER;
 
     // How long we wait for a launched process to complete its app startup before we ANR.
-    static final int BIND_APPLICATION_TIMEOUT = 10 * 1000 * Build.HW_TIMEOUT_MULTIPLIER;
+    static final int BIND_APPLICATION_TIMEOUT = 15 * 1000 * Build.HW_TIMEOUT_MULTIPLIER;
 
     // How long we wait to kill an application zygote, after the last process using
     // it has gone away.
@@ -1630,7 +1631,8 @@ public class ActivityManagerService extends IActivityManager.Stub
     static final int UPDATE_CACHED_APP_HIGH_WATERMARK = 79;
     static final int ADD_UID_TO_OBSERVER_MSG = 80;
     static final int REMOVE_UID_FROM_OBSERVER_MSG = 81;
-    static final int BIND_APPLICATION_TIMEOUT_MSG = 82;
+    static final int BIND_APPLICATION_TIMEOUT_SOFT_MSG = 82;
+    static final int BIND_APPLICATION_TIMEOUT_HARD_MSG = 83;
 
     static final int FIRST_BROADCAST_QUEUE_MSG = 200;
 
@@ -1983,15 +1985,11 @@ public class ActivityManagerService extends IActivityManager.Stub
                 case UPDATE_CACHED_APP_HIGH_WATERMARK: {
                     mAppProfiler.mCachedAppsWatermarkData.updateCachedAppsSnapshot((long) msg.obj);
                 } break;
-                case BIND_APPLICATION_TIMEOUT_MSG: {
-                    ProcessRecord app = (ProcessRecord) msg.obj;
-
-                    final String anrMessage;
-                    synchronized (app) {
-                        anrMessage = "Process " + app + " failed to complete startup";
-                    }
-
-                    mAnrHelper.appNotResponding(app, TimeoutRecord.forAppStart(anrMessage));
+                case BIND_APPLICATION_TIMEOUT_SOFT_MSG: {
+                    handleBindApplicationTimeoutSoft((ProcessRecord) msg.obj, msg.arg1);
+                } break;
+                case BIND_APPLICATION_TIMEOUT_HARD_MSG: {
+                    handleBindApplicationTimeoutHard((ProcessRecord) msg.obj);
                 } break;
             }
         }
@@ -4749,6 +4747,7 @@ public class ActivityManagerService extends IActivityManager.Stub
                 mPlatformCompat.resetReporting(app.info);
             }
             final ProviderInfoList providerList = ProviderInfoList.fromList(providers);
+            app.mProfile.mLastCpuDelayTime.set(app.getCpuDelayTime());
             if (app.getIsolatedEntryPoint() != null) {
                 // This is an isolated process which should just call an entry point instead of
                 // being bound to an application.
@@ -4786,9 +4785,10 @@ public class ActivityManagerService extends IActivityManager.Stub
                         app.getStartElapsedTime(), app.getStartUptime());
             }
 
-            Message msg = mHandler.obtainMessage(BIND_APPLICATION_TIMEOUT_MSG);
+            Message msg = mHandler.obtainMessage(BIND_APPLICATION_TIMEOUT_SOFT_MSG);
             msg.obj = app;
-            mHandler.sendMessageDelayed(msg, BIND_APPLICATION_TIMEOUT);
+            msg.arg1 = BIND_APPLICATION_TIMEOUT;
+            mHandler.sendMessageDelayed(msg, msg.arg1 /* BIND_APPLICATION_TIMEOUT */);
             mHandler.removeMessages(PROC_START_TIMEOUT_MSG, app);
 
             if (profilerInfo != null) {
@@ -4865,7 +4865,8 @@ public class ActivityManagerService extends IActivityManager.Stub
         }
 
         if (app != null && app.getStartUid() == uid && app.getStartSeq() == startSeq) {
-            mHandler.removeMessages(BIND_APPLICATION_TIMEOUT_MSG, app);
+            mHandler.removeMessages(BIND_APPLICATION_TIMEOUT_SOFT_MSG, app);
+            mHandler.removeMessages(BIND_APPLICATION_TIMEOUT_HARD_MSG, app);
         } else {
             Slog.wtf(TAG, "Mismatched or missing ProcessRecord: " + app + ". Pid: " + pid
                     + ". Uid: " + uid);
@@ -5002,6 +5003,35 @@ public class ActivityManagerService extends IActivityManager.Stub
         }
     }
 
+    private void handleBindApplicationTimeoutSoft(ProcessRecord app, int softTimeoutMillis) {
+        // Similar logic as the broadcast delivery timeout:
+        // instead of immediately triggering an ANR, extend the timeout by
+        // the amount of time the process was runnable-but-waiting; we're
+        // only willing to do this once before triggering an hard ANR.
+        final long cpuDelayTime = app.getCpuDelayTime() - app.mProfile.mLastCpuDelayTime.get();
+        final long hardTimeoutMillis = MathUtils.constrain(cpuDelayTime, 0, softTimeoutMillis);
+
+        if (hardTimeoutMillis == 0) {
+            handleBindApplicationTimeoutHard(app);
+            return;
+        }
+
+        Slog.i(TAG, "Extending process start timeout by " + hardTimeoutMillis + "ms for " + app);
+        Trace.instant(Trace.TRACE_TAG_ACTIVITY_MANAGER, "bindApplicationTimeSoft "
+                + app.processName + "(" + app.getPid() + ")");
+        final Message msg = mHandler.obtainMessage(BIND_APPLICATION_TIMEOUT_HARD_MSG, app);
+        mHandler.sendMessageDelayed(msg, hardTimeoutMillis);
+    }
+
+    private void handleBindApplicationTimeoutHard(ProcessRecord app) {
+        final String anrMessage;
+        synchronized (app) {
+            anrMessage = "Process " + app + " failed to complete startup";
+        }
+
+        mAnrHelper.appNotResponding(app, TimeoutRecord.forAppStart(anrMessage));
+    }
+
     /**
      * @return The last part of the string of an intent's action.
      */
diff --git a/services/core/java/com/android/server/am/ProcessProfileRecord.java b/services/core/java/com/android/server/am/ProcessProfileRecord.java
index db74f1aed422..c1f86e0c9bb4 100644
--- a/services/core/java/com/android/server/am/ProcessProfileRecord.java
+++ b/services/core/java/com/android/server/am/ProcessProfileRecord.java
@@ -142,6 +142,11 @@ final class ProcessProfileRecord {
     final AtomicLong mCurCpuTime = new AtomicLong(0);
 
     /**
+     * How long the process has spent on waiting in the runqueue since fork.
+     */
+    final AtomicLong mLastCpuDelayTime = new AtomicLong(0);
+
+    /**
      * Last selected memory trimming level.
      */
     @CompositeRWLock({"mService", "mProcLock"})