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

Merge "Predump the first PID in the ANR process" into udc-dev

Browse Source
This commit is contained in:
Treehugger Robot
2023-04-14 18:46:56 +00:00
committed by Android (Google) Code Review
parent 75bd5713c1 ad2df8f778
commit 4058dfc187
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);
}
}