Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Predump the first PID in the ANR process

Browse Source 
Dump the first ANRing process as soon as we can in a separate thread,
and copy its stack traces later in the ANRing thread

Bug: 272292150
Test: tested on a device
(cherry picked from https://googleplex-android-review.googlesource.com/q/commit:7245a5398292baa95736ad424eeeac865e14674e)
Merged-In: Ib25753734efdb8eeade065e630e80f6f7be855a0
Change-Id: Ib25753734efdb8eeade065e630e80f6f7be855a0
This commit is contained in:
Mohamad Mahmoud
2023-03-22 10:47:48 +00:00
committed by Olivier Gaillard
parent b4a8a82fa9
commit ad2df8f778
8 changed files with 376 additions and 73 deletions
Download Patch File Download Diff File Expand all files Collapse all files

121
core/java/com/android/internal/os/anr/AnrLatencyTracker.java
View File

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

29
core/tests/coretests/src/android/internal/os/anr/AnrLatencyTrackerTests.java
View File

@@ -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();

71
services/core/java/com/android/server/am/AnrHelper.java
View File

@@ -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<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;
@@ -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<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 {
@@ -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<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;
@@ -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();
}

9
services/core/java/com/android/server/am/ProcessErrorStateRecord.java
View File

@@ -290,7 +290,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;
@@ -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

192
services/core/java/com/android/server/am/StackTracesDumpHelper.java
View File

@@ -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<ArrayList<Integer>> 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<Integer> firstPids,
ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids,
Future<ArrayList<Integer>> 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<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile,
AtomicLong firstPidEndOffset, String subject, String criticalEventSection,
String memoryHeaders, @NonNull Executor auxiliaryTaskExecutor,
AnrLatencyTracker latencyTracker) {
Future<File> 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<Integer> firstPids, Future<ArrayList<Integer>> nativePidsFuture,
Future<ArrayList<Integer>> extraPidsFuture, AnrLatencyTracker latencyTracker) {
Future<ArrayList<Integer>> extraPidsFuture, Future<File> 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<File> 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

2
services/core/java/com/android/server/wm/ActivityTaskManagerService.java
View File

@@ -5356,7 +5356,7 @@ public class ActivityTaskManagerService extends IActivityTaskManager.Stub {
if (app != null && app.getPid() > 0) {
ArrayList<Integer> firstPids = new ArrayList<Integer>();
firstPids.add(app.getPid());
dumpStackTraces(tracesFile.getAbsolutePath(), firstPids, null, null, null);
dumpStackTraces(tracesFile.getAbsolutePath(), firstPids, null, null, null, null);
}
File lastTracesFile = null;

23
services/tests/servicestests/src/com/android/server/am/AnrHelperTest.java
View File

@@ -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<File> 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());
}
}

2
services/tests/servicestests/src/com/android/server/am/ProcessRecordTests.java
View File

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