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
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 @@
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.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 @@
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 @@
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 @@
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 @@
}
}
- return tracesFile;
-
} finally {
observer.stopWatching();
}
@@ -2981,6 +2990,78 @@
}
}
+ 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 @@
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 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 @@
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 @@
// 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 @@
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 @@
// 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 @@
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 @@
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 @@
// 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 @@
// 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 @@
ActivityRecord r = ActivityRecord.forToken(token);
if (r != null) {
mHandler.removeMessages(IDLE_TIMEOUT_MSG, r);
+ r.finishLaunchTickingLocked();
}
// Get the activity record.
@@ -3588,6 +3616,7 @@
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) {