diff options
9 files changed, 497 insertions, 458 deletions
diff --git a/core/java/com/android/internal/os/anr/AnrLatencyTracker.java b/core/java/com/android/internal/os/anr/AnrLatencyTracker.java index 6a6165687981..096d1cd212be 100644 --- a/core/java/com/android/internal/os/anr/AnrLatencyTracker.java +++ b/core/java/com/android/internal/os/anr/AnrLatencyTracker.java @@ -137,14 +137,14 @@ public class AnrLatencyTracker implements AutoCloseable { close(); } - /** Records the start of ActivityManagerService#dumpStackTraces. */ + /** Records the start of StackTracesDumpHelper#dumpStackTraces. */ public void dumpStackTracesStarted() { mDumpStackTracesStartUptime = getUptimeMillis(); Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "dumpStackTraces()"); } - /** Records the end of ActivityManagerService#dumpStackTraces. */ + /** Records the end of StackTracesDumpHelper#dumpStackTraces. */ public void dumpStackTracesEnded() { Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER); } @@ -328,7 +328,7 @@ public class AnrLatencyTracker implements AutoCloseable { anrSkipped("appNotResponding"); } - /** Records a skipped ANR in ActivityManagerService#dumpStackTraces. */ + /** Records a skipped ANR in StackTracesDumpHelper#dumpStackTraces. */ public void anrSkippedDumpStackTraces() { anrSkipped("dumpStackTraces"); } diff --git a/services/core/java/com/android/server/SystemServerInitThreadPool.java b/services/core/java/com/android/server/SystemServerInitThreadPool.java index 7f24c52ccc6b..3d3535d2dbd2 100644 --- a/services/core/java/com/android/server/SystemServerInitThreadPool.java +++ b/services/core/java/com/android/server/SystemServerInitThreadPool.java @@ -25,7 +25,7 @@ import android.util.Slog; import com.android.internal.annotations.GuardedBy; import com.android.internal.util.ConcurrentUtils; import com.android.internal.util.Preconditions; -import com.android.server.am.ActivityManagerService; +import com.android.server.am.StackTracesDumpHelper; import com.android.server.utils.TimingsTraceAndSlog; import java.io.PrintWriter; @@ -188,12 +188,12 @@ public final class SystemServerInitThreadPool implements Dumpable { } /** - * A helper function to call ActivityManagerService.dumpStackTraces(). + * A helper function to call StackTracesDumpHelper.dumpStackTraces(). */ private static void dumpStackTraces() { final ArrayList<Integer> pids = new ArrayList<>(); pids.add(Process.myPid()); - ActivityManagerService.dumpStackTraces(pids, + StackTracesDumpHelper.dumpStackTraces(pids, /* processCpuTracker= */null, /* lastPids= */null, CompletableFuture.completedFuture(Watchdog.getInterestingNativePids()), /* logExceptionCreatingFile= */null, /* subject= */null, diff --git a/services/core/java/com/android/server/Watchdog.java b/services/core/java/com/android/server/Watchdog.java index 03821db3e43f..62651dd80cd9 100644 --- a/services/core/java/com/android/server/Watchdog.java +++ b/services/core/java/com/android/server/Watchdog.java @@ -56,6 +56,7 @@ import com.android.internal.os.ProcessCpuTracker; import com.android.internal.os.ZygoteConnectionConstants; import com.android.internal.util.FrameworkStatsLog; import com.android.server.am.ActivityManagerService; +import com.android.server.am.StackTracesDumpHelper; import com.android.server.am.TraceErrorLogger; import com.android.server.criticalevents.CriticalEventLog; import com.android.server.wm.SurfaceAnimationThread; @@ -905,7 +906,7 @@ public class Watchdog implements Dumpable { report.append(ResourcePressureUtil.currentPsiState()); ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(false); StringWriter tracesFileException = new StringWriter(); - final File stack = ActivityManagerService.dumpStackTraces( + final File stack = StackTracesDumpHelper.dumpStackTraces( pids, processCpuTracker, new SparseBooleanArray(), CompletableFuture.completedFuture(getInterestingNativePids()), tracesFileException, subject, criticalEvents, Runnable::run, /* latencyTracker= */null); diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index f2b6306aab5b..713b993824f9 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -114,7 +114,6 @@ import static android.os.Process.setThreadScheduler; import static android.provider.Settings.Global.ALWAYS_FINISH_ACTIVITIES; import static android.provider.Settings.Global.DEBUG_APP; import static android.provider.Settings.Global.WAIT_FOR_DEBUGGER; -import static android.text.format.DateUtils.DAY_IN_MILLIS; import static android.util.FeatureFlagUtils.SETTINGS_ENABLE_MONITOR_PHANTOM_PROCS; import static android.view.Display.INVALID_DISPLAY; @@ -123,7 +122,6 @@ import static com.android.internal.util.FrameworkStatsLog.UNSAFE_INTENT_EVENT_RE import static com.android.internal.util.FrameworkStatsLog.UNSAFE_INTENT_EVENT_REPORTED__EVENT_TYPE__NEW_MUTABLE_IMPLICIT_PENDING_INTENT_RETRIEVED; import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_ALL; import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_ALLOWLISTS; -import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_ANR; import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BACKGROUND_CHECK; import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BACKUP; import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST; @@ -372,7 +370,6 @@ import android.util.Pair; import android.util.PrintWriterPrinter; import android.util.Slog; import android.util.SparseArray; -import android.util.SparseBooleanArray; import android.util.SparseIntArray; import android.util.TimeUtils; import android.util.proto.ProtoOutputStream; @@ -409,7 +406,6 @@ import com.android.internal.os.SomeArgs; import com.android.internal.os.TimeoutRecord; import com.android.internal.os.TransferPipe; import com.android.internal.os.Zygote; -import com.android.internal.os.anr.AnrLatencyTracker; import com.android.internal.policy.AttributeCache; import com.android.internal.protolog.common.ProtoLog; import com.android.internal.util.ArrayUtils; @@ -488,14 +484,10 @@ import java.io.FileOutputStream; import java.io.IOException; import java.io.InputStreamReader; import java.io.PrintWriter; -import java.io.StringWriter; -import java.nio.charset.StandardCharsets; -import java.text.SimpleDateFormat; import java.util.ArrayList; import java.util.Arrays; import java.util.Collections; import java.util.Comparator; -import java.util.Date; import java.util.HashMap; import java.util.HashSet; import java.util.Iterator; @@ -506,18 +498,13 @@ import java.util.Map; import java.util.Objects; import java.util.Set; import java.util.UUID; -import java.util.concurrent.CompletableFuture; import java.util.concurrent.CopyOnWriteArrayList; import java.util.concurrent.CountDownLatch; -import java.util.concurrent.ExecutionException; import java.util.concurrent.Executor; -import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; -import java.util.concurrent.atomic.AtomicLong; import java.util.function.BiFunction; import java.util.function.Consumer; -import java.util.function.Supplier; public class ActivityManagerService extends IActivityManager.Stub implements Watchdog.Monitor, BatteryStatsImpl.BatteryCallback, ActivityManagerGlobalLock { @@ -555,8 +542,6 @@ public class ActivityManagerService extends IActivityManager.Stub static final String SYSTEM_USER_HOME_NEEDED = "ro.system_user_home_needed"; - public static final String ANR_TRACE_DIR = "/data/anr"; - // Maximum number of receivers an app can register. private static final int MAX_RECEIVERS_ALLOWED_PER_APP = 1000; @@ -618,10 +603,6 @@ public class ActivityManagerService extends IActivityManager.Stub private static final int MAX_BUGREPORT_TITLE_SIZE = 100; private static final int MAX_BUGREPORT_DESCRIPTION_SIZE = 150; - 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. - OomAdjuster mOomAdjuster; static final String EXTRA_TITLE = "android.intent.extra.TITLE"; @@ -3428,432 +3409,6 @@ public class ActivityManagerService extends IActivityManager.Stub } } - /** - * If a stack trace dump file is configured, dump process stack traces. - * @param firstPids of dalvik VM processes to dump stack traces for first - * @param lastPids of dalvik VM processes to dump stack traces for last - * @param nativePids optional list of native pids to dump stack crawls - * @param logExceptionCreatingFile optional writer to which we log errors creating the file - * @param auxiliaryTaskExecutor executor to execute auxiliary tasks on - * @param latencyTracker the latency tracker instance of the current ANR. - */ - public static File dumpStackTraces(ArrayList<Integer> firstPids, - ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids, - Future<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile, - @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) { - return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture, - logExceptionCreatingFile, null, null, null, auxiliaryTaskExecutor, latencyTracker); - } - - /** - * If a stack trace dump file is configured, dump process stack traces. - * @param firstPids of dalvik VM processes to dump stack traces for first - * @param lastPids of dalvik VM processes to dump stack traces for last - * @param nativePids optional list of native pids to dump stack crawls - * @param logExceptionCreatingFile optional writer to which we log errors creating the file - * @param subject optional line related to the error - * @param criticalEventSection optional lines containing recent critical events. - * @param auxiliaryTaskExecutor executor to execute auxiliary tasks on - * @param latencyTracker the latency tracker instance of the current ANR. - */ - 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) { - return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture, - logExceptionCreatingFile, null, subject, criticalEventSection, - auxiliaryTaskExecutor, latencyTracker); - } - - /** - * @param firstPidEndOffset Optional, when it's set, it receives the start/end offset - * of the very first pid to be dumped. - */ - /* package */ static File dumpStackTraces(ArrayList<Integer> firstPids, - ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids, - Future<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile, - AtomicLong firstPidEndOffset, String subject, String criticalEventSection, - @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) { - try { - - if (latencyTracker != null) { - latencyTracker.dumpStackTracesStarted(); - } - - Slog.i(TAG, "dumpStackTraces pids=" + lastPids); - - // Measure CPU usage as soon as we're called in order to get a realistic sampling - // of the top users at the time of the request. - Supplier<ArrayList<Integer>> extraPidsSupplier = processCpuTracker != null - ? () -> getExtraPids(processCpuTracker, lastPids, latencyTracker) : null; - Future<ArrayList<Integer>> extraPidsFuture = null; - if (extraPidsSupplier != null) { - extraPidsFuture = - CompletableFuture.supplyAsync(extraPidsSupplier, auxiliaryTaskExecutor); - } - - final File tracesDir = new File(ANR_TRACE_DIR); - - // NOTE: We should consider creating the file in native code atomically once we've - // gotten rid of the old scheme of dumping and lot of the code that deals with paths - // can be removed. - File tracesFile; - try { - tracesFile = createAnrDumpFile(tracesDir); - } catch (IOException e) { - Slog.w(TAG, "Exception creating ANR dump file:", e); - if (logExceptionCreatingFile != null) { - logExceptionCreatingFile.append( - "----- Exception creating ANR dump file -----\n"); - e.printStackTrace(new PrintWriter(logExceptionCreatingFile)); - } - if (latencyTracker != null) { - latencyTracker.anrSkippedDumpStackTraces(); - } - return null; - } - - if (subject != null || criticalEventSection != null) { - appendtoANRFile(tracesFile.getAbsolutePath(), - (subject != null ? "Subject: " + subject + "\n\n" : "") - + (criticalEventSection != null ? criticalEventSection : "")); - } - - long firstPidEndPos = dumpStackTraces( - tracesFile.getAbsolutePath(), firstPids, nativePidsFuture, - extraPidsFuture, latencyTracker); - if (firstPidEndOffset != null) { - firstPidEndOffset.set(firstPidEndPos); - } - // Each set of ANR traces is written to a separate file and dumpstate will process - // all such files and add them to a captured bug report if they're recent enough. - maybePruneOldTraces(tracesDir); - - return tracesFile; - } finally { - if (latencyTracker != null) { - latencyTracker.dumpStackTracesEnded(); - } - } - - } - - @GuardedBy("ActivityManagerService.class") - private static SimpleDateFormat sAnrFileDateFormat; - static final String ANR_FILE_PREFIX = "anr_"; - - private static ArrayList<Integer> getExtraPids(ProcessCpuTracker processCpuTracker, - SparseBooleanArray lastPids, AnrLatencyTracker latencyTracker) { - if (latencyTracker != null) { - latencyTracker.processCpuTrackerMethodsCalled(); - } - ArrayList<Integer> extraPids = new ArrayList<>(); - processCpuTracker.init(); - try { - Thread.sleep(200); - } catch (InterruptedException ignored) { - } - - processCpuTracker.update(); - - // We'll take the stack crawls of just the top apps using CPU. - final int workingStatsNumber = processCpuTracker.countWorkingStats(); - for (int i = 0; i < workingStatsNumber && extraPids.size() < 2; i++) { - ProcessCpuTracker.Stats stats = processCpuTracker.getWorkingStats(i); - if (lastPids.indexOfKey(stats.pid) >= 0) { - if (DEBUG_ANR) { - Slog.d(TAG, "Collecting stacks for extra pid " + stats.pid); - } - - extraPids.add(stats.pid); - } else { - Slog.i(TAG, - "Skipping next CPU consuming process, not a java proc: " - + stats.pid); - } - } - if (latencyTracker != null) { - latencyTracker.processCpuTrackerMethodsReturned(); - } - return extraPids; - } - - private static synchronized File createAnrDumpFile(File tracesDir) throws IOException { - if (sAnrFileDateFormat == null) { - sAnrFileDateFormat = new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss-SSS"); - } - - final String formattedDate = sAnrFileDateFormat.format(new Date()); - final File anrFile = new File(tracesDir, ANR_FILE_PREFIX + formattedDate); - - if (anrFile.createNewFile()) { - FileUtils.setPermissions(anrFile.getAbsolutePath(), 0600, -1, -1); // -rw------- - return anrFile; - } else { - throw new IOException("Unable to create ANR dump file: createNewFile failed"); - } - } - - /** - * Prune all trace files that are more than a day old. - * - * NOTE: It might make sense to move this functionality to tombstoned eventually, along with a - * shift away from anr_XX and tombstone_XX to a more descriptive name. We do it here for now - * since it's the system_server that creates trace files for most ANRs. - */ - private static void maybePruneOldTraces(File tracesDir) { - final File[] files = tracesDir.listFiles(); - if (files == null) return; - - final int max = SystemProperties.getInt("tombstoned.max_anr_count", 64); - final long now = System.currentTimeMillis(); - try { - Arrays.sort(files, Comparator.comparingLong(File::lastModified).reversed()); - for (int i = 0; i < files.length; ++i) { - if (i > max || (now - files[i].lastModified()) > DAY_IN_MILLIS) { - if (!files[i].delete()) { - Slog.w(TAG, "Unable to prune stale trace file: " + files[i]); - } - } - } - } catch (IllegalArgumentException e) { - // The modification times changed while we were sorting. Bail... - // https://issuetracker.google.com/169836837 - Slog.w(TAG, "tombstone modification times changed while sorting; not pruning", e); - } - } - - /** - * 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 - * to the java section of the trace, a further {@code NATIVE_DUMP_TIMEOUT_MS} might be spent - * attempting to obtain native traces in the case of a failure. Returns the total time spent - * capturing traces. - */ - private static long dumpJavaTracesTombstoned(int pid, String fileName, long timeoutMs) { - final long timeStart = SystemClock.elapsedRealtime(); - int headerSize = writeUptimeStartHeaderForPid(pid, fileName); - boolean javaSuccess = Debug.dumpJavaBacktraceToFileTimeout(pid, fileName, - (int) (timeoutMs / 1000)); - if (javaSuccess) { - // Check that something is in the file, actually. Try-catch should not be necessary, - // but better safe than sorry. - try { - long size = new File(fileName).length(); - if ((size - headerSize) < JAVA_DUMP_MINIMUM_SIZE) { - Slog.w(TAG, "Successfully created Java ANR file is empty!"); - javaSuccess = false; - } - } catch (Exception e) { - Slog.w(TAG, "Unable to get ANR file size", e); - javaSuccess = false; - } - } - if (!javaSuccess) { - Slog.w(TAG, "Dumping Java threads failed, initiating native stack dump."); - if (!Debug.dumpNativeBacktraceToFileTimeout(pid, fileName, - (NATIVE_DUMP_TIMEOUT_MS / 1000))) { - Slog.w(TAG, "Native stack dump failed!"); - } - } - - return SystemClock.elapsedRealtime() - timeStart; - } - - private static int appendtoANRFile(String fileName, String text) { - try (FileOutputStream fos = new FileOutputStream(fileName, true)) { - byte[] header = text.getBytes(StandardCharsets.UTF_8); - fos.write(header); - return header.length; - } catch (IOException e) { - Slog.w(TAG, "Exception writing to ANR dump file:", e); - return 0; - } - } - - /* - * Writes a header containing the process id and the current system uptime. - */ - private static int writeUptimeStartHeaderForPid(int pid, String fileName) { - return appendtoANRFile(fileName, "----- dumping pid: " + pid + " at " - + SystemClock.uptimeMillis() + "\n"); - } - - - /** - * @return The end offset of the trace of the very first PID - */ - public static long dumpStackTraces(String tracesFile, - ArrayList<Integer> firstPids, Future<ArrayList<Integer>> nativePidsFuture, - Future<ArrayList<Integer>> extraPidsFuture, AnrLatencyTracker latencyTracker) { - - Slog.i(TAG, "Dumping to " + tracesFile); - - // We don't need any sort of inotify based monitoring when we're dumping traces via - // tombstoned. Data is piped to an "intercept" FD installed in tombstoned so we're in full - // control of all writes to the file in question. - - // 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 - // dumped, remember the current file size. - long firstPidEnd = -1; - - // First 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++) { - final int pid = firstPids.get(i); - // We don't copy ANR traces from the system_server intentionally. - final boolean firstPid = i == 0 && 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(); - } - - remainingTime -= timeTaken; - if (remainingTime <= 0) { - Slog.e(TAG, "Aborting stack trace dump (current firstPid=" + pid - + "); deadline exceeded."); - return firstPidEnd; - } - - if (firstPid) { - firstPidEnd = new File(tracesFile).length(); - // Full latency dump - if (latencyTracker != null) { - appendtoANRFile(tracesFile, - latencyTracker.dumpAsCommaSeparatedArrayWithHeader()); - } - } - if (DEBUG_ANR) { - Slog.d(TAG, "Done with pid " + firstPids.get(i) + " in " + timeTaken + "ms"); - } - } - if (latencyTracker != null) { - latencyTracker.dumpingFirstPidsEnded(); - } - } - - // Next collect the stacks of the native pids - ArrayList<Integer> nativePids = collectPids(nativePidsFuture, "native pids"); - - Slog.i(TAG, "dumpStackTraces nativepids=" + nativePids); - - if (nativePids != null) { - if (latencyTracker != null) { - latencyTracker.dumpingNativePidsStarted(); - } - for (int pid : nativePids) { - Slog.i(TAG, "Collecting stacks for native pid " + pid); - final long nativeDumpTimeoutMs = Math.min(NATIVE_DUMP_TIMEOUT_MS, remainingTime); - - if (latencyTracker != null) { - latencyTracker.dumpingPidStarted(pid); - } - final long start = SystemClock.elapsedRealtime(); - Debug.dumpNativeBacktraceToFileTimeout( - pid, tracesFile, (int) (nativeDumpTimeoutMs / 1000)); - final long timeTaken = SystemClock.elapsedRealtime() - start; - if (latencyTracker != null) { - latencyTracker.dumpingPidEnded(); - } - remainingTime -= timeTaken; - if (remainingTime <= 0) { - Slog.e(TAG, "Aborting stack trace dump (current native pid=" + pid + - "); deadline exceeded."); - return firstPidEnd; - } - - if (DEBUG_ANR) { - Slog.d(TAG, "Done with native pid " + pid + " in " + timeTaken + "ms"); - } - } - if (latencyTracker != null) { - latencyTracker.dumpingNativePidsEnded(); - } - } - - // Lastly, dump stacks for all extra PIDs from the CPU tracker. - ArrayList<Integer> extraPids = collectPids(extraPidsFuture, "extra pids"); - - if (extraPidsFuture != null) { - try { - extraPids = extraPidsFuture.get(); - } catch (ExecutionException e) { - Slog.w(TAG, "Failed to collect extra pids", e.getCause()); - } catch (InterruptedException e) { - Slog.w(TAG, "Interrupted while collecting extra pids", e); - } - } - Slog.i(TAG, "dumpStackTraces extraPids=" + extraPids); - - if (extraPids != null) { - if (latencyTracker != null) { - latencyTracker.dumpingExtraPidsStarted(); - } - 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(); - } - remainingTime -= timeTaken; - if (remainingTime <= 0) { - Slog.e(TAG, "Aborting stack trace dump (current extra pid=" + pid + - "); deadline exceeded."); - return firstPidEnd; - } - - if (DEBUG_ANR) { - Slog.d(TAG, "Done with extra pid " + pid + " in " + timeTaken + "ms"); - } - } - if (latencyTracker != null) { - latencyTracker.dumpingExtraPidsEnded(); - } - } - // Append the dumping footer with the current uptime - appendtoANRFile(tracesFile, "----- dumping ended at " + SystemClock.uptimeMillis() + "\n"); - Slog.i(TAG, "Done dumping"); - - return firstPidEnd; - } - - private static ArrayList<Integer> collectPids(Future<ArrayList<Integer>> pidsFuture, - String logName) { - - ArrayList<Integer> pids = null; - - if (pidsFuture == null) { - return pids; - } - try { - pids = pidsFuture.get(); - } catch (ExecutionException e) { - Slog.w(TAG, "Failed to collect " + logName, e.getCause()); - } catch (InterruptedException e) { - Slog.w(TAG, "Interrupted while collecting " + logName , e); - } - return pids; - } - @Override public boolean clearApplicationUserData(final String packageName, boolean keepState, final IPackageDataObserver observer, int userId) { diff --git a/services/core/java/com/android/server/am/AppExitInfoTracker.java b/services/core/java/com/android/server/am/AppExitInfoTracker.java index 1ba326680fc2..44436369fb31 100644 --- a/services/core/java/com/android/server/am/AppExitInfoTracker.java +++ b/services/core/java/com/android/server/am/AppExitInfoTracker.java @@ -1153,7 +1153,7 @@ public final class AppExitInfoTracker { final ArraySet<String> allFiles = new ArraySet(); final File[] files = mProcExitStoreDir.listFiles((f) -> { final String name = f.getName(); - boolean trace = name.startsWith(ActivityManagerService.ANR_FILE_PREFIX) + boolean trace = name.startsWith(StackTracesDumpHelper.ANR_FILE_PREFIX) && name.endsWith(APP_TRACE_FILE_SUFFIX); if (trace) { allFiles.add(name); diff --git a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java index 2517c9c1ea4b..1d48cb25f03a 100644 --- a/services/core/java/com/android/server/am/ProcessErrorStateRecord.java +++ b/services/core/java/com/android/server/am/ProcessErrorStateRecord.java @@ -493,7 +493,7 @@ class ProcessErrorStateRecord { StringWriter tracesFileException = new StringWriter(); // To hold the start and end offset to the ANR trace file respectively. final AtomicLong firstPidEndOffset = new AtomicLong(-1); - File tracesFile = ActivityManagerService.dumpStackTraces(firstPids, + File tracesFile = StackTracesDumpHelper.dumpStackTraces(firstPids, isSilentAnr ? null : processCpuTracker, isSilentAnr ? null : lastPids, nativePidsFuture, tracesFileException, firstPidEndOffset, annotation, criticalEventLog, auxiliaryTaskExecutor, latencyTracker); diff --git a/services/core/java/com/android/server/am/StackTracesDumpHelper.java b/services/core/java/com/android/server/am/StackTracesDumpHelper.java new file mode 100644 index 000000000000..937332894dbd --- /dev/null +++ b/services/core/java/com/android/server/am/StackTracesDumpHelper.java @@ -0,0 +1,483 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.server.am; + +import static android.text.format.DateUtils.DAY_IN_MILLIS; + +import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_ANR; +import static com.android.server.am.ActivityManagerDebugConfig.TAG_AM; +import static com.android.server.am.ActivityManagerDebugConfig.TAG_WITH_CLASS_NAME; + +import android.annotation.NonNull; +import android.os.Build; +import android.os.Debug; +import android.os.FileUtils; +import android.os.SystemClock; +import android.os.SystemProperties; +import android.util.Slog; +import android.util.SparseBooleanArray; + +import com.android.internal.annotations.GuardedBy; +import com.android.internal.os.ProcessCpuTracker; +import com.android.internal.os.anr.AnrLatencyTracker; + +import java.io.File; +import java.io.FileOutputStream; +import java.io.IOException; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.nio.charset.StandardCharsets; +import java.text.SimpleDateFormat; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.Comparator; +import java.util.Date; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.Executor; +import java.util.concurrent.Future; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Supplier; + + +/** + * A helper for dumping stack traces. + */ +public class StackTracesDumpHelper { + static final String TAG = TAG_WITH_CLASS_NAME ? "StackTracesDumpHelper" : TAG_AM; + + @GuardedBy("StackTracesDumpHelper.class") + private static final SimpleDateFormat ANR_FILE_DATE_FORMAT = + 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"; + + 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. + + /** + * If a stack trace dump file is configured, dump process stack traces. + * @param firstPids of dalvik VM processes to dump stack traces for first + * @param lastPids of dalvik VM processes to dump stack traces for last + * @param nativePidsFuture optional future for a list of native pids to dump stack crawls + * @param logExceptionCreatingFile optional writer to which we log errors creating the file + * @param auxiliaryTaskExecutor executor to execute auxiliary tasks on + * @param latencyTracker the latency tracker instance of the current ANR. + */ + public static File dumpStackTraces(ArrayList<Integer> firstPids, + ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids, + Future<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile, + @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) { + return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture, + logExceptionCreatingFile, null, null, null, auxiliaryTaskExecutor, latencyTracker); + } + + /** + * @param subject the subject of the dumped traces + * @param criticalEventSection the critical event log, passed as a string + */ + 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) { + return dumpStackTraces(firstPids, processCpuTracker, lastPids, nativePidsFuture, + logExceptionCreatingFile, null, subject, criticalEventSection, + auxiliaryTaskExecutor, latencyTracker); + } + + /** + * @param firstPidEndOffset Optional, when it's set, it receives the start/end offset + * of the very first pid to be dumped. + */ + /* package */ static File dumpStackTraces(ArrayList<Integer> firstPids, + ProcessCpuTracker processCpuTracker, SparseBooleanArray lastPids, + Future<ArrayList<Integer>> nativePidsFuture, StringWriter logExceptionCreatingFile, + AtomicLong firstPidEndOffset, String subject, String criticalEventSection, + @NonNull Executor auxiliaryTaskExecutor, AnrLatencyTracker latencyTracker) { + try { + + if (latencyTracker != null) { + latencyTracker.dumpStackTracesStarted(); + } + + Slog.i(TAG, "dumpStackTraces pids=" + lastPids); + + // Measure CPU usage as soon as we're called in order to get a realistic sampling + // of the top users at the time of the request. + Supplier<ArrayList<Integer>> extraPidsSupplier = processCpuTracker != null + ? () -> getExtraPids(processCpuTracker, lastPids, latencyTracker) : null; + Future<ArrayList<Integer>> extraPidsFuture = null; + if (extraPidsSupplier != null) { + extraPidsFuture = + CompletableFuture.supplyAsync(extraPidsSupplier, auxiliaryTaskExecutor); + } + + final File tracesDir = new File(ANR_TRACE_DIR); + + // NOTE: We should consider creating the file in native code atomically once we've + // gotten rid of the old scheme of dumping and lot of the code that deals with paths + // can be removed. + File tracesFile; + try { + tracesFile = createAnrDumpFile(tracesDir); + } catch (IOException e) { + Slog.w(TAG, "Exception creating ANR dump file:", e); + if (logExceptionCreatingFile != null) { + logExceptionCreatingFile.append( + "----- Exception creating ANR dump file -----\n"); + e.printStackTrace(new PrintWriter(logExceptionCreatingFile)); + } + if (latencyTracker != null) { + latencyTracker.anrSkippedDumpStackTraces(); + } + return null; + } + + if (subject != null || criticalEventSection != null) { + appendtoANRFile(tracesFile.getAbsolutePath(), + (subject != null ? "Subject: " + subject + "\n\n" : "") + + (criticalEventSection != null ? criticalEventSection : "")); + } + + long firstPidEndPos = dumpStackTraces( + tracesFile.getAbsolutePath(), firstPids, nativePidsFuture, + extraPidsFuture, latencyTracker); + if (firstPidEndOffset != null) { + firstPidEndOffset.set(firstPidEndPos); + } + // Each set of ANR traces is written to a separate file and dumpstate will process + // all such files and add them to a captured bug report if they're recent enough. + maybePruneOldTraces(tracesDir); + + return tracesFile; + } finally { + if (latencyTracker != null) { + latencyTracker.dumpStackTracesEnded(); + } + } + + } + + /** + * @return The end offset of the trace of the very first PID + */ + public static long dumpStackTraces(String tracesFile, + ArrayList<Integer> firstPids, Future<ArrayList<Integer>> nativePidsFuture, + Future<ArrayList<Integer>> extraPidsFuture, AnrLatencyTracker latencyTracker) { + + Slog.i(TAG, "Dumping to " + tracesFile); + + // We don't need any sort of inotify based monitoring when we're dumping traces via + // tombstoned. Data is piped to an "intercept" FD installed in tombstoned so we're in full + // control of all writes to the file in question. + + // 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 + // dumped, remember the current file size. + long firstPidEnd = -1; + + // First 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++) { + 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(); + } + + remainingTime -= timeTaken; + if (remainingTime <= 0) { + Slog.e(TAG, "Aborting stack trace dump (current firstPid=" + pid + + "); deadline exceeded."); + return firstPidEnd; + } + + if (firstPid) { + firstPidEnd = new File(tracesFile).length(); + // Full latency dump + if (latencyTracker != null) { + appendtoANRFile(tracesFile, + latencyTracker.dumpAsCommaSeparatedArrayWithHeader()); + } + } + if (DEBUG_ANR) { + Slog.d(TAG, "Done with pid " + firstPids.get(i) + " in " + timeTaken + "ms"); + } + } + if (latencyTracker != null) { + latencyTracker.dumpingFirstPidsEnded(); + } + } + + // Next collect the stacks of the native pids + ArrayList<Integer> nativePids = collectPids(nativePidsFuture, "native pids"); + + Slog.i(TAG, "dumpStackTraces nativepids=" + nativePids); + + if (nativePids != null) { + if (latencyTracker != null) { + latencyTracker.dumpingNativePidsStarted(); + } + for (int pid : nativePids) { + Slog.i(TAG, "Collecting stacks for native pid " + pid); + final long nativeDumpTimeoutMs = Math.min(NATIVE_DUMP_TIMEOUT_MS, remainingTime); + + if (latencyTracker != null) { + latencyTracker.dumpingPidStarted(pid); + } + final long start = SystemClock.elapsedRealtime(); + Debug.dumpNativeBacktraceToFileTimeout( + pid, tracesFile, (int) (nativeDumpTimeoutMs / 1000)); + final long timeTaken = SystemClock.elapsedRealtime() - start; + if (latencyTracker != null) { + latencyTracker.dumpingPidEnded(); + } + remainingTime -= timeTaken; + if (remainingTime <= 0) { + Slog.e(TAG, "Aborting stack trace dump (current native pid=" + pid + + "); deadline exceeded."); + return firstPidEnd; + } + + if (DEBUG_ANR) { + Slog.d(TAG, "Done with native pid " + pid + " in " + timeTaken + "ms"); + } + } + if (latencyTracker != null) { + latencyTracker.dumpingNativePidsEnded(); + } + } + + // Lastly, dump stacks for all extra PIDs from the CPU tracker. + ArrayList<Integer> extraPids = collectPids(extraPidsFuture, "extra pids"); + + if (extraPidsFuture != null) { + try { + extraPids = extraPidsFuture.get(); + } catch (ExecutionException e) { + Slog.w(TAG, "Failed to collect extra pids", e.getCause()); + } catch (InterruptedException e) { + Slog.w(TAG, "Interrupted while collecting extra pids", e); + } + } + Slog.i(TAG, "dumpStackTraces extraPids=" + extraPids); + + if (extraPids != null) { + if (latencyTracker != null) { + latencyTracker.dumpingExtraPidsStarted(); + } + 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(); + } + remainingTime -= timeTaken; + if (remainingTime <= 0) { + Slog.e(TAG, "Aborting stack trace dump (current extra pid=" + pid + + "); deadline exceeded."); + return firstPidEnd; + } + + if (DEBUG_ANR) { + Slog.d(TAG, "Done with extra pid " + pid + " in " + timeTaken + "ms"); + } + } + if (latencyTracker != null) { + latencyTracker.dumpingExtraPidsEnded(); + } + } + // Append the dumping footer with the current uptime + appendtoANRFile(tracesFile, "----- dumping ended at " + SystemClock.uptimeMillis() + "\n"); + Slog.i(TAG, "Done dumping"); + + return firstPidEnd; + } + + 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); + + if (anrFile.createNewFile()) { + FileUtils.setPermissions(anrFile.getAbsolutePath(), 0600, -1, -1); // -rw------- + return anrFile; + } else { + throw new IOException("Unable to create ANR dump file: createNewFile failed"); + } + } + + private static ArrayList<Integer> getExtraPids(ProcessCpuTracker processCpuTracker, + SparseBooleanArray lastPids, AnrLatencyTracker latencyTracker) { + if (latencyTracker != null) { + latencyTracker.processCpuTrackerMethodsCalled(); + } + ArrayList<Integer> extraPids = new ArrayList<>(); + processCpuTracker.init(); + try { + Thread.sleep(200); + } catch (InterruptedException ignored) { + } + + processCpuTracker.update(); + + // We'll take the stack crawls of just the top apps using CPU. + final int workingStatsNumber = processCpuTracker.countWorkingStats(); + for (int i = 0; i < workingStatsNumber && extraPids.size() < 2; i++) { + ProcessCpuTracker.Stats stats = processCpuTracker.getWorkingStats(i); + if (lastPids.indexOfKey(stats.pid) >= 0) { + if (DEBUG_ANR) { + Slog.d(TAG, "Collecting stacks for extra pid " + stats.pid); + } + + extraPids.add(stats.pid); + } else { + Slog.i(TAG, + "Skipping next CPU consuming process, not a java proc: " + + stats.pid); + } + } + if (latencyTracker != null) { + latencyTracker.processCpuTrackerMethodsReturned(); + } + return extraPids; + } + + /** + * Prune all trace files that are more than a day old. + * + * NOTE: It might make sense to move this functionality to tombstoned eventually, along with a + * shift away from anr_XX and tombstone_XX to a more descriptive name. We do it here for now + * since it's the system_server that creates trace files for most ANRs. + */ + private static void maybePruneOldTraces(File tracesDir) { + final File[] files = tracesDir.listFiles(); + if (files == null) return; + + final int max = SystemProperties.getInt("tombstoned.max_anr_count", 64); + final long now = System.currentTimeMillis(); + try { + Arrays.sort(files, Comparator.comparingLong(File::lastModified).reversed()); + for (int i = 0; i < files.length; ++i) { + if (i > max || (now - files[i].lastModified()) > DAY_IN_MILLIS) { + if (!files[i].delete()) { + Slog.w(TAG, "Unable to prune stale trace file: " + files[i]); + } + } + } + } catch (IllegalArgumentException e) { + // The modification times changed while we were sorting. Bail... + // https://issuetracker.google.com/169836837 + Slog.w(TAG, "tombstone modification times changed while sorting; not pruning", e); + } + } + /** + * 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 + * to the java section of the trace, a further {@code NATIVE_DUMP_TIMEOUT_MS} might be spent + * attempting to obtain native traces in the case of a failure. Returns the total time spent + * capturing traces. + */ + private static long dumpJavaTracesTombstoned(int pid, String fileName, long timeoutMs) { + final long timeStart = SystemClock.elapsedRealtime(); + int headerSize = writeUptimeStartHeaderForPid(pid, fileName); + boolean javaSuccess = Debug.dumpJavaBacktraceToFileTimeout(pid, fileName, + (int) (timeoutMs / 1000)); + if (javaSuccess) { + // Check that something is in the file, actually. Try-catch should not be necessary, + // but better safe than sorry. + try { + long size = new File(fileName).length(); + if ((size - headerSize) < JAVA_DUMP_MINIMUM_SIZE) { + Slog.w(TAG, "Successfully created Java ANR file is empty!"); + javaSuccess = false; + } + } catch (Exception e) { + Slog.w(TAG, "Unable to get ANR file size", e); + javaSuccess = false; + } + } + if (!javaSuccess) { + Slog.w(TAG, "Dumping Java threads failed, initiating native stack dump."); + if (!Debug.dumpNativeBacktraceToFileTimeout(pid, fileName, + (NATIVE_DUMP_TIMEOUT_MS / 1000))) { + Slog.w(TAG, "Native stack dump failed!"); + } + } + + return SystemClock.elapsedRealtime() - timeStart; + } + + private static int appendtoANRFile(String fileName, String text) { + try (FileOutputStream fos = new FileOutputStream(fileName, true)) { + byte[] header = text.getBytes(StandardCharsets.UTF_8); + fos.write(header); + return header.length; + } catch (IOException e) { + Slog.w(TAG, "Exception writing to ANR dump file:", e); + return 0; + } + } + + /* + * Writes a header containing the process id and the current system uptime. + */ + private static int writeUptimeStartHeaderForPid(int pid, String fileName) { + return appendtoANRFile(fileName, "----- dumping pid: " + pid + " at " + + SystemClock.uptimeMillis() + "\n"); + } + + private static ArrayList<Integer> collectPids(Future<ArrayList<Integer>> pidsFuture, + String logName) { + + ArrayList<Integer> pids = null; + + if (pidsFuture == null) { + return pids; + } + try { + pids = pidsFuture.get(); + } catch (ExecutionException e) { + Slog.w(TAG, "Failed to collect " + logName, e.getCause()); + } catch (InterruptedException e) { + Slog.w(TAG, "Interrupted while collecting " + logName , e); + } + return pids; + } + +} diff --git a/services/core/java/com/android/server/wm/ActivityTaskManagerService.java b/services/core/java/com/android/server/wm/ActivityTaskManagerService.java index 555cd38806e6..7b9cc6fee602 100644 --- a/services/core/java/com/android/server/wm/ActivityTaskManagerService.java +++ b/services/core/java/com/android/server/wm/ActivityTaskManagerService.java @@ -75,9 +75,7 @@ import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_FOCUS; import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_IMMERSIVE; import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_LOCKTASK; import static com.android.internal.protolog.ProtoLogGroup.WM_DEBUG_TASKS; -import static com.android.server.am.ActivityManagerService.ANR_TRACE_DIR; import static com.android.server.am.ActivityManagerService.STOCK_PM_FLAGS; -import static com.android.server.am.ActivityManagerService.dumpStackTraces; import static com.android.server.am.ActivityManagerServiceDumpActivitiesProto.ROOT_WINDOW_CONTAINER; import static com.android.server.am.ActivityManagerServiceDumpProcessesProto.CONFIG_WILL_CHANGE; import static com.android.server.am.ActivityManagerServiceDumpProcessesProto.CONTROLLER; @@ -95,6 +93,8 @@ import static com.android.server.am.ActivityManagerServiceDumpProcessesProto.Scr import static com.android.server.am.ActivityManagerServiceDumpProcessesProto.ScreenCompatPackage.PACKAGE; import static com.android.server.am.EventLogTags.writeBootProgressEnableScreen; import static com.android.server.am.EventLogTags.writeConfigurationChanged; +import static com.android.server.am.StackTracesDumpHelper.ANR_TRACE_DIR; +import static com.android.server.am.StackTracesDumpHelper.dumpStackTraces; import static com.android.server.wm.ActivityInterceptorCallback.MAINLINE_FIRST_ORDERED_ID; import static com.android.server.wm.ActivityInterceptorCallback.MAINLINE_LAST_ORDERED_ID; import static com.android.server.wm.ActivityInterceptorCallback.SYSTEM_FIRST_ORDERED_ID; diff --git a/services/core/java/com/android/server/wm/AnrController.java b/services/core/java/com/android/server/wm/AnrController.java index bbe7a33669c8..90ec964e2f0f 100644 --- a/services/core/java/com/android/server/wm/AnrController.java +++ b/services/core/java/com/android/server/wm/AnrController.java @@ -34,7 +34,7 @@ import android.util.SparseArray; import android.view.InputApplicationHandle; import com.android.internal.os.TimeoutRecord; -import com.android.server.am.ActivityManagerService; +import com.android.server.am.StackTracesDumpHelper; import com.android.server.criticalevents.CriticalEventLog; import java.io.File; @@ -336,7 +336,7 @@ class AnrController { String criticalEvents = CriticalEventLog.getInstance().logLinesForSystemServerTraceFile(); - final File tracesFile = ActivityManagerService.dumpStackTraces(firstPids, + final File tracesFile = StackTracesDumpHelper.dumpStackTraces(firstPids, null /* processCpuTracker */, null /* lastPids */, CompletableFuture.completedFuture(nativePids), null /* logExceptionCreatingFile */, "Pre-dump", criticalEvents, |