From 711859d0ee93b74e9787271f4137eee3f83bbcdf Mon Sep 17 00:00:00 2001 From: Mohamad Mahmoud Date: Wed, 10 May 2023 11:58:00 +0000 Subject: Move dumpAnrStateLocked off the critical ANR path Shift the execution of dumpAnrStateLocked to the foreground thread to allow concurrent operation with the stack dump for the ANRing process. This significantly reduces the time to initiate the stack dump (~70 ms on a Pixel 5 device)for input dispatching timeout ANRs. This change addresses a major source of nativePollOnce (message queue idle) ANRs, which is the latency in initiating stack dumps. Bug: 272292150 Test: make sure dumpAnrStateLocked behaves as expected Test: Manual test: make sure the duration array has the correct value Test: atest FrameworksServicesTests:AnrHelperTest Change-Id: Ic7a2391c365501b4b4b19c0fbc4d3f22e37f1918 --- .../android/internal/os/anr/AnrLatencyTracker.java | 18 ++++++++++- .../java/com/android/server/wm/AnrController.java | 37 +++++++++++++++------- 2 files changed, 42 insertions(+), 13 deletions(-) diff --git a/core/java/com/android/internal/os/anr/AnrLatencyTracker.java b/core/java/com/android/internal/os/anr/AnrLatencyTracker.java index 6fa6fa5d37f3..3ba4ea55b5d3 100644 --- a/core/java/com/android/internal/os/anr/AnrLatencyTracker.java +++ b/core/java/com/android/internal/os/anr/AnrLatencyTracker.java @@ -118,6 +118,9 @@ public class AnrLatencyTracker implements AutoCloseable { private boolean mIsSkipped = false; private boolean mCopyingFirstPidSucceeded = false; + private long mPreDumpIfLockTooSlowStartUptime; + private long mPreDumpIfLockTooSlowDuration = 0; + private final int mAnrRecordPlacedOnQueueCookie = sNextAnrRecordPlacedOnQueueCookieGenerator.incrementAndGet(); @@ -401,6 +404,17 @@ public class AnrLatencyTracker implements AutoCloseable { Trace.traceCounter(TRACE_TAG_ACTIVITY_MANAGER, "anrRecordsQueueSize", queueSize); } + /** Records the start of AnrController#preDumpIfLockTooSlow. */ + public void preDumpIfLockTooSlowStarted() { + mPreDumpIfLockTooSlowStartUptime = getUptimeMillis(); + } + + /** Records the end of AnrController#preDumpIfLockTooSlow. */ + public void preDumpIfLockTooSlowEnded() { + mPreDumpIfLockTooSlowDuration += + getUptimeMillis() - mPreDumpIfLockTooSlowStartUptime; + } + /** Records a skipped ANR in ProcessErrorStateRecord#appNotResponding. */ public void anrSkippedProcessErrorStateRecordAppNotResponding() { anrSkipped("appNotResponding"); @@ -415,7 +429,7 @@ public class AnrLatencyTracker implements AutoCloseable { * Returns latency data as a comma separated value string for inclusion in ANR report. */ public String dumpAsCommaSeparatedArrayWithHeader() { - return "DurationsV3: " + mAnrTriggerUptime + return "DurationsV4: " + mAnrTriggerUptime /* triggering_to_app_not_responding_duration = */ + "," + (mAppNotRespondingStartUptime - mAnrTriggerUptime) /* app_not_responding_duration = */ @@ -464,6 +478,8 @@ public class AnrLatencyTracker implements AutoCloseable { + "," + mEarlyDumpStatus /* copying_first_pid_succeeded = */ + "," + (mCopyingFirstPidSucceeded ? 1 : 0) + /* preDumpIfLockTooSlow_duration = */ + + "," + mPreDumpIfLockTooSlowDuration + "\n\n"; } diff --git a/services/core/java/com/android/server/wm/AnrController.java b/services/core/java/com/android/server/wm/AnrController.java index 90ec964e2f0f..2df601fd1d3b 100644 --- a/services/core/java/com/android/server/wm/AnrController.java +++ b/services/core/java/com/android/server/wm/AnrController.java @@ -34,6 +34,7 @@ import android.util.SparseArray; import android.view.InputApplicationHandle; import com.android.internal.os.TimeoutRecord; +import com.android.server.FgThread; import com.android.server.am.StackTracesDumpHelper; import com.android.server.criticalevents.CriticalEventLog; @@ -68,7 +69,9 @@ class AnrController { TimeoutRecord timeoutRecord) { try { Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "notifyAppUnresponsive()"); + timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowStarted(); preDumpIfLockTooSlow(); + timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowEnded(); final ActivityRecord activity; timeoutRecord.mLatencyTracker.waitingOnGlobalLockStarted(); boolean blamePendingFocusRequest = false; @@ -108,7 +111,7 @@ class AnrController { if (!blamePendingFocusRequest) { Slog.i(TAG_WM, "ANR in " + activity.getName() + ". Reason: " + timeoutRecord.mReason); - dumpAnrStateLocked(activity, null /* windowState */, timeoutRecord.mReason); + dumpAnrStateAsync(activity, null /* windowState */, timeoutRecord.mReason); mUnresponsiveAppByDisplay.put(activity.getDisplayId(), activity); } } @@ -159,7 +162,9 @@ class AnrController { */ private boolean notifyWindowUnresponsive(@NonNull IBinder inputToken, TimeoutRecord timeoutRecord) { + timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowStarted(); preDumpIfLockTooSlow(); + timeoutRecord.mLatencyTracker.preDumpIfLockTooSlowEnded(); final int pid; final boolean aboveSystem; final ActivityRecord activity; @@ -178,7 +183,7 @@ class AnrController { ? windowState.mActivityRecord : null; Slog.i(TAG_WM, "ANR in " + target + ". Reason:" + timeoutRecord.mReason); aboveSystem = isWindowAboveSystem(windowState); - dumpAnrStateLocked(activity, windowState, timeoutRecord.mReason); + dumpAnrStateAsync(activity, windowState, timeoutRecord.mReason); } if (activity != null) { activity.inputDispatchingTimedOut(timeoutRecord, pid); @@ -197,7 +202,7 @@ class AnrController { timeoutRecord.mLatencyTracker.waitingOnGlobalLockStarted(); synchronized (mService.mGlobalLock) { timeoutRecord.mLatencyTracker.waitingOnGlobalLockEnded(); - dumpAnrStateLocked(null /* activity */, null /* windowState */, timeoutRecord.mReason); + dumpAnrStateAsync(null /* activity */, null /* windowState */, timeoutRecord.mReason); } // We cannot determine the z-order of the window, so place the anr dialog as high @@ -351,15 +356,23 @@ class AnrController { } - private void dumpAnrStateLocked(ActivityRecord activity, WindowState windowState, - String reason) { - try { - Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "dumpAnrStateLocked()"); - mService.saveANRStateLocked(activity, windowState, reason); - mService.mAtmService.saveANRState(reason); - } finally { - Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); - } + /** + * Executes asynchronously on the fg thread not to block the stack dump for + * the ANRing processes. + */ + private void dumpAnrStateAsync(ActivityRecord activity, WindowState windowState, + String reason) { + FgThread.getExecutor().execute(() -> { + try { + Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "dumpAnrStateLocked()"); + synchronized (mService.mGlobalLock) { + mService.saveANRStateLocked(activity, windowState, reason); + mService.mAtmService.saveANRState(reason); + } + } finally { + Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER); + } + }); } private boolean isWindowAboveSystem(@NonNull WindowState windowState) { -- cgit v1.2.3-59-g8ed1b