drgreen/android_frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Debugging code for #6169553: Make Phone launch faster

Browse Source 
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
This commit is contained in:
Dianne Hackborn
2012-03-15 15:48:38 -07:00
parent 7f94977867
commit 2a29b3ad13
4 changed files with 169 additions and 12 deletions
Download Patch File Download Diff File Expand all files Collapse all files

101
services/java/com/android/server/am/ActivityManagerService.java
View File

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

29
services/java/com/android/server/am/ActivityRecord.java
View File

@ -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();
}
}

33
services/java/com/android/server/am/ActivityStack.java
View File

@ -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) {