Loading core/java/com/android/internal/os/anr/AnrLatencyTracker.java +107 −14 Original line number Diff line number Diff line Loading @@ -28,12 +28,15 @@ import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__A import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__START_FOREGROUND_SERVICE; import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__UNKNOWN_ANR_TYPE; import android.annotation.IntDef; import android.os.SystemClock; import android.os.Trace; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.util.FrameworkStatsLog; import java.lang.annotation.Retention; import java.lang.annotation.RetentionPolicy; import java.util.concurrent.atomic.AtomicInteger; /** Loading @@ -44,6 +47,22 @@ import java.util.concurrent.atomic.AtomicInteger; */ public class AnrLatencyTracker implements AutoCloseable { /** Status of the early dumped pid. */ @IntDef(value = { EarlyDumpStatus.UNKNOWN, EarlyDumpStatus.SUCCEEDED, EarlyDumpStatus.FAILED_TO_CREATE_FILE, EarlyDumpStatus.TIMED_OUT }) @Retention(RetentionPolicy.SOURCE) private @interface EarlyDumpStatus { int UNKNOWN = 1; int SUCCEEDED = 2; int FAILED_TO_CREATE_FILE = 3; int TIMED_OUT = 4; } private static final AtomicInteger sNextAnrRecordPlacedOnQueueCookieGenerator = new AtomicInteger(); Loading Loading @@ -77,7 +96,16 @@ public class AnrLatencyTracker implements AutoCloseable { private int mAnrQueueSize; private int mAnrType; private int mDumpedProcessesCount = 0; private final AtomicInteger mDumpedProcessesCount = new AtomicInteger(0); private volatile @EarlyDumpStatus int mEarlyDumpStatus = EarlyDumpStatus.UNKNOWN; private volatile long mTempFileDumpingStartUptime; private volatile long mTempFileDumpingDuration = 0; private long mCopyingFirstPidStartUptime; private long mCopyingFirstPidDuration = 0; private long mEarlyDumpRequestSubmissionUptime = 0; private long mEarlyDumpExecutorPidCount = 0; private long mFirstPidsDumpingStartUptime; private long mFirstPidsDumpingDuration = 0; Loading @@ -88,7 +116,7 @@ public class AnrLatencyTracker implements AutoCloseable { private boolean mIsPushed = false; private boolean mIsSkipped = false; private boolean mCopyingFirstPidSucceeded = false; private final int mAnrRecordPlacedOnQueueCookie = sNextAnrRecordPlacedOnQueueCookieGenerator.incrementAndGet(); Loading @@ -111,6 +139,15 @@ public class AnrLatencyTracker implements AutoCloseable { Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** * Records the number of processes we are currently early-dumping, this number includes the * current ANR's main process. */ public void earlyDumpRequestSubmittedWithSize(int currentProcessedPidCount) { mEarlyDumpRequestSubmissionUptime = getUptimeMillis(); mEarlyDumpExecutorPidCount = currentProcessedPidCount; } /** Records the placing of the AnrHelper.AnrRecord instance on the processing queue. */ public void anrRecordPlacingOnQueueWithSize(int queueSize) { mAnrRecordPlacedOnQueueUptime = getUptimeMillis(); Loading Loading @@ -210,48 +247,89 @@ public class AnrLatencyTracker implements AutoCloseable { Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of pid dumping to file. */ public void dumpingPidStarted(int pid) { Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingPid#" + pid); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of pid dumping to file. */ public void dumpingPidEnded() { mDumpedProcessesCount++; mDumpedProcessesCount.incrementAndGet(); Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of first pids dumping to file. */ public void dumpingFirstPidsStarted() { mFirstPidsDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingFirstPids"); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of first pids dumping to file. */ public void dumpingFirstPidsEnded() { mFirstPidsDumpingDuration = getUptimeMillis() - mFirstPidsDumpingStartUptime; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of the copying of the pre-dumped first pid. */ public void copyingFirstPidStarted() { mCopyingFirstPidStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "copyingFirstPid"); } /** Records the end of the copying of the pre-dumped first pid. */ public void copyingFirstPidEnded(boolean copySucceeded) { mCopyingFirstPidDuration = getUptimeMillis() - mCopyingFirstPidStartUptime; mCopyingFirstPidSucceeded = copySucceeded; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pre-dumping. */ public void dumpStackTracesTempFileStarted() { mTempFileDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFile"); } /** Records the end of pre-dumping. */ public void dumpStackTracesTempFileEnded() { mTempFileDumpingDuration = getUptimeMillis() - mTempFileDumpingStartUptime; if (mEarlyDumpStatus == EarlyDumpStatus.UNKNOWN) { mEarlyDumpStatus = EarlyDumpStatus.SUCCEEDED; } Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records file creation failure events in dumpStackTracesTempFile. */ public void dumpStackTracesTempFileCreationFailed() { mEarlyDumpStatus = EarlyDumpStatus.FAILED_TO_CREATE_FILE; Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFileCreationFailed"); } /** Records timeout events in dumpStackTracesTempFile. */ public void dumpStackTracesTempFileTimedOut() { mEarlyDumpStatus = EarlyDumpStatus.TIMED_OUT; Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFileTimedOut"); } /** Records the start of native pids dumping to file. */ public void dumpingNativePidsStarted() { mNativePidsDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingNativePids"); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of native pids dumping to file . */ public void dumpingNativePidsEnded() { mNativePidsDumpingDuration = getUptimeMillis() - mNativePidsDumpingStartUptime; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of extra pids dumping to file. */ public void dumpingExtraPidsStarted() { mExtraPidsDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingExtraPids"); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of extra pids dumping to file. */ public void dumpingExtraPidsEnded() { mExtraPidsDumpingDuration = getUptimeMillis() - mExtraPidsDumpingStartUptime; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); Loading Loading @@ -337,7 +415,7 @@ public class AnrLatencyTracker implements AutoCloseable { * Returns latency data as a comma separated value string for inclusion in ANR report. */ public String dumpAsCommaSeparatedArrayWithHeader() { return "DurationsV2: " + mAnrTriggerUptime return "DurationsV3: " + mAnrTriggerUptime /* triggering_to_app_not_responding_duration = */ + "," + (mAppNotRespondingStartUptime - mAnrTriggerUptime) /* app_not_responding_duration = */ Loading Loading @@ -370,7 +448,22 @@ public class AnrLatencyTracker implements AutoCloseable { /* anr_queue_size_when_pushed = */ + "," + mAnrQueueSize /* dump_stack_traces_io_time = */ + "," + (mFirstPidsDumpingStartUptime - mDumpStackTracesStartUptime) // We use copyingFirstPidUptime if we're dumping the durations list before the // first pids ie after copying the early dump stacks. + "," + ((mFirstPidsDumpingStartUptime > 0 ? mFirstPidsDumpingStartUptime : mCopyingFirstPidStartUptime) - mDumpStackTracesStartUptime) /* temp_file_dump_duration = */ + "," + mTempFileDumpingDuration /* temp_dump_request_on_queue_duration = */ + "," + (mTempFileDumpingStartUptime - mEarlyDumpRequestSubmissionUptime) /* temp_dump_pid_count_when_pushed = */ + "," + mEarlyDumpExecutorPidCount /* first_pid_copying_time = */ + "," + mCopyingFirstPidDuration /* early_dump_status = */ + "," + mEarlyDumpStatus /* copying_first_pid_succeeded = */ + "," + (mCopyingFirstPidSucceeded ? 1 : 0) + "\n\n"; } Loading Loading @@ -449,7 +542,7 @@ public class AnrLatencyTracker implements AutoCloseable { /* anr_queue_size_when_pushed = */ mAnrQueueSize, /* anr_type = */ mAnrType, /* dumped_processes_count = */ mDumpedProcessesCount); /* dumped_processes_count = */ mDumpedProcessesCount.get()); } private void anrSkipped(String method) { Loading core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java +27 −2 Original line number Diff line number Diff line Loading @@ -59,7 +59,10 @@ public class AnrLatencyTrackerTests { .thenReturn(175L) .thenReturn(198L) .thenReturn(203L) .thenReturn(209L); .thenReturn(209L) .thenReturn(211L) .thenReturn(212L) .thenReturn(220L); } @Test Loading @@ -68,6 +71,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.appNotRespondingStarted(); mLatencyTracker.waitingOnAnrRecordLockStarted(); mLatencyTracker.waitingOnAnrRecordLockEnded(); mLatencyTracker.earlyDumpRequestSubmittedWithSize(5); mLatencyTracker.anrRecordPlacingOnQueueWithSize(3); mLatencyTracker.appNotRespondingEnded(); Loading @@ -90,7 +94,16 @@ public class AnrLatencyTrackerTests { mLatencyTracker.waitingOnProcLockStarted(); mLatencyTracker.waitingOnProcLockEnded(); mLatencyTracker.dumpStackTracesTempFileStarted(); mLatencyTracker.dumpingPidStarted(5); mLatencyTracker.dumpStackTracesStarted(); mLatencyTracker.copyingFirstPidStarted(); mLatencyTracker.dumpingPidEnded(); mLatencyTracker.dumpStackTracesTempFileEnded(); mLatencyTracker.copyingFirstPidEnded(true); mLatencyTracker.dumpingFirstPidsStarted(); mLatencyTracker.dumpingPidStarted(1); mLatencyTracker.dumpingPidEnded(); Loading @@ -111,7 +124,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.close(); assertThat(mLatencyTracker.dumpAsCommaSeparatedArrayWithHeader()) .isEqualTo("DurationsV2: 50,5,25,8,115,2,3,7,8,15,2,7,23,10,3,6\n\n"); .isEqualTo("DurationsV3: 50,5,33,11,112,4,2,4,6,5,1,10,5,10,3,9,11,129,5,8,1\n\n"); verify(mLatencyTracker, times(1)).pushAtom(); } Loading @@ -121,6 +134,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.appNotRespondingStarted(); mLatencyTracker.waitingOnAnrRecordLockStarted(); mLatencyTracker.waitingOnAnrRecordLockEnded(); mLatencyTracker.earlyDumpRequestSubmittedWithSize(5); mLatencyTracker.anrRecordPlacingOnQueueWithSize(3); mLatencyTracker.appNotRespondingEnded(); Loading @@ -143,7 +157,18 @@ public class AnrLatencyTrackerTests { mLatencyTracker.waitingOnProcLockStarted(); mLatencyTracker.waitingOnProcLockEnded(); mLatencyTracker.dumpStackTracesTempFileStarted(); mLatencyTracker.dumpingPidStarted(5); mLatencyTracker.dumpStackTracesStarted(); mLatencyTracker.copyingFirstPidStarted(); mLatencyTracker.dumpingPidEnded(); mLatencyTracker.dumpStackTracesTempFileEnded(); mLatencyTracker.copyingFirstPidEnded(true); mLatencyTracker.dumpingFirstPidsStarted(); mLatencyTracker.dumpingPidStarted(1); mLatencyTracker.dumpingPidEnded(); Loading services/core/java/com/android/server/am/AnrHelper.java +58 −13 Original line number Diff line number Diff line Loading @@ -22,6 +22,7 @@ import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NA import android.content.pm.ApplicationInfo; import android.os.SystemClock; import android.os.Trace; import android.util.ArraySet; import android.util.Slog; import com.android.internal.annotations.GuardedBy; Loading @@ -29,8 +30,12 @@ import com.android.internal.annotations.VisibleForTesting; import com.android.internal.os.TimeoutRecord; import com.android.server.wm.WindowProcessController; import java.io.File; import java.util.ArrayList; import java.util.Collections; import java.util.Set; import java.util.concurrent.ExecutorService; import java.util.concurrent.Future; import java.util.concurrent.LinkedBlockingQueue; import java.util.concurrent.ThreadFactory; import java.util.concurrent.ThreadPoolExecutor; Loading Loading @@ -59,13 +64,19 @@ class AnrHelper { /** * The keep alive time for the threads in the helper threadpool executor */ private static final int AUX_THREAD_KEEP_ALIVE_SECOND = 10; private static final int DEFAULT_THREAD_KEEP_ALIVE_SECOND = 10; private static final ThreadFactory sDefaultThreadFactory = r -> new Thread(r, "AnrAuxiliaryTaskExecutor"); private static final ThreadFactory sMainProcessDumpThreadFactory = r -> new Thread(r, "AnrMainProcessDumpThread"); @GuardedBy("mAnrRecords") private final ArrayList<AnrRecord> mAnrRecords = new ArrayList<>(); private final Set<Integer> mTempDumpedPids = Collections.synchronizedSet(new ArraySet<Integer>()); private final AtomicBoolean mRunning = new AtomicBoolean(false); private final ActivityManagerService mService; Loading @@ -80,17 +91,21 @@ class AnrHelper { private int mProcessingPid = -1; private final ExecutorService mAuxiliaryTaskExecutor; private final ExecutorService mEarlyDumpExecutor; AnrHelper(final ActivityManagerService service) { this(service, new ThreadPoolExecutor(/* corePoolSize= */ 0, /* maximumPoolSize= */ 1, /* keepAliveTime= */ AUX_THREAD_KEEP_ALIVE_SECOND, TimeUnit.SECONDS, new LinkedBlockingQueue<>(), sDefaultThreadFactory)); // All the ANR threads need to expire after a period of inactivity, given the // ephemeral nature of ANRs and how infrequent they are. this(service, makeExpiringThreadPoolWithSize(1, sDefaultThreadFactory), makeExpiringThreadPoolWithSize(2, sMainProcessDumpThreadFactory)); } @VisibleForTesting AnrHelper(ActivityManagerService service, ExecutorService auxExecutor) { AnrHelper(ActivityManagerService service, ExecutorService auxExecutor, ExecutorService earlyDumpExecutor) { mService = service; mAuxiliaryTaskExecutor = auxExecutor; mEarlyDumpExecutor = earlyDumpExecutor; } void appNotResponding(ProcessRecord anrProcess, TimeoutRecord timeoutRecord) { Loading Loading @@ -121,6 +136,12 @@ class AnrHelper { + timeoutRecord.mReason); return; } if (!mTempDumpedPids.add(incomingPid)) { Slog.i(TAG, "Skip ANR being predumped, pid=" + incomingPid + " " + timeoutRecord.mReason); return; } for (int i = mAnrRecords.size() - 1; i >= 0; i--) { if (mAnrRecords.get(i).mPid == incomingPid) { Slog.i(TAG, Loading @@ -129,10 +150,24 @@ class AnrHelper { return; } } // We dump the main process as soon as we can on a different thread, // this is done as the main process's dump can go stale in a few hundred // milliseconds and the average full ANR dump takes a few seconds. timeoutRecord.mLatencyTracker.earlyDumpRequestSubmittedWithSize( mTempDumpedPids.size()); Future<File> firstPidDumpPromise = mEarlyDumpExecutor.submit(() -> { // the class AnrLatencyTracker is not generally thread safe but the values // recorded/touched by the Temporary dump thread(s) are all volatile/atomic. File tracesFile = StackTracesDumpHelper.dumpStackTracesTempFile(incomingPid, timeoutRecord.mLatencyTracker); mTempDumpedPids.remove(incomingPid); return tracesFile; }); timeoutRecord.mLatencyTracker.anrRecordPlacingOnQueueWithSize(mAnrRecords.size()); mAnrRecords.add(new AnrRecord(anrProcess, activityShortComponentName, aInfo, parentShortComponentName, parentProcess, aboveSystem, mAuxiliaryTaskExecutor, timeoutRecord, isContinuousAnr)); parentShortComponentName, parentProcess, aboveSystem, timeoutRecord, isContinuousAnr, firstPidDumpPromise)); } startAnrConsumerIfNeeded(); } finally { Loading @@ -147,6 +182,16 @@ class AnrHelper { } } private static ThreadPoolExecutor makeExpiringThreadPoolWithSize(int size, ThreadFactory factory) { ThreadPoolExecutor pool = new ThreadPoolExecutor(/* corePoolSize= */ size, /* maximumPoolSize= */ size, /* keepAliveTime= */ DEFAULT_THREAD_KEEP_ALIVE_SECOND, TimeUnit.SECONDS, new LinkedBlockingQueue<>(), factory); // We allow the core threads to expire after the keepAliveTime. pool.allowCoreThreadTimeOut(true); return pool; } /** * The thread to execute {@link ProcessErrorStateRecord#appNotResponding}. It will terminate if * all records are handled. Loading Loading @@ -219,7 +264,7 @@ class AnrHelper { } } private static class AnrRecord { private class AnrRecord { final ProcessRecord mApp; final int mPid; final String mActivityShortComponentName; Loading @@ -228,14 +273,14 @@ class AnrHelper { final ApplicationInfo mAppInfo; final WindowProcessController mParentProcess; final boolean mAboveSystem; final ExecutorService mAuxiliaryTaskExecutor; final long mTimestamp = SystemClock.uptimeMillis(); final boolean mIsContinuousAnr; final Future<File> mFirstPidFilePromise; AnrRecord(ProcessRecord anrProcess, String activityShortComponentName, ApplicationInfo aInfo, String parentShortComponentName, WindowProcessController parentProcess, boolean aboveSystem, ExecutorService auxiliaryTaskExecutor, TimeoutRecord timeoutRecord, boolean isContinuousAnr) { TimeoutRecord timeoutRecord, boolean isContinuousAnr, Future<File> firstPidFilePromise) { mApp = anrProcess; mPid = anrProcess.mPid; mActivityShortComponentName = activityShortComponentName; Loading @@ -244,8 +289,8 @@ class AnrHelper { mAppInfo = aInfo; mParentProcess = parentProcess; mAboveSystem = aboveSystem; mAuxiliaryTaskExecutor = auxiliaryTaskExecutor; mIsContinuousAnr = isContinuousAnr; mFirstPidFilePromise = firstPidFilePromise; } void appNotResponding(boolean onlyDumpSelf) { Loading @@ -254,7 +299,7 @@ class AnrHelper { mApp.mErrorState.appNotResponding(mActivityShortComponentName, mAppInfo, mParentShortComponentName, mParentProcess, mAboveSystem, mTimeoutRecord, mAuxiliaryTaskExecutor, onlyDumpSelf, mIsContinuousAnr); mIsContinuousAnr, mFirstPidFilePromise); } finally { mTimeoutRecord.mLatencyTracker.anrProcessingEnded(); } Loading services/core/java/com/android/server/am/ProcessErrorStateRecord.java +5 −3 Original line number Diff line number Diff line Loading @@ -287,7 +287,7 @@ class ProcessErrorStateRecord { String parentShortComponentName, WindowProcessController parentProcess, boolean aboveSystem, TimeoutRecord timeoutRecord, ExecutorService auxiliaryTaskExecutor, boolean onlyDumpSelf, boolean isContinuousAnr) { boolean isContinuousAnr, Future<File> firstPidFilePromise) { String annotation = timeoutRecord.mReason; AnrLatencyTracker latencyTracker = timeoutRecord.mLatencyTracker; Future<?> updateCpuStatsNowFirstCall = null; Loading Loading @@ -334,7 +334,6 @@ class ProcessErrorStateRecord { Counter.logIncrement("stability_anr.value_skipped_anrs"); return; } // In case we come through here for the same app before completing // this one, mark as anring now so we will bail out. latencyTracker.waitingOnProcLockStarted(); Loading Loading @@ -368,6 +367,9 @@ class ProcessErrorStateRecord { firstPids.add(pid); // Don't dump other PIDs if it's a background ANR or is requested to only dump self. // Note that the primary pid is added here just in case, as it should normally be // dumped on the early dump thread, and would only be dumped on the Anr consumer thread // as a fallback. isSilentAnr = isSilentAnr(); if (!isSilentAnr && !onlyDumpSelf) { int parentPid = pid; Loading Loading @@ -498,7 +500,7 @@ class ProcessErrorStateRecord { File tracesFile = StackTracesDumpHelper.dumpStackTraces(firstPids, isSilentAnr ? null : processCpuTracker, isSilentAnr ? null : lastPids, nativePidsFuture, tracesFileException, firstPidEndOffset, annotation, criticalEventLog, auxiliaryTaskExecutor, latencyTracker); criticalEventLog, auxiliaryTaskExecutor, firstPidFilePromise, latencyTracker); if (isMonitorCpuUsage()) { // Wait for the first call to finish Loading services/core/java/com/android/server/am/StackTracesDumpHelper.java +161 −29 File changed.Preview size limit exceeded, changes collapsed. Show changes Loading
core/java/com/android/internal/os/anr/AnrLatencyTracker.java +107 −14 Original line number Diff line number Diff line Loading @@ -28,12 +28,15 @@ import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__A import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__START_FOREGROUND_SERVICE; import static com.android.internal.util.FrameworkStatsLog.ANRLATENCY_REPORTED__ANR_TYPE__UNKNOWN_ANR_TYPE; import android.annotation.IntDef; import android.os.SystemClock; import android.os.Trace; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.util.FrameworkStatsLog; import java.lang.annotation.Retention; import java.lang.annotation.RetentionPolicy; import java.util.concurrent.atomic.AtomicInteger; /** Loading @@ -44,6 +47,22 @@ import java.util.concurrent.atomic.AtomicInteger; */ public class AnrLatencyTracker implements AutoCloseable { /** Status of the early dumped pid. */ @IntDef(value = { EarlyDumpStatus.UNKNOWN, EarlyDumpStatus.SUCCEEDED, EarlyDumpStatus.FAILED_TO_CREATE_FILE, EarlyDumpStatus.TIMED_OUT }) @Retention(RetentionPolicy.SOURCE) private @interface EarlyDumpStatus { int UNKNOWN = 1; int SUCCEEDED = 2; int FAILED_TO_CREATE_FILE = 3; int TIMED_OUT = 4; } private static final AtomicInteger sNextAnrRecordPlacedOnQueueCookieGenerator = new AtomicInteger(); Loading Loading @@ -77,7 +96,16 @@ public class AnrLatencyTracker implements AutoCloseable { private int mAnrQueueSize; private int mAnrType; private int mDumpedProcessesCount = 0; private final AtomicInteger mDumpedProcessesCount = new AtomicInteger(0); private volatile @EarlyDumpStatus int mEarlyDumpStatus = EarlyDumpStatus.UNKNOWN; private volatile long mTempFileDumpingStartUptime; private volatile long mTempFileDumpingDuration = 0; private long mCopyingFirstPidStartUptime; private long mCopyingFirstPidDuration = 0; private long mEarlyDumpRequestSubmissionUptime = 0; private long mEarlyDumpExecutorPidCount = 0; private long mFirstPidsDumpingStartUptime; private long mFirstPidsDumpingDuration = 0; Loading @@ -88,7 +116,7 @@ public class AnrLatencyTracker implements AutoCloseable { private boolean mIsPushed = false; private boolean mIsSkipped = false; private boolean mCopyingFirstPidSucceeded = false; private final int mAnrRecordPlacedOnQueueCookie = sNextAnrRecordPlacedOnQueueCookieGenerator.incrementAndGet(); Loading @@ -111,6 +139,15 @@ public class AnrLatencyTracker implements AutoCloseable { Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** * Records the number of processes we are currently early-dumping, this number includes the * current ANR's main process. */ public void earlyDumpRequestSubmittedWithSize(int currentProcessedPidCount) { mEarlyDumpRequestSubmissionUptime = getUptimeMillis(); mEarlyDumpExecutorPidCount = currentProcessedPidCount; } /** Records the placing of the AnrHelper.AnrRecord instance on the processing queue. */ public void anrRecordPlacingOnQueueWithSize(int queueSize) { mAnrRecordPlacedOnQueueUptime = getUptimeMillis(); Loading Loading @@ -210,48 +247,89 @@ public class AnrLatencyTracker implements AutoCloseable { Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of pid dumping to file. */ public void dumpingPidStarted(int pid) { Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingPid#" + pid); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of pid dumping to file. */ public void dumpingPidEnded() { mDumpedProcessesCount++; mDumpedProcessesCount.incrementAndGet(); Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of first pids dumping to file. */ public void dumpingFirstPidsStarted() { mFirstPidsDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingFirstPids"); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of first pids dumping to file. */ public void dumpingFirstPidsEnded() { mFirstPidsDumpingDuration = getUptimeMillis() - mFirstPidsDumpingStartUptime; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of the copying of the pre-dumped first pid. */ public void copyingFirstPidStarted() { mCopyingFirstPidStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "copyingFirstPid"); } /** Records the end of the copying of the pre-dumped first pid. */ public void copyingFirstPidEnded(boolean copySucceeded) { mCopyingFirstPidDuration = getUptimeMillis() - mCopyingFirstPidStartUptime; mCopyingFirstPidSucceeded = copySucceeded; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pre-dumping. */ public void dumpStackTracesTempFileStarted() { mTempFileDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFile"); } /** Records the end of pre-dumping. */ public void dumpStackTracesTempFileEnded() { mTempFileDumpingDuration = getUptimeMillis() - mTempFileDumpingStartUptime; if (mEarlyDumpStatus == EarlyDumpStatus.UNKNOWN) { mEarlyDumpStatus = EarlyDumpStatus.SUCCEEDED; } Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records file creation failure events in dumpStackTracesTempFile. */ public void dumpStackTracesTempFileCreationFailed() { mEarlyDumpStatus = EarlyDumpStatus.FAILED_TO_CREATE_FILE; Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFileCreationFailed"); } /** Records timeout events in dumpStackTracesTempFile. */ public void dumpStackTracesTempFileTimedOut() { mEarlyDumpStatus = EarlyDumpStatus.TIMED_OUT; Trace.instant(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTracesTempFileTimedOut"); } /** Records the start of native pids dumping to file. */ public void dumpingNativePidsStarted() { mNativePidsDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingNativePids"); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of native pids dumping to file . */ public void dumpingNativePidsEnded() { mNativePidsDumpingDuration = getUptimeMillis() - mNativePidsDumpingStartUptime; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } /** Records the start of pid dumping to file (subject and criticalEventSection). */ /** Records the start of extra pids dumping to file. */ public void dumpingExtraPidsStarted() { mExtraPidsDumpingStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpingExtraPids"); } /** Records the end of pid dumping to file (subject and criticalEventSection). */ /** Records the end of extra pids dumping to file. */ public void dumpingExtraPidsEnded() { mExtraPidsDumpingDuration = getUptimeMillis() - mExtraPidsDumpingStartUptime; Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); Loading Loading @@ -337,7 +415,7 @@ public class AnrLatencyTracker implements AutoCloseable { * Returns latency data as a comma separated value string for inclusion in ANR report. */ public String dumpAsCommaSeparatedArrayWithHeader() { return "DurationsV2: " + mAnrTriggerUptime return "DurationsV3: " + mAnrTriggerUptime /* triggering_to_app_not_responding_duration = */ + "," + (mAppNotRespondingStartUptime - mAnrTriggerUptime) /* app_not_responding_duration = */ Loading Loading @@ -370,7 +448,22 @@ public class AnrLatencyTracker implements AutoCloseable { /* anr_queue_size_when_pushed = */ + "," + mAnrQueueSize /* dump_stack_traces_io_time = */ + "," + (mFirstPidsDumpingStartUptime - mDumpStackTracesStartUptime) // We use copyingFirstPidUptime if we're dumping the durations list before the // first pids ie after copying the early dump stacks. + "," + ((mFirstPidsDumpingStartUptime > 0 ? mFirstPidsDumpingStartUptime : mCopyingFirstPidStartUptime) - mDumpStackTracesStartUptime) /* temp_file_dump_duration = */ + "," + mTempFileDumpingDuration /* temp_dump_request_on_queue_duration = */ + "," + (mTempFileDumpingStartUptime - mEarlyDumpRequestSubmissionUptime) /* temp_dump_pid_count_when_pushed = */ + "," + mEarlyDumpExecutorPidCount /* first_pid_copying_time = */ + "," + mCopyingFirstPidDuration /* early_dump_status = */ + "," + mEarlyDumpStatus /* copying_first_pid_succeeded = */ + "," + (mCopyingFirstPidSucceeded ? 1 : 0) + "\n\n"; } Loading Loading @@ -449,7 +542,7 @@ public class AnrLatencyTracker implements AutoCloseable { /* anr_queue_size_when_pushed = */ mAnrQueueSize, /* anr_type = */ mAnrType, /* dumped_processes_count = */ mDumpedProcessesCount); /* dumped_processes_count = */ mDumpedProcessesCount.get()); } private void anrSkipped(String method) { Loading
core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java +27 −2 Original line number Diff line number Diff line Loading @@ -59,7 +59,10 @@ public class AnrLatencyTrackerTests { .thenReturn(175L) .thenReturn(198L) .thenReturn(203L) .thenReturn(209L); .thenReturn(209L) .thenReturn(211L) .thenReturn(212L) .thenReturn(220L); } @Test Loading @@ -68,6 +71,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.appNotRespondingStarted(); mLatencyTracker.waitingOnAnrRecordLockStarted(); mLatencyTracker.waitingOnAnrRecordLockEnded(); mLatencyTracker.earlyDumpRequestSubmittedWithSize(5); mLatencyTracker.anrRecordPlacingOnQueueWithSize(3); mLatencyTracker.appNotRespondingEnded(); Loading @@ -90,7 +94,16 @@ public class AnrLatencyTrackerTests { mLatencyTracker.waitingOnProcLockStarted(); mLatencyTracker.waitingOnProcLockEnded(); mLatencyTracker.dumpStackTracesTempFileStarted(); mLatencyTracker.dumpingPidStarted(5); mLatencyTracker.dumpStackTracesStarted(); mLatencyTracker.copyingFirstPidStarted(); mLatencyTracker.dumpingPidEnded(); mLatencyTracker.dumpStackTracesTempFileEnded(); mLatencyTracker.copyingFirstPidEnded(true); mLatencyTracker.dumpingFirstPidsStarted(); mLatencyTracker.dumpingPidStarted(1); mLatencyTracker.dumpingPidEnded(); Loading @@ -111,7 +124,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.close(); assertThat(mLatencyTracker.dumpAsCommaSeparatedArrayWithHeader()) .isEqualTo("DurationsV2: 50,5,25,8,115,2,3,7,8,15,2,7,23,10,3,6\n\n"); .isEqualTo("DurationsV3: 50,5,33,11,112,4,2,4,6,5,1,10,5,10,3,9,11,129,5,8,1\n\n"); verify(mLatencyTracker, times(1)).pushAtom(); } Loading @@ -121,6 +134,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.appNotRespondingStarted(); mLatencyTracker.waitingOnAnrRecordLockStarted(); mLatencyTracker.waitingOnAnrRecordLockEnded(); mLatencyTracker.earlyDumpRequestSubmittedWithSize(5); mLatencyTracker.anrRecordPlacingOnQueueWithSize(3); mLatencyTracker.appNotRespondingEnded(); Loading @@ -143,7 +157,18 @@ public class AnrLatencyTrackerTests { mLatencyTracker.waitingOnProcLockStarted(); mLatencyTracker.waitingOnProcLockEnded(); mLatencyTracker.dumpStackTracesTempFileStarted(); mLatencyTracker.dumpingPidStarted(5); mLatencyTracker.dumpStackTracesStarted(); mLatencyTracker.copyingFirstPidStarted(); mLatencyTracker.dumpingPidEnded(); mLatencyTracker.dumpStackTracesTempFileEnded(); mLatencyTracker.copyingFirstPidEnded(true); mLatencyTracker.dumpingFirstPidsStarted(); mLatencyTracker.dumpingPidStarted(1); mLatencyTracker.dumpingPidEnded(); Loading
services/core/java/com/android/server/am/AnrHelper.java +58 −13 Original line number Diff line number Diff line Loading @@ -22,6 +22,7 @@ import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NA import android.content.pm.ApplicationInfo; import android.os.SystemClock; import android.os.Trace; import android.util.ArraySet; import android.util.Slog; import com.android.internal.annotations.GuardedBy; Loading @@ -29,8 +30,12 @@ import com.android.internal.annotations.VisibleForTesting; import com.android.internal.os.TimeoutRecord; import com.android.server.wm.WindowProcessController; import java.io.File; import java.util.ArrayList; import java.util.Collections; import java.util.Set; import java.util.concurrent.ExecutorService; import java.util.concurrent.Future; import java.util.concurrent.LinkedBlockingQueue; import java.util.concurrent.ThreadFactory; import java.util.concurrent.ThreadPoolExecutor; Loading Loading @@ -59,13 +64,19 @@ class AnrHelper { /** * The keep alive time for the threads in the helper threadpool executor */ private static final int AUX_THREAD_KEEP_ALIVE_SECOND = 10; private static final int DEFAULT_THREAD_KEEP_ALIVE_SECOND = 10; private static final ThreadFactory sDefaultThreadFactory = r -> new Thread(r, "AnrAuxiliaryTaskExecutor"); private static final ThreadFactory sMainProcessDumpThreadFactory = r -> new Thread(r, "AnrMainProcessDumpThread"); @GuardedBy("mAnrRecords") private final ArrayList<AnrRecord> mAnrRecords = new ArrayList<>(); private final Set<Integer> mTempDumpedPids = Collections.synchronizedSet(new ArraySet<Integer>()); private final AtomicBoolean mRunning = new AtomicBoolean(false); private final ActivityManagerService mService; Loading @@ -80,17 +91,21 @@ class AnrHelper { private int mProcessingPid = -1; private final ExecutorService mAuxiliaryTaskExecutor; private final ExecutorService mEarlyDumpExecutor; AnrHelper(final ActivityManagerService service) { this(service, new ThreadPoolExecutor(/* corePoolSize= */ 0, /* maximumPoolSize= */ 1, /* keepAliveTime= */ AUX_THREAD_KEEP_ALIVE_SECOND, TimeUnit.SECONDS, new LinkedBlockingQueue<>(), sDefaultThreadFactory)); // All the ANR threads need to expire after a period of inactivity, given the // ephemeral nature of ANRs and how infrequent they are. this(service, makeExpiringThreadPoolWithSize(1, sDefaultThreadFactory), makeExpiringThreadPoolWithSize(2, sMainProcessDumpThreadFactory)); } @VisibleForTesting AnrHelper(ActivityManagerService service, ExecutorService auxExecutor) { AnrHelper(ActivityManagerService service, ExecutorService auxExecutor, ExecutorService earlyDumpExecutor) { mService = service; mAuxiliaryTaskExecutor = auxExecutor; mEarlyDumpExecutor = earlyDumpExecutor; } void appNotResponding(ProcessRecord anrProcess, TimeoutRecord timeoutRecord) { Loading Loading @@ -121,6 +136,12 @@ class AnrHelper { + timeoutRecord.mReason); return; } if (!mTempDumpedPids.add(incomingPid)) { Slog.i(TAG, "Skip ANR being predumped, pid=" + incomingPid + " " + timeoutRecord.mReason); return; } for (int i = mAnrRecords.size() - 1; i >= 0; i--) { if (mAnrRecords.get(i).mPid == incomingPid) { Slog.i(TAG, Loading @@ -129,10 +150,24 @@ class AnrHelper { return; } } // We dump the main process as soon as we can on a different thread, // this is done as the main process's dump can go stale in a few hundred // milliseconds and the average full ANR dump takes a few seconds. timeoutRecord.mLatencyTracker.earlyDumpRequestSubmittedWithSize( mTempDumpedPids.size()); Future<File> firstPidDumpPromise = mEarlyDumpExecutor.submit(() -> { // the class AnrLatencyTracker is not generally thread safe but the values // recorded/touched by the Temporary dump thread(s) are all volatile/atomic. File tracesFile = StackTracesDumpHelper.dumpStackTracesTempFile(incomingPid, timeoutRecord.mLatencyTracker); mTempDumpedPids.remove(incomingPid); return tracesFile; }); timeoutRecord.mLatencyTracker.anrRecordPlacingOnQueueWithSize(mAnrRecords.size()); mAnrRecords.add(new AnrRecord(anrProcess, activityShortComponentName, aInfo, parentShortComponentName, parentProcess, aboveSystem, mAuxiliaryTaskExecutor, timeoutRecord, isContinuousAnr)); parentShortComponentName, parentProcess, aboveSystem, timeoutRecord, isContinuousAnr, firstPidDumpPromise)); } startAnrConsumerIfNeeded(); } finally { Loading @@ -147,6 +182,16 @@ class AnrHelper { } } private static ThreadPoolExecutor makeExpiringThreadPoolWithSize(int size, ThreadFactory factory) { ThreadPoolExecutor pool = new ThreadPoolExecutor(/* corePoolSize= */ size, /* maximumPoolSize= */ size, /* keepAliveTime= */ DEFAULT_THREAD_KEEP_ALIVE_SECOND, TimeUnit.SECONDS, new LinkedBlockingQueue<>(), factory); // We allow the core threads to expire after the keepAliveTime. pool.allowCoreThreadTimeOut(true); return pool; } /** * The thread to execute {@link ProcessErrorStateRecord#appNotResponding}. It will terminate if * all records are handled. Loading Loading @@ -219,7 +264,7 @@ class AnrHelper { } } private static class AnrRecord { private class AnrRecord { final ProcessRecord mApp; final int mPid; final String mActivityShortComponentName; Loading @@ -228,14 +273,14 @@ class AnrHelper { final ApplicationInfo mAppInfo; final WindowProcessController mParentProcess; final boolean mAboveSystem; final ExecutorService mAuxiliaryTaskExecutor; final long mTimestamp = SystemClock.uptimeMillis(); final boolean mIsContinuousAnr; final Future<File> mFirstPidFilePromise; AnrRecord(ProcessRecord anrProcess, String activityShortComponentName, ApplicationInfo aInfo, String parentShortComponentName, WindowProcessController parentProcess, boolean aboveSystem, ExecutorService auxiliaryTaskExecutor, TimeoutRecord timeoutRecord, boolean isContinuousAnr) { TimeoutRecord timeoutRecord, boolean isContinuousAnr, Future<File> firstPidFilePromise) { mApp = anrProcess; mPid = anrProcess.mPid; mActivityShortComponentName = activityShortComponentName; Loading @@ -244,8 +289,8 @@ class AnrHelper { mAppInfo = aInfo; mParentProcess = parentProcess; mAboveSystem = aboveSystem; mAuxiliaryTaskExecutor = auxiliaryTaskExecutor; mIsContinuousAnr = isContinuousAnr; mFirstPidFilePromise = firstPidFilePromise; } void appNotResponding(boolean onlyDumpSelf) { Loading @@ -254,7 +299,7 @@ class AnrHelper { mApp.mErrorState.appNotResponding(mActivityShortComponentName, mAppInfo, mParentShortComponentName, mParentProcess, mAboveSystem, mTimeoutRecord, mAuxiliaryTaskExecutor, onlyDumpSelf, mIsContinuousAnr); mIsContinuousAnr, mFirstPidFilePromise); } finally { mTimeoutRecord.mLatencyTracker.anrProcessingEnded(); } Loading
services/core/java/com/android/server/am/ProcessErrorStateRecord.java +5 −3 Original line number Diff line number Diff line Loading @@ -287,7 +287,7 @@ class ProcessErrorStateRecord { String parentShortComponentName, WindowProcessController parentProcess, boolean aboveSystem, TimeoutRecord timeoutRecord, ExecutorService auxiliaryTaskExecutor, boolean onlyDumpSelf, boolean isContinuousAnr) { boolean isContinuousAnr, Future<File> firstPidFilePromise) { String annotation = timeoutRecord.mReason; AnrLatencyTracker latencyTracker = timeoutRecord.mLatencyTracker; Future<?> updateCpuStatsNowFirstCall = null; Loading Loading @@ -334,7 +334,6 @@ class ProcessErrorStateRecord { Counter.logIncrement("stability_anr.value_skipped_anrs"); return; } // In case we come through here for the same app before completing // this one, mark as anring now so we will bail out. latencyTracker.waitingOnProcLockStarted(); Loading Loading @@ -368,6 +367,9 @@ class ProcessErrorStateRecord { firstPids.add(pid); // Don't dump other PIDs if it's a background ANR or is requested to only dump self. // Note that the primary pid is added here just in case, as it should normally be // dumped on the early dump thread, and would only be dumped on the Anr consumer thread // as a fallback. isSilentAnr = isSilentAnr(); if (!isSilentAnr && !onlyDumpSelf) { int parentPid = pid; Loading Loading @@ -498,7 +500,7 @@ class ProcessErrorStateRecord { File tracesFile = StackTracesDumpHelper.dumpStackTraces(firstPids, isSilentAnr ? null : processCpuTracker, isSilentAnr ? null : lastPids, nativePidsFuture, tracesFileException, firstPidEndOffset, annotation, criticalEventLog, auxiliaryTaskExecutor, latencyTracker); criticalEventLog, auxiliaryTaskExecutor, firstPidFilePromise, latencyTracker); if (isMonitorCpuUsage()) { // Wait for the first call to finish Loading
services/core/java/com/android/server/am/StackTracesDumpHelper.java +161 −29 File changed.Preview size limit exceeded, changes collapsed. Show changes