Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 701a85f3 authored by Fyodor Kupolov's avatar Fyodor Kupolov
Browse files

Blame services for slow operations 

The system will now log a warning if a service takes 50+ ms to handle
a lifecycle callback.

Example:
SystemServiceManager: Service class com.android.server.appwidget.AppWidgetService took 404 ms in onUnlockUser

Test: device boots, times are logged
Bug: 37579992
Change-Id: Id1f339d02e1854f3a9acf85eb54b03f35ff68b89
parent 9e55fcbd

services/core/java/com/android/server/SystemServiceManager.java

+26 −0
Original line number Diff line number Diff line
@@ -33,6 +33,7 @@ import java.util.ArrayList; 
 */

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 @@ public class SystemServiceManager { 
        // 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 @@ public class SystemServiceManager { 
            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 @@ public class SystemServiceManager { 
                            + ": 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 class SystemServiceManager { 
    }



    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 @@ public class SystemServiceManager { 
        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.