am ce06c00: Merge "Debugging code for #6169553: Make Phone launch faster" into ics-mr1

* commit 'ce06c000b4133c63414c3244c3325e25315ab179':
  Debugging code for #6169553: Make Phone launch faster

Author: Dianne Hackborn

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

services/java/com/android/server/am/ActivityManagerService.java

@@ -105,6 +105,7 @@
 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 static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> first
             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 static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> first
             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 static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> first
                 }
             }
 
-            return tracesFile;
-
         } finally {
             observer.stopWatching();
         }
@@ -2981,6 +2990,78 @@ public void run() {
         }
     }
 
+    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);

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 @@ void clearThumbnail() {
         }
     }
 
+    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 @@ public void windowsDrawn() {
                 stack.mInitialStartTime = 0;
             }
             startTime = 0;
+            finishLaunchTickingLocked();
         }
     }
 

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 @@ enum ActivityState {
     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 @@ public void handleMessage(Message msg) {
                     // 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 @@ public void handleMessage(Message msg) {
                     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 boolean realStartActivityLocked(ActivityRecord r,
         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 @@ private final void startPausingLocked(boolean userLeaving, boolean uiSleeping) {
             // 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 boolean resumeTopActivityLocked(ActivityRecord prev) {
             // 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 ActivityRecord activityIdleInternal(IBinder token, boolean fromTimeout,
             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 void cleanUpActivityLocked(ActivityRecord r, boolean cleanServices,
         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) {