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
This commit is contained in:
Mohamad Mahmoud
2023-05-10 11:58:00 +00:00
parent 53466c0060
commit 711859d0ee
2 changed files with 42 additions and 13 deletions

View File

@@ -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";
}

View File

@@ -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) {