Merge "ActivityManagerService: Add an overall stack dumping timeout." into oc-dev am: e7e6ce027c

am: 62c3698a79

Change-Id: I0671f29d8c96208342c812d46b9152e358bc9808

1 files changed, 69 insertions, 18 deletions

diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index 657096392348..1ac7f72876f2 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -5406,7 +5406,7 @@ public class ActivityManagerService extends IActivityManager.Stub
     public static class DumpStackFileObserver extends FileObserver {
         // Keep in sync with frameworks/native/cmds/dumpstate/utils.cpp
         private static final int TRACE_DUMP_TIMEOUT_MS = 10000; // 10 seconds
-        static final int TRACE_DUMP_TIMEOUT_SECONDS = TRACE_DUMP_TIMEOUT_MS / 1000;
+        static final int NATIVE_DUMP_TIMEOUT_MS = 2000; // 2 seconds;
 
         private final String mTracesPath;
         private boolean mClosed;
@@ -5422,21 +5422,41 @@ public class ActivityManagerService extends IActivityManager.Stub
             notify();
         }
 
-        public void dumpWithTimeout(int pid) {
+        public long dumpWithTimeout(int pid, long timeout) {
             sendSignal(pid, SIGNAL_QUIT);
+            final long start = SystemClock.elapsedRealtime();
+
+            final long waitTime = Math.min(timeout, TRACE_DUMP_TIMEOUT_MS);
             synchronized (this) {
                 try {
-                    wait(TRACE_DUMP_TIMEOUT_MS); // Wait for traces file to be closed.
+                    wait(waitTime); // Wait for traces file to be closed.
                 } catch (InterruptedException e) {
                     Slog.wtf(TAG, e);
                 }
             }
+
+            // This avoids a corner case of passing a negative time to the native
+            // trace in case we've already hit the overall timeout.
+            final long timeWaited = SystemClock.elapsedRealtime() - start;
+            if (timeWaited >= timeout) {
+                return timeWaited;
+            }
+
             if (!mClosed) {
                 Slog.w(TAG, "Didn't see close of " + mTracesPath + " for pid " + pid +
                        ". Attempting native stack collection.");
-                Debug.dumpNativeBacktraceToFileTimeout(pid, mTracesPath, TRACE_DUMP_TIMEOUT_SECONDS);
+
+                final long nativeDumpTimeoutMs = Math.min(
+                        NATIVE_DUMP_TIMEOUT_MS, timeout - timeWaited);
+
+                Debug.dumpNativeBacktraceToFileTimeout(pid, mTracesPath,
+                        (int) (nativeDumpTimeoutMs / 1000));
             }
+
+            final long end = SystemClock.elapsedRealtime();
             mClosed = false;
+
+            return (end - start);
         }
     }
 
@@ -5446,6 +5466,9 @@ public class ActivityManagerService extends IActivityManager.Stub
         // Use a FileObserver to detect when traces finish writing.
         // The order of traces is considered important to maintain for legibility.
         DumpStackFileObserver observer = new DumpStackFileObserver(tracesPath);
+
+        // We must complete all stack dumps within 20 seconds.
+        long remainingTime = 20 * 1000;
         try {
             observer.startWatching();
 
@@ -5455,10 +5478,18 @@ public class ActivityManagerService extends IActivityManager.Stub
                 for (int i = 0; i < num; i++) {
                     if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for pid "
                             + firstPids.get(i));
-                    final long sime = SystemClock.elapsedRealtime();
-                    observer.dumpWithTimeout(firstPids.get(i));
-                    if (DEBUG_ANR) Slog.d(TAG, "Done with pid " + firstPids.get(i)
-                            + " in " + (SystemClock.elapsedRealtime()-sime) + "ms");
+                    final long timeTaken = observer.dumpWithTimeout(firstPids.get(i), remainingTime);
+
+                    remainingTime -= timeTaken;
+                    if (remainingTime <= 0) {
+                        Slog.e(TAG, "Aborting stack trace dump (current firstPid=" + firstPids.get(i) +
+                            "); deadline exceeded.");
+                        return;
+                    }
+
+                    if (DEBUG_ANR) {
+                        Slog.d(TAG, "Done with pid " + firstPids.get(i) + " in " + timeTaken + "ms");
+                    }
                 }
             }
 
@@ -5466,12 +5497,24 @@ public class ActivityManagerService extends IActivityManager.Stub
             if (nativePids != null) {
                 for (int pid : nativePids) {
                     if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for native pid " + pid);
-                    final long sime = SystemClock.elapsedRealtime();
+                    final long nativeDumpTimeoutMs = Math.min(
+                            DumpStackFileObserver.NATIVE_DUMP_TIMEOUT_MS, remainingTime);
 
+                    final long start = SystemClock.elapsedRealtime();
                     Debug.dumpNativeBacktraceToFileTimeout(
-                            pid, tracesPath, DumpStackFileObserver.TRACE_DUMP_TIMEOUT_SECONDS);
-                    if (DEBUG_ANR) Slog.d(TAG, "Done with native pid " + pid
-                            + " in " + (SystemClock.elapsedRealtime()-sime) + "ms");
+                            pid, tracesPath, (int) (nativeDumpTimeoutMs / 1000));
+                    final long timeTaken = SystemClock.elapsedRealtime() - start;
+
+                    remainingTime -= timeTaken;
+                    if (remainingTime <= 0) {
+                        Slog.e(TAG, "Aborting stack trace dump (current native pid=" + pid +
+                            "); deadline exceeded.");
+                        return;
+                    }
+
+                    if (DEBUG_ANR) {
+                        Slog.d(TAG, "Done with native pid " + pid + " in " + timeTaken + "ms");
+                    }
                 }
             }
 
@@ -5495,12 +5538,20 @@ public class ActivityManagerService extends IActivityManager.Stub
                     ProcessCpuTracker.Stats stats = processCpuTracker.getWorkingStats(i);
                     if (lastPids.indexOfKey(stats.pid) >= 0) {
                         numProcs++;
-                        if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for extra pid "
-                                + stats.pid);
-                        final long stime = SystemClock.elapsedRealtime();
-                        observer.dumpWithTimeout(stats.pid);
-                        if (DEBUG_ANR) Slog.d(TAG, "Done with extra pid " + stats.pid
-                                + " in " + (SystemClock.elapsedRealtime()-stime) + "ms");
+
+                        if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for extra pid " + stats.pid);
+
+                        final long timeTaken = observer.dumpWithTimeout(stats.pid, remainingTime);
+                        remainingTime -= timeTaken;
+                        if (remainingTime <= 0) {
+                            Slog.e(TAG, "Aborting stack trace dump (current extra pid=" + stats.pid +
+                                "); deadline exceeded.");
+                            return;
+                        }
+
+                        if (DEBUG_ANR) {
+                            Slog.d(TAG, "Done with extra pid " + stats.pid + " in " + timeTaken + "ms");
+                        }
                     } else if (DEBUG_ANR) {
                         Slog.d(TAG, "Skipping next CPU consuming process, not a java proc: "
                                 + stats.pid);