Debugging code for #6169553: Make Phone launch faster

The activity manager now has a tick when launching an app every
500ms, where it collects the current stack traces of the app if
it hasn't finished launching.  These traces are included as part
of dumpstate.

This is only done on non-user builds.

Change-Id: I7f09ea00aab821ac81795f48c9d68fcca65f89fe

4 files changed, 169 insertions, 12 deletions

diff --git a/cmds/dumpstate/dumpstate.c b/cmds/dumpstate/dumpstate.c
index 395c28b..60af415 100644
--- a/cmds/dumpstate/dumpstate.c
+++ b/cmds/dumpstate/dumpstate.c
@@ -108,6 +108,24 @@ static void dumpstate() {
         dump_file("VM TRACES AT LAST ANR", anr_traces_path);
     }
 
+    /* slow traces for slow operations */
+    if (anr_traces_path[0] != 0) {
+        int tail = strlen(anr_traces_path)-1;
+        while (tail > 0 && anr_traces_path[tail] != '/') {
+            tail--;
+        }
+        int i = 0;
+        while (1) {
+            sprintf(anr_traces_path+tail+1, "slow%02d.txt", i);
+            if (stat(anr_traces_path, &st)) {
+                // No traces file at this index, done with the files.
+                break;
+            }
+            dump_file("VM TRACES WHEN SLOW", anr_traces_path);
+            i++;
+        }
+    }
+
     // dump_file("EVENT LOG TAGS", "/etc/event-log-tags");
     run_command("EVENT LOG", 20, "logcat", "-b", "events", "-v", "threadtime", "-d", "*:v", NULL);
     run_command("RADIO LOG", 20, "logcat", "-b", "radio", "-v", "threadtime", "-d", "*:v", NULL);
diff --git a/services/java/com/android/server/am/ActivityManagerService.java b/services/java/com/android/server/am/ActivityManagerService.java
index 87eb65e..cffb391 100644
--- a/services/java/com/android/server/am/ActivityManagerService.java
+++ b/services/java/com/android/server/am/ActivityManagerService.java
@@ -105,6 +105,7 @@ import android.os.StrictMode;
 import android.os.SystemClock;
 import android.os.SystemProperties;
 import android.provider.Settings;
+import android.text.format.Time;
 import android.util.EventLog;
 import android.util.Pair;
 import android.util.Slog;
@@ -186,6 +187,8 @@ public final class ActivityManagerService extends ActivityManagerNative
     
     private static final String SYSTEM_DEBUGGABLE = "ro.debuggable";
 
+    static final boolean IS_USER_BUILD = "user".equals(Build.TYPE);
+
     // Maximum number of recent tasks that we can remember.
     static final int MAX_RECENT_TASKS = 20;
     
@@ -2904,6 +2907,12 @@ public final class ActivityManagerService extends ActivityManagerNative
             return null;
         }
 
+        dumpStackTraces(tracesPath, firstPids, processStats, lastPids);
+        return tracesFile;
+    }
+
+    private static void dumpStackTraces(String tracesPath, ArrayList<Integer> firstPids,
+            ProcessStats processStats, SparseArray<Boolean> lastPids) {
         // Use a FileObserver to detect when traces finish writing.
         // The order of traces is considered important to maintain for legibility.
         FileObserver observer = new FileObserver(tracesPath, FileObserver.CLOSE_WRITE) {
@@ -2914,16 +2923,18 @@ public final class ActivityManagerService extends ActivityManagerNative
             observer.startWatching();
 
             // First collect all of the stacks of the most important pids.
-            try {
-                int num = firstPids.size();
-                for (int i = 0; i < num; i++) {
-                    synchronized (observer) {
-                        Process.sendSignal(firstPids.get(i), Process.SIGNAL_QUIT);
-                        observer.wait(200);  // Wait for write-close, give up after 200msec
+            if (firstPids != null) {
+                try {
+                    int num = firstPids.size();
+                    for (int i = 0; i < num; i++) {
+                        synchronized (observer) {
+                            Process.sendSignal(firstPids.get(i), Process.SIGNAL_QUIT);
+                            observer.wait(200);  // Wait for write-close, give up after 200msec
+                        }
                     }
+                } catch (InterruptedException e) {
+                    Log.wtf(TAG, e);
                 }
-            } catch (InterruptedException e) {
-                Log.wtf(TAG, e);
             }
 
             // Next measure CPU usage.
@@ -2959,8 +2970,6 @@ public final class ActivityManagerService extends ActivityManagerNative
                 }
             }
 
-            return tracesFile;
-
         } finally {
             observer.stopWatching();
         }
@@ -2981,6 +2990,78 @@ public final class ActivityManagerService extends ActivityManagerNative
         }
     }
 
+    final void logAppTooSlow(ProcessRecord app, long startTime, String msg) {
+        if (IS_USER_BUILD) {
+            return;
+        }
+        String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);
+        if (tracesPath == null || tracesPath.length() == 0) {
+            return;
+        }
+
+        StrictMode.ThreadPolicy oldPolicy = StrictMode.allowThreadDiskReads();
+        StrictMode.allowThreadDiskWrites();
+        try {
+            final File tracesFile = new File(tracesPath);
+            final File tracesDir = tracesFile.getParentFile();
+            final File tracesTmp = new File(tracesDir, "__tmp__");
+            try {
+                if (!tracesDir.exists()) tracesFile.mkdirs();
+                FileUtils.setPermissions(tracesDir.getPath(), 0775, -1, -1);  // drwxrwxr-x
+
+                if (tracesFile.exists()) {
+                    tracesTmp.delete();
+                    tracesFile.renameTo(tracesTmp);
+                }
+                StringBuilder sb = new StringBuilder();
+                Time tobj = new Time();
+                tobj.set(System.currentTimeMillis());
+                sb.append(tobj.format("%Y-%m-%d %H:%M:%S"));
+                sb.append(": ");
+                TimeUtils.formatDuration(SystemClock.uptimeMillis()-startTime, sb);
+                sb.append(" since ");
+                sb.append(msg);
+                FileOutputStream fos = new FileOutputStream(tracesFile);
+                fos.write(sb.toString().getBytes());
+                if (app == null) {
+                    fos.write("\n*** No application process!".getBytes());
+                }
+                fos.close();
+                FileUtils.setPermissions(tracesFile.getPath(), 0666, -1, -1); // -rw-rw-rw-
+            } catch (IOException e) {
+                Slog.w(TAG, "Unable to prepare slow app traces file: " + tracesPath, e);
+                return;
+            }
+
+            if (app != null) {
+                ArrayList<Integer> firstPids = new ArrayList<Integer>();
+                firstPids.add(app.pid);
+                dumpStackTraces(tracesPath, firstPids, null, null);
+            }
+
+            File lastTracesFile = null;
+            File curTracesFile = null;
+            for (int i=9; i>=0; i--) {
+                String name = String.format("slow%02d.txt", i);
+                curTracesFile = new File(tracesDir, name);
+                if (curTracesFile.exists()) {
+                    if (lastTracesFile != null) {
+                        curTracesFile.renameTo(lastTracesFile);
+                    } else {
+                        curTracesFile.delete();
+                    }
+                }
+                lastTracesFile = curTracesFile;
+            }
+            tracesFile.renameTo(curTracesFile);
+            if (tracesTmp.exists()) {
+                tracesTmp.renameTo(tracesFile);
+            }
+        } finally {
+            StrictMode.setThreadPolicy(oldPolicy);
+        }
+    }
+
     final void appNotResponding(ProcessRecord app, ActivityRecord activity,
             ActivityRecord parent, final String annotation) {
         ArrayList<Integer> firstPids = new ArrayList<Integer>(5);
diff --git a/services/java/com/android/server/am/ActivityRecord.java b/services/java/com/android/server/am/ActivityRecord.java
index c819114..6ef36eb 100644
--- a/services/java/com/android/server/am/ActivityRecord.java
+++ b/services/java/com/android/server/am/ActivityRecord.java
@@ -82,6 +82,8 @@ final class ActivityRecord {
     long startTime;         // last time this activity was started
     long lastVisibleTime;   // last time this activity became visible
     long cpuTimeAtResume;   // the cpu time of host process at the time of resuming activity
+    long pauseTime;         // last time we started pausing the activity
+    long launchTickTime;    // base time for launch tick messages
     Configuration configuration; // configuration activity was last running in
     CompatibilityInfo compat;// last used compatibility mode
     ActivityRecord resultTo; // who started this entry, so will get our reply
@@ -572,6 +574,32 @@ final class ActivityRecord {
         }
     }
 
+    void startLaunchTickingLocked() {
+        if (ActivityManagerService.IS_USER_BUILD) {
+            return;
+        }
+        if (launchTickTime == 0) {
+            launchTickTime = SystemClock.uptimeMillis();
+            continueLaunchTickingLocked();
+        }
+    }
+
+    boolean continueLaunchTickingLocked() {
+        if (launchTickTime != 0) {
+            Message msg = stack.mHandler.obtainMessage(ActivityStack.LAUNCH_TICK_MSG);
+            msg.obj = this;
+            stack.mHandler.removeMessages(ActivityStack.LAUNCH_TICK_MSG);
+            stack.mHandler.sendMessageDelayed(msg, ActivityStack.LAUNCH_TICK);
+            return true;
+        }
+        return false;
+    }
+
+    void finishLaunchTickingLocked() {
+        launchTickTime = 0;
+        stack.mHandler.removeMessages(ActivityStack.LAUNCH_TICK_MSG);
+    }
+
     // IApplicationToken
 
     public boolean mayFreezeScreenLocked(ProcessRecord app) {
@@ -627,6 +655,7 @@ final class ActivityRecord {
                 stack.mInitialStartTime = 0;
             }
             startTime = 0;
+            finishLaunchTickingLocked();
         }
     }
 
diff --git a/services/java/com/android/server/am/ActivityStack.java b/services/java/com/android/server/am/ActivityStack.java
index a7bf7e1..351dbb8 100644
--- a/services/java/com/android/server/am/ActivityStack.java
+++ b/services/java/com/android/server/am/ActivityStack.java
@@ -95,7 +95,10 @@ final class ActivityStack {
     // How long we wait until giving up on the last activity telling us it
     // is idle.
     static final int IDLE_TIMEOUT = 10*1000;
-    
+
+    // Ticks during which we check progress while waiting for an app to launch.
+    static final int LAUNCH_TICK = 500;
+
     // How long we wait until giving up on the last activity to pause.  This
     // is short because it directly impacts the responsiveness of starting the
     // next activity.
@@ -278,10 +281,11 @@ final class ActivityStack {
     static final int PAUSE_TIMEOUT_MSG = 9;
     static final int IDLE_TIMEOUT_MSG = 10;
     static final int IDLE_NOW_MSG = 11;
+    static final int LAUNCH_TICK_MSG = 12;
     static final int LAUNCH_TIMEOUT_MSG = 16;
     static final int DESTROY_TIMEOUT_MSG = 17;
     static final int RESUME_TOP_ACTIVITY_MSG = 19;
-    
+
     final Handler mHandler = new Handler() {
         //public Handler() {
         //    if (localLOGV) Slog.v(TAG, "Handler started!");
@@ -303,6 +307,13 @@ final class ActivityStack {
                     // We don't at this point know if the activity is fullscreen,
                     // so we need to be conservative and assume it isn't.
                     Slog.w(TAG, "Activity pause timeout for " + r);
+                    synchronized (mService) {
+                        if (r.app != null) {
+                            mService.logAppTooSlow(r.app, r.pauseTime,
+                                    "pausing " + r);
+                        }
+                    }
+
                     activityPaused(r != null ? r.appToken : null, true);
                 } break;
                 case IDLE_TIMEOUT_MSG: {
@@ -319,6 +330,15 @@ final class ActivityStack {
                     Slog.w(TAG, "Activity idle timeout for " + r);
                     activityIdleInternal(r != null ? r.appToken : null, true, null);
                 } break;
+                case LAUNCH_TICK_MSG: {
+                    ActivityRecord r = (ActivityRecord)msg.obj;
+                    synchronized (mService) {
+                        if (r.continueLaunchTickingLocked()) {
+                            mService.logAppTooSlow(r.app, r.launchTickTime,
+                                    "launching " + r);
+                        }
+                    }
+                } break;
                 case DESTROY_TIMEOUT_MSG: {
                     ActivityRecord r = (ActivityRecord)msg.obj;
                     // We don't at this point know if the activity is fullscreen,
@@ -518,6 +538,9 @@ final class ActivityStack {
         r.startFreezingScreenLocked(app, 0);
         mService.mWindowManager.setAppVisibility(r.appToken, true);
 
+        // schedule launch ticks to collect information about slow apps.
+        r.startLaunchTickingLocked();
+
         // Have the window manager re-evaluate the orientation of
         // the screen based on the new activity order.  Note that
         // as a result of this, it can call back into the activity
@@ -900,6 +923,7 @@ final class ActivityStack {
             // responsiveness seen by the user.
             Message msg = mHandler.obtainMessage(PAUSE_TIMEOUT_MSG);
             msg.obj = prev;
+            prev.pauseTime = SystemClock.uptimeMillis();
             mHandler.sendMessageDelayed(msg, PAUSE_TIMEOUT);
             if (DEBUG_PAUSE) Slog.v(TAG, "Waiting for pause to complete...");
         } else {
@@ -1443,6 +1467,9 @@ final class ActivityStack {
             // This activity is now becoming visible.
             mService.mWindowManager.setAppVisibility(next.appToken, true);
 
+            // schedule launch ticks to collect information about slow apps.
+            next.startLaunchTickingLocked();
+
             ActivityRecord lastResumedActivity = mResumedActivity;
             ActivityState lastState = next.state;
 
@@ -3218,6 +3245,7 @@ final class ActivityStack {
             ActivityRecord r = ActivityRecord.forToken(token);
             if (r != null) {
                 mHandler.removeMessages(IDLE_TIMEOUT_MSG, r);
+                r.finishLaunchTickingLocked();
             }
 
             // Get the activity record.
@@ -3588,6 +3616,7 @@ final class ActivityStack {
         mHandler.removeMessages(PAUSE_TIMEOUT_MSG, r);
         mHandler.removeMessages(IDLE_TIMEOUT_MSG, r);
         mHandler.removeMessages(DESTROY_TIMEOUT_MSG, r);
+        r.finishLaunchTickingLocked();
     }
 
     final void removeActivityFromHistoryLocked(ActivityRecord r) {