Merge "Debugging code for #6169553: Make Phone launch faster" into ics-mr1
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) {