Merge "resolved conflicts for merge of 354e034 to master"

Author: Dianne Hackborn

cmds/dumpstate/dumpstate.c

@@ -124,6 +124,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("NETWORK DEV INFO", "/proc/net/dev");
     dump_file("QTAGUID NETWORK INTERFACES INFO", "/proc/net/xt_qtaguid/iface_stat_all");
     dump_file("QTAGUID CTRL INFO", "/proc/net/xt_qtaguid/ctrl");

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

@@ -110,6 +110,7 @@
 import android.os.SystemProperties;
 import android.os.UserId;
 import android.provider.Settings;
+import android.text.format.Time;
 import android.util.EventLog;
 import android.util.Pair;
 import android.util.Slog;
@@ -197,6 +198,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;
 
@@ -2962,6 +2965,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) {
@@ -2972,16 +2981,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.
@@ -3017,13 +3028,83 @@ public static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> first
                 }
             }
 
-            return tracesFile;
-
         } finally {
             observer.stopWatching();
         }
     }
 
+    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

@@ -85,6 +85,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
@@ -576,6 +578,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) {
@@ -631,6 +659,7 @@ public void windowsDrawn() {
                 stack.mInitialStartTime = 0;
             }
             startTime = 0;
+            finishLaunchTickingLocked();
         }
     }
 

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

@@ -87,7 +87,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.
@@ -275,6 +278,7 @@ enum ActivityState {
     static final int LAUNCH_TIMEOUT_MSG = ActivityManagerService.FIRST_ACTIVITY_STACK_MSG + 4;
     static final int DESTROY_TIMEOUT_MSG = ActivityManagerService.FIRST_ACTIVITY_STACK_MSG + 5;
     static final int RESUME_TOP_ACTIVITY_MSG = ActivityManagerService.FIRST_ACTIVITY_STACK_MSG + 6;
+    static final int LAUNCH_TICK_MSG = ActivityManagerService.FIRST_ACTIVITY_STACK_MSG + 7;
 
     final Handler mHandler = new Handler() {
         //public Handler() {
@@ -297,6 +301,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: {
@@ -313,6 +324,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,
@@ -554,6 +574,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
@@ -936,6 +959,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 {
@@ -1480,6 +1504,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;
 
@@ -3257,6 +3284,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.
@@ -3627,6 +3655,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) {