diff options
| -rw-r--r-- | cmds/dumpstate/dumpstate.c | 18 | ||||
| -rw-r--r-- | services/java/com/android/server/am/ActivityManagerService.java | 101 | ||||
| -rw-r--r-- | services/java/com/android/server/am/ActivityRecord.java | 29 | ||||
| -rw-r--r-- | services/java/com/android/server/am/ActivityStack.java | 33 |
4 files changed, 169 insertions, 12 deletions
diff --git a/cmds/dumpstate/dumpstate.c b/cmds/dumpstate/dumpstate.c index 395c28bbd89a..60af4156fc88 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 87eb65ea768e..cffb3912780b 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 c819114f3866..6ef36eb9c9fd 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 a7bf7e125adb..351dbb8dfd4b 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) { |