Merge "Blame services for slow operations" into oc-dev
diff --git a/services/core/java/com/android/server/SystemServiceManager.java b/services/core/java/com/android/server/SystemServiceManager.java
index cb13a3d..10b2609 100644
--- a/services/core/java/com/android/server/SystemServiceManager.java
+++ b/services/core/java/com/android/server/SystemServiceManager.java
@@ -33,6 +33,7 @@
*/
public class SystemServiceManager {
private static final String TAG = "SystemServiceManager";
+ private static final int SERVICE_CALL_WARN_TIME_MS = 50;
private final Context mContext;
private boolean mSafeMode;
@@ -117,12 +118,14 @@
// Register it.
mServices.add(service);
// Start it.
+ long time = System.currentTimeMillis();
try {
service.onStart();
} catch (RuntimeException ex) {
throw new RuntimeException("Failed to start service " + service.getClass().getName()
+ ": onStart threw an exception", ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onStart");
}
/**
@@ -143,6 +146,7 @@
final int serviceLen = mServices.size();
for (int i = 0; i < serviceLen; i++) {
final SystemService service = mServices.get(i);
+ long time = System.currentTimeMillis();
Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, service.getClass().getName());
try {
service.onBootPhase(mCurrentPhase);
@@ -152,6 +156,7 @@
+ ": onBootPhase threw an exception during phase "
+ mCurrentPhase, ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onBootPhase");
Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
}
} finally {
@@ -160,81 +165,96 @@
}
public void startUser(final int userHandle) {
+ Slog.i(TAG, "Calling onStartUser u" + userHandle);
final int serviceLen = mServices.size();
for (int i = 0; i < serviceLen; i++) {
final SystemService service = mServices.get(i);
Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onStartUser "
+ service.getClass().getName());
+ long time = System.currentTimeMillis();
try {
service.onStartUser(userHandle);
} catch (Exception ex) {
Slog.wtf(TAG, "Failure reporting start of user " + userHandle
+ " to service " + service.getClass().getName(), ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onStartUser ");
Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
}
}
public void unlockUser(final int userHandle) {
+ Slog.i(TAG, "Calling onUnlockUser u" + userHandle);
final int serviceLen = mServices.size();
for (int i = 0; i < serviceLen; i++) {
final SystemService service = mServices.get(i);
Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onUnlockUser "
+ service.getClass().getName());
+ long time = System.currentTimeMillis();
try {
service.onUnlockUser(userHandle);
} catch (Exception ex) {
Slog.wtf(TAG, "Failure reporting unlock of user " + userHandle
+ " to service " + service.getClass().getName(), ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onUnlockUser ");
Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
}
}
public void switchUser(final int userHandle) {
+ Slog.i(TAG, "Calling switchUser u" + userHandle);
final int serviceLen = mServices.size();
for (int i = 0; i < serviceLen; i++) {
final SystemService service = mServices.get(i);
Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onSwitchUser "
+ service.getClass().getName());
+ long time = System.currentTimeMillis();
try {
service.onSwitchUser(userHandle);
} catch (Exception ex) {
Slog.wtf(TAG, "Failure reporting switch of user " + userHandle
+ " to service " + service.getClass().getName(), ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onSwitchUser");
Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
}
}
public void stopUser(final int userHandle) {
+ Slog.i(TAG, "Calling onStopUser u" + userHandle);
final int serviceLen = mServices.size();
for (int i = 0; i < serviceLen; i++) {
final SystemService service = mServices.get(i);
Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onStopUser "
+ service.getClass().getName());
+ long time = System.currentTimeMillis();
try {
service.onStopUser(userHandle);
} catch (Exception ex) {
Slog.wtf(TAG, "Failure reporting stop of user " + userHandle
+ " to service " + service.getClass().getName(), ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onStopUser");
Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
}
}
public void cleanupUser(final int userHandle) {
+ Slog.i(TAG, "Calling onCleanupUser u" + userHandle);
final int serviceLen = mServices.size();
for (int i = 0; i < serviceLen; i++) {
final SystemService service = mServices.get(i);
Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, "onCleanupUser "
+ service.getClass().getName());
+ long time = System.currentTimeMillis();
try {
service.onCleanupUser(userHandle);
} catch (Exception ex) {
Slog.wtf(TAG, "Failure reporting cleanup of user " + userHandle
+ " to service " + service.getClass().getName(), ex);
}
+ warnIfTooLong(System.currentTimeMillis() - time, service, "onCleanupUser");
Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
}
}
@@ -263,6 +283,12 @@
mRuntimeRestarted = runtimeRestarted;
}
+ private void warnIfTooLong(long duration, SystemService service, String operation) {
+ if (duration > SERVICE_CALL_WARN_TIME_MS) {
+ Slog.w(TAG, "Service " + service.getClass().getName() + " took " + duration + " ms in "
+ + operation);
+ }
+ }
/**
* Outputs the state of this manager to the System log.