diff --git a/core/java/com/android/internal/os/anr/AnrLatencyTracker.java b/core/java/com/android/internal/os/anr/AnrLatencyTracker.java index 096d1cd212be7..6fa6fa5d37f35 100644 --- a/core/java/com/android/internal/os/anr/AnrLatencyTracker.java +++ b/core/java/com/android/internal/os/anr/AnrLatencyTracker.java @@ -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; /** @@ -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(); @@ -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; @@ -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(); @@ -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(); @@ -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); @@ -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 = */ @@ -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"; } @@ -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) { diff --git a/core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java b/core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java index 4eea076343ee1..7d5a036455753 100644 --- a/core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java +++ b/core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java @@ -59,7 +59,10 @@ public class AnrLatencyTrackerTests { .thenReturn(175L) .thenReturn(198L) .thenReturn(203L) - .thenReturn(209L); + .thenReturn(209L) + .thenReturn(211L) + .thenReturn(212L) + .thenReturn(220L); } @Test @@ -68,6 +71,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.appNotRespondingStarted(); mLatencyTracker.waitingOnAnrRecordLockStarted(); mLatencyTracker.waitingOnAnrRecordLockEnded(); + mLatencyTracker.earlyDumpRequestSubmittedWithSize(5); mLatencyTracker.anrRecordPlacingOnQueueWithSize(3); mLatencyTracker.appNotRespondingEnded(); @@ -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(); @@ -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(); } @@ -121,6 +134,7 @@ public class AnrLatencyTrackerTests { mLatencyTracker.appNotRespondingStarted(); mLatencyTracker.waitingOnAnrRecordLockStarted(); mLatencyTracker.waitingOnAnrRecordLockEnded(); + mLatencyTracker.earlyDumpRequestSubmittedWithSize(5); mLatencyTracker.anrRecordPlacingOnQueueWithSize(3); mLatencyTracker.appNotRespondingEnded(); @@ -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(); diff --git a/services/core/java/com/android/server/am/AnrHelper.java b/services/core/java/com/android/server/am/AnrHelper.java index 16219cd5b2ea9..7d984434284cb 100644 --- a/services/core/java/com/android/server/am/AnrHelper.java +++ b/services/core/java/com/android/server/am/AnrHelper.java @@ -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; @@ -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; @@ -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 mAnrRecords = new ArrayList<>(); + + private final Set mTempDumpedPids = + Collections.synchronizedSet(new ArraySet()); + private final AtomicBoolean mRunning = new AtomicBoolean(false); private final ActivityManagerService mService; @@ -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) { @@ -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, @@ -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 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 { @@ -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. @@ -219,7 +264,7 @@ class AnrHelper { } } - private static class AnrRecord { + private class AnrRecord { final ProcessRecord mApp; final int mPid; final String mActivityShortComponentName; @@ -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 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 firstPidFilePromise) { mApp = anrProcess; mPid = anrProcess.mPid; mActivityShortComponentName = activityShortComponentName; @@ -244,8 +289,8 @@ class AnrHelper { mAppInfo = aInfo; mParentProcess = parentProcess; mAboveSystem = aboveSystem; - mAuxiliaryTaskExecutor = auxiliaryTaskExecutor; mIsContinuousAnr = isContinuousAnr; + mFirstPidFilePromise = firstPidFilePromise; } void appNotResponding(boolean onlyDumpSelf) { @@ -254,7 +299,7 @@ class AnrHelper { mApp.mErrorState.appNotResponding(mActivityShortComponentName, mAppInfo, mParentShortComponentName, mParentProcess, mAboveSystem, mTimeoutRecord, mAuxiliaryTaskExecutor, onlyDumpSelf, - mIsContinuousAnr); + mIsContinuousAnr, mFirstPidFilePromise); } finally { mTimeoutRecord.mLatencyTracker.anrProcessingEnded(); } diff --git a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java index ca41f429a0dec..e4983846f1dab 100644 --- a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java +++ b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java @@ -290,7 +290,7 @@ class ProcessErrorStateRecord { String parentShortComponentName, WindowProcessController parentProcess, boolean aboveSystem, TimeoutRecord timeoutRecord, ExecutorService auxiliaryTaskExecutor, boolean onlyDumpSelf, - boolean isContinuousAnr) { + boolean isContinuousAnr, Future firstPidFilePromise) { String annotation = timeoutRecord.mReason; AnrLatencyTracker latencyTracker = timeoutRecord.mLatencyTracker; Future updateCpuStatsNowFirstCall = null; @@ -335,7 +335,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(); @@ -369,6 +368,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; @@ -501,7 +503,8 @@ class ProcessErrorStateRecord { File tracesFile = StackTracesDumpHelper.dumpStackTraces(firstPids, isSilentAnr ? null : processCpuTracker, isSilentAnr ? null : lastPids, nativePidsFuture, tracesFileException, firstPidEndOffset, annotation, - criticalEventLog, memoryHeaders, auxiliaryTaskExecutor, latencyTracker); + criticalEventLog, memoryHeaders, auxiliaryTaskExecutor, firstPidFilePromise, + latencyTracker); if (isMonitorCpuUsage()) { // Wait for the first call to finish diff --git a/services/core/java/com/android/server/am/StackTracesDumpHelper.java b/services/core/java/com/android/server/am/StackTracesDumpHelper.java index 10ddc2f562dcf..01fb0d1d8b185 100644 --- a/services/core/java/com/android/server/am/StackTracesDumpHelper.java +++ b/services/core/java/com/android/server/am/StackTracesDumpHelper.java @@ -41,6 +41,7 @@ import java.io.IOException; import java.io.PrintWriter; import java.io.StringWriter; import java.nio.charset.StandardCharsets; +import java.nio.file.Files; import java.text.SimpleDateFormat; import java.util.ArrayList; import java.util.Arrays; @@ -50,6 +51,8 @@ import java.util.concurrent.CompletableFuture; import java.util.concurrent.ExecutionException; import java.util.concurrent.Executor; import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.TimeoutException; import java.util.concurrent.atomic.AtomicLong; import java.util.function.Supplier; @@ -65,11 +68,16 @@ public class StackTracesDumpHelper { new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss-SSS"); static final String ANR_FILE_PREFIX = "anr_"; - public static final String ANR_TRACE_DIR = "/data/anr"; + static final String ANR_TEMP_FILE_PREFIX = "temp_anr_"; + public static final String ANR_TRACE_DIR = "/data/anr"; private static final int NATIVE_DUMP_TIMEOUT_MS = 2000 * Build.HW_TIMEOUT_MULTIPLIER; // 2 seconds; private static final int JAVA_DUMP_MINIMUM_SIZE = 100; // 100 bytes. + // The time limit for a single process's dump + private static final int TEMP_DUMP_TIME_LIMIT = + 10 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; // 10 seconds + /** * If a stack trace dump file is configured, dump process stack traces. @@ -85,7 +93,7 @@ public class StackTracesDumpHelper { Future> nativePidsFuture, StringWriter logExceptionCreatingFile, @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) { return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture, - logExceptionCreatingFile, null, null, null, null, auxiliaryTaskExecutor, + logExceptionCreatingFile, null, null, null, null, auxiliaryTaskExecutor, null, latencyTracker); } @@ -96,11 +104,11 @@ public class StackTracesDumpHelper { public static File dumpStackTraces(ArrayList firstPids, ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids, Future> nativePidsFuture, StringWriter logExceptionCreatingFile, - String subject, String criticalEventSection, @NonNull Executor auxiliaryTaskExecutor, - AnrLatencyTracker latencyTracker) { + String subject, String criticalEventSection, + @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) { return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture, logExceptionCreatingFile, null, subject, criticalEventSection, - /* memoryHeaders= */ null, auxiliaryTaskExecutor, latencyTracker); + /* memoryHeaders= */ null, auxiliaryTaskExecutor, null, latencyTracker); } /** @@ -112,7 +120,7 @@ public class StackTracesDumpHelper { Future> nativePidsFuture, StringWriter logExceptionCreatingFile, AtomicLong firstPidEndOffset, String subject, String criticalEventSection, String memoryHeaders, @NonNull Executor auxiliaryTaskExecutor, - AnrLatencyTracker latencyTracker) { + Future firstPidFilePromise, AnrLatencyTracker latencyTracker) { try { if (latencyTracker != null) { @@ -161,7 +169,7 @@ public class StackTracesDumpHelper { long firstPidEndPos = dumpStackTraces( tracesFile.getAbsolutePath(), firstPids, nativePidsFuture, - extraPidsFuture, latencyTracker); + extraPidsFuture, firstPidFilePromise, latencyTracker); if (firstPidEndOffset != null) { firstPidEndOffset.set(firstPidEndPos); } @@ -175,7 +183,6 @@ public class StackTracesDumpHelper { latencyTracker.dumpStackTracesEnded(); } } - } /** @@ -183,7 +190,8 @@ public class StackTracesDumpHelper { */ public static long dumpStackTraces(String tracesFile, ArrayList firstPids, Future> nativePidsFuture, - Future> extraPidsFuture, AnrLatencyTracker latencyTracker) { + Future> extraPidsFuture, Future firstPidFilePromise, + AnrLatencyTracker latencyTracker) { Slog.i(TAG, "Dumping to " + tracesFile); @@ -194,33 +202,52 @@ public class StackTracesDumpHelper { // We must complete all stack dumps within 20 seconds. long remainingTime = 20 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; - // As applications are usually interested with the ANR stack traces, but we can't share with - // them the stack traces other than their own stacks. So after the very first PID is + // As applications are usually interested with the ANR stack traces, but we can't share + // with them the stack traces other than their own stacks. So after the very first PID is // dumped, remember the current file size. long firstPidEnd = -1; - // First collect all of the stacks of the most important pids. - if (firstPids != null) { + // Was the first pid copied from the temporary file that was created in the predump phase? + boolean firstPidTempDumpCopied = false; + + // First copy the first pid's dump from the temporary file it was dumped into earlier, + // The first pid should always exist in firstPids but we check the size just in case. + if (firstPidFilePromise != null && firstPids != null && firstPids.size() > 0) { + final int primaryPid = firstPids.get(0); + final long start = SystemClock.elapsedRealtime(); + firstPidTempDumpCopied = copyFirstPidTempDump(tracesFile, firstPidFilePromise, + remainingTime, latencyTracker); + final long timeTaken = SystemClock.elapsedRealtime() - start; + remainingTime -= timeTaken; + if (remainingTime <= 0) { + Slog.e(TAG, "Aborting stack trace dump (currently copying primary pid" + primaryPid + + "); deadline exceeded."); + return firstPidEnd; + } + // We don't copy ANR traces from the system_server intentionally. + if (firstPidTempDumpCopied && primaryPid != ActivityManagerService.MY_PID) { + firstPidEnd = new File(tracesFile).length(); + } + // Append the Durations/latency comma separated array after the first PID. + if (latencyTracker != null) { + appendtoANRFile(tracesFile, + latencyTracker.dumpAsCommaSeparatedArrayWithHeader()); + } + } + // Next collect all of the stacks of the most important pids. + if (firstPids != null) { if (latencyTracker != null) { latencyTracker.dumpingFirstPidsStarted(); } int num = firstPids.size(); - for (int i = 0; i < num; i++) { + for (int i = firstPidTempDumpCopied ? 1 : 0; i < num; i++) { final int pid = firstPids.get(i); // We don't copy ANR traces from the system_server intentionally. final boolean firstPid = i == 0 && ActivityManagerService.MY_PID != pid; - if (latencyTracker != null) { - latencyTracker.dumpingPidStarted(pid); - } - Slog.i(TAG, "Collecting stacks for pid " + pid); - final long timeTaken = dumpJavaTracesTombstoned(pid, tracesFile, - remainingTime); - if (latencyTracker != null) { - latencyTracker.dumpingPidEnded(); - } - + final long timeTaken = dumpJavaTracesTombstoned(pid, tracesFile, remainingTime, + latencyTracker); remainingTime -= timeTaken; if (remainingTime <= 0) { Slog.e(TAG, "Aborting stack trace dump (current firstPid=" + pid @@ -304,13 +331,8 @@ public class StackTracesDumpHelper { } for (int pid : extraPids) { Slog.i(TAG, "Collecting stacks for extra pid " + pid); - if (latencyTracker != null) { - latencyTracker.dumpingPidStarted(pid); - } - final long timeTaken = dumpJavaTracesTombstoned(pid, tracesFile, remainingTime); - if (latencyTracker != null) { - latencyTracker.dumpingPidEnded(); - } + final long timeTaken = dumpJavaTracesTombstoned(pid, tracesFile, remainingTime, + latencyTracker); remainingTime -= timeTaken; if (remainingTime <= 0) { Slog.e(TAG, "Aborting stack trace dump (current extra pid=" + pid @@ -333,6 +355,99 @@ public class StackTracesDumpHelper { return firstPidEnd; } + /** + * Dumps the supplied pid to a temporary file. + * @param pid the PID to be dumped + * @param latencyTracker the latency tracker instance of the current ANR. + */ + public static File dumpStackTracesTempFile(int pid, AnrLatencyTracker latencyTracker) { + try { + if (latencyTracker != null) { + latencyTracker.dumpStackTracesTempFileStarted(); + } + + File tmpTracesFile; + try { + tmpTracesFile = File.createTempFile(ANR_TEMP_FILE_PREFIX, ".txt", + new File(ANR_TRACE_DIR)); + Slog.d(TAG, "created ANR temporary file:" + tmpTracesFile.getAbsolutePath()); + } catch (IOException e) { + Slog.w(TAG, "Exception creating temporary ANR dump file:", e); + if (latencyTracker != null) { + latencyTracker.dumpStackTracesTempFileCreationFailed(); + } + return null; + } + + Slog.i(TAG, "Collecting stacks for pid " + pid + " into temporary file " + + tmpTracesFile.getName()); + if (latencyTracker != null) { + latencyTracker.dumpingPidStarted(pid); + } + final long timeTaken = dumpJavaTracesTombstoned(pid, tmpTracesFile.getAbsolutePath(), + TEMP_DUMP_TIME_LIMIT); + if (latencyTracker != null) { + latencyTracker.dumpingPidEnded(); + } + if (TEMP_DUMP_TIME_LIMIT <= timeTaken) { + Slog.e(TAG, "Aborted stack trace dump (current primary pid=" + pid + + "); deadline exceeded."); + tmpTracesFile.delete(); + if (latencyTracker != null) { + latencyTracker.dumpStackTracesTempFileTimedOut(); + } + return null; + } + if (DEBUG_ANR) { + Slog.d(TAG, "Done with primary pid " + pid + " in " + timeTaken + "ms" + + " dumped into temporary file " + tmpTracesFile.getName()); + } + return tmpTracesFile; + } finally { + if (latencyTracker != null) { + latencyTracker.dumpStackTracesTempFileEnded(); + } + } + } + + private static boolean copyFirstPidTempDump(String tracesFile, Future firstPidFilePromise, + long timeLimitMs, AnrLatencyTracker latencyTracker) { + + boolean copySucceeded = false; + try (FileOutputStream fos = new FileOutputStream(tracesFile, true)) { + if (latencyTracker != null) { + latencyTracker.copyingFirstPidStarted(); + } + final File tempfile = firstPidFilePromise.get(timeLimitMs, TimeUnit.MILLISECONDS); + if (tempfile != null) { + Files.copy(tempfile.toPath(), fos); + // Delete the temporary first pid dump file + tempfile.delete(); + copySucceeded = true; + return copySucceeded; + } + return false; + } catch (ExecutionException e) { + Slog.w(TAG, "Failed to collect the first pid's predump to the main ANR file", + e.getCause()); + return false; + } catch (InterruptedException e) { + Slog.w(TAG, "Interrupted while collecting the first pid's predump" + + " to the main ANR file", e); + return false; + } catch (IOException e) { + Slog.w(TAG, "Failed to read the first pid's predump file", e); + return false; + } catch (TimeoutException e) { + Slog.w(TAG, "Copying the first pid timed out", e); + return false; + } finally { + if (latencyTracker != null) { + latencyTracker.copyingFirstPidEnded(copySucceeded); + } + } + } + private static synchronized File createAnrDumpFile(File tracesDir) throws IOException { final String formattedDate = ANR_FILE_DATE_FORMAT.format(new Date()); final File anrFile = new File(tracesDir, ANR_FILE_PREFIX + formattedDate); @@ -409,6 +524,21 @@ public class StackTracesDumpHelper { Slog.w(TAG, "tombstone modification times changed while sorting; not pruning", e); } } + + private static long dumpJavaTracesTombstoned(int pid, String fileName, long timeoutMs, + AnrLatencyTracker latencyTracker) { + try { + if (latencyTracker != null) { + latencyTracker.dumpingPidStarted(pid); + } + return dumpJavaTracesTombstoned(pid, fileName, timeoutMs); + } finally { + if (latencyTracker != null) { + latencyTracker.dumpingPidEnded(); + } + } + } + /** * Dump java traces for process {@code pid} to the specified file. If java trace dumping * fails, a native backtrace is attempted. Note that the timeout {@code timeoutMs} only applies diff --git a/services/core/java/com/android/server/wm/ActivityTaskManagerService.java b/services/core/java/com/android/server/wm/ActivityTaskManagerService.java index 431f82a4f55c6..401c16f7f76ac 100644 --- a/services/core/java/com/android/server/wm/ActivityTaskManagerService.java +++ b/services/core/java/com/android/server/wm/ActivityTaskManagerService.java @@ -5356,7 +5356,7 @@ public class ActivityTaskManagerService extends IActivityTaskManager.Stub { if (app != null && app.getPid() > 0) { ArrayList firstPids = new ArrayList(); firstPids.add(app.getPid()); - dumpStackTraces(tracesFile.getAbsolutePath(), firstPids, null, null, null); + dumpStackTraces(tracesFile.getAbsolutePath(), firstPids, null, null, null, null); } File lastTracesFile = null; diff --git a/services/tests/servicestests/src/com/android/server/am/AnrHelperTest.java b/services/tests/servicestests/src/com/android/server/am/AnrHelperTest.java index 9578993ea452b..acdfee9af5570 100644 --- a/services/tests/servicestests/src/com/android/server/am/AnrHelperTest.java +++ b/services/tests/servicestests/src/com/android/server/am/AnrHelperTest.java @@ -26,6 +26,7 @@ import static org.mockito.ArgumentMatchers.anyBoolean; import static org.mockito.ArgumentMatchers.anyString; import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.doAnswer; +import static org.mockito.Mockito.doReturn; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.timeout; import static org.mockito.Mockito.verify; @@ -48,8 +49,10 @@ import org.junit.Test; import java.io.File; import java.lang.reflect.Field; import java.lang.reflect.Modifier; +import java.util.concurrent.Callable; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; +import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; /** @@ -63,8 +66,9 @@ public class AnrHelperTest { private AnrHelper mAnrHelper; private ProcessRecord mAnrApp; - private ExecutorService mExecutorService; + private ExecutorService mAuxExecutorService; + private Future mEarlyDumpFuture; @Rule public ServiceThreadRule mServiceThreadRule = new ServiceThreadRule(); @@ -91,9 +95,12 @@ public class AnrHelperTest { return mServiceThreadRule.getThread().getThreadHandler(); } }, mServiceThreadRule.getThread()); - mExecutorService = mock(ExecutorService.class); + mAuxExecutorService = mock(ExecutorService.class); + final ExecutorService earlyDumpExecutorService = mock(ExecutorService.class); + mEarlyDumpFuture = mock(Future.class); + doReturn(mEarlyDumpFuture).when(earlyDumpExecutorService).submit(any(Callable.class)); - mAnrHelper = new AnrHelper(service, mExecutorService); + mAnrHelper = new AnrHelper(service, mAuxExecutorService, earlyDumpExecutorService); }); } @@ -125,8 +132,8 @@ public class AnrHelperTest { verify(mAnrApp.mErrorState, timeout(TIMEOUT_MS)).appNotResponding( eq(activityShortComponentName), eq(appInfo), eq(parentShortComponentName), - eq(parentProcess), eq(aboveSystem), eq(timeoutRecord), eq(mExecutorService), - eq(false) /* onlyDumpSelf */, eq(false) /*isContinuousAnr*/); + eq(parentProcess), eq(aboveSystem), eq(timeoutRecord), eq(mAuxExecutorService), + eq(false) /* onlyDumpSelf */, eq(false) /*isContinuousAnr*/, eq(mEarlyDumpFuture)); } @Test @@ -139,7 +146,7 @@ public class AnrHelperTest { processingLatch.await(); return null; }).when(mAnrApp.mErrorState).appNotResponding(anyString(), any(), any(), any(), - anyBoolean(), any(), any(), anyBoolean(), anyBoolean()); + anyBoolean(), any(), any(), anyBoolean(), anyBoolean(), any()); final ApplicationInfo appInfo = new ApplicationInfo(); final TimeoutRecord timeoutRecord = TimeoutRecord.forInputDispatchWindowUnresponsive( "annotation"); @@ -162,7 +169,7 @@ public class AnrHelperTest { processingLatch.countDown(); // There is only one ANR reported. verify(mAnrApp.mErrorState, timeout(TIMEOUT_MS).only()).appNotResponding( - anyString(), any(), any(), any(), anyBoolean(), any(), eq(mExecutorService), - anyBoolean(), anyBoolean()); + anyString(), any(), any(), any(), anyBoolean(), any(), eq(mAuxExecutorService), + anyBoolean(), anyBoolean(), any()); } } diff --git a/services/tests/servicestests/src/com/android/server/am/ProcessRecordTests.java b/services/tests/servicestests/src/com/android/server/am/ProcessRecordTests.java index 6350e225a429a..d92b9f8ae736e 100644 --- a/services/tests/servicestests/src/com/android/server/am/ProcessRecordTests.java +++ b/services/tests/servicestests/src/com/android/server/am/ProcessRecordTests.java @@ -203,6 +203,6 @@ public class ProcessRecordTests { processErrorState.appNotResponding(null /* activityShortComponentName */, null /* aInfo */, null /* parentShortComponentName */, null /* parentProcess */, false /* aboveSystem */, timeoutRecord, mExecutorService, false /* onlyDumpSelf */, - false /*isContinuousAnr*/); + false /*isContinuousAnr*/, null); } }