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

Merge "Debugging code for #6169553: Make Phone launch faster" into ics-mr1

Browse Source
This commit is contained in:
Dianne Hackborn
2012-03-16 11:53:53 -07:00
committed by Android (Google) Code Review
parent 1f60afc5cb 2a29b3ad13
commit ce06c000b4
4 changed files with 169 additions and 12 deletions
Download Patch File Download Diff File Expand all files Collapse all files

18
cmds/dumpstate/dumpstate.c
View File

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

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