diff options
-rw-r--r-- | config/compiled-classes-phone | 2 | ||||
-rw-r--r-- | config/preloaded-classes | 2 | ||||
-rw-r--r-- | core/java/android/util/TimingsTraceLog.java (renamed from core/java/android/util/BootTimingsTraceLog.java) | 31 | ||||
-rw-r--r-- | core/java/com/android/internal/os/WrapperInit.java | 4 | ||||
-rw-r--r-- | core/java/com/android/internal/os/ZygoteInit.java | 9 | ||||
-rw-r--r-- | packages/SystemUI/src/com/android/systemui/SystemUIApplication.java | 6 | ||||
-rw-r--r-- | services/art-profile | 2 | ||||
-rw-r--r-- | services/core/java/com/android/server/am/ActivityManagerService.java | 4 | ||||
-rw-r--r-- | services/core/java/com/android/server/pm/PackageManagerService.java | 4 | ||||
-rw-r--r-- | services/core/java/com/android/server/power/ShutdownThread.java | 34 | ||||
-rw-r--r-- | services/java/com/android/server/SystemServer.java | 13 |
11 files changed, 71 insertions, 40 deletions
diff --git a/config/compiled-classes-phone b/config/compiled-classes-phone index 548dc3896aa2..c8297286b784 100644 --- a/config/compiled-classes-phone +++ b/config/compiled-classes-phone @@ -4183,7 +4183,7 @@ android.util.Base64 android.util.Base64$Coder android.util.Base64$Decoder android.util.Base64$Encoder -android.util.BootTimingsTraceLog +android.util.TimingsTraceLog android.util.ByteStringUtils android.util.ContainerHelpers android.util.DebugUtils diff --git a/config/preloaded-classes b/config/preloaded-classes index 96122319c8cf..b6be0ee80877 100644 --- a/config/preloaded-classes +++ b/config/preloaded-classes @@ -2276,7 +2276,7 @@ android.util.Base64 android.util.Base64$Coder android.util.Base64$Decoder android.util.Base64$Encoder -android.util.BootTimingsTraceLog +android.util.TimingsTraceLog android.util.ContainerHelpers android.util.DisplayMetrics android.util.EventLog diff --git a/core/java/android/util/BootTimingsTraceLog.java b/core/java/android/util/TimingsTraceLog.java index 7a702a92d3b1..36e9f77bb831 100644 --- a/core/java/android/util/BootTimingsTraceLog.java +++ b/core/java/android/util/TimingsTraceLog.java @@ -11,7 +11,7 @@ * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and - * limitations under the License + * limitations under the License. */ package android.util; @@ -24,22 +24,26 @@ import java.util.ArrayDeque; import java.util.Deque; /** - * Helper class for reporting boot timing metrics. + * Helper class for reporting boot and shutdown timing metrics. * @hide */ -public class BootTimingsTraceLog { +public class TimingsTraceLog { // Debug boot time for every step if it's non-user build. private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER; - private final Deque<Pair<String, Long>> mStartTimes - = DEBUG_BOOT_TIME ? new ArrayDeque<>() : null; + private final Deque<Pair<String, Long>> mStartTimes = + DEBUG_BOOT_TIME ? new ArrayDeque<>() : null; private final String mTag; private long mTraceTag; - public BootTimingsTraceLog(String tag, long traceTag) { + public TimingsTraceLog(String tag, long traceTag) { mTag = tag; mTraceTag = traceTag; } + /** + * Begin tracing named section + * @param name name to appear in trace + */ public void traceBegin(String name) { Trace.traceBegin(mTraceTag, name); if (DEBUG_BOOT_TIME) { @@ -47,6 +51,10 @@ public class BootTimingsTraceLog { } } + /** + * End tracing previously {@link #traceBegin(String) started} section. + * Also {@link #logDuration logs} the duration. + */ public void traceEnd() { Trace.traceEnd(mTraceTag); if (!DEBUG_BOOT_TIME) { @@ -57,8 +65,13 @@ public class BootTimingsTraceLog { return; } Pair<String, Long> event = mStartTimes.pop(); - // Log the duration so it can be parsed by external tools for performance reporting - Slog.d(mTag, event.first + " took to complete: " - + (SystemClock.elapsedRealtime() - event.second) + "ms"); + logDuration(event.first, (SystemClock.elapsedRealtime() - event.second)); + } + + /** + * Log the duration so it can be parsed by external tools for performance reporting + */ + public void logDuration(String name, long timeMs) { + Slog.d(mTag, name + " took to complete: " + timeMs + "ms"); } } diff --git a/core/java/com/android/internal/os/WrapperInit.java b/core/java/com/android/internal/os/WrapperInit.java index 89328b21ccf5..49010802c784 100644 --- a/core/java/com/android/internal/os/WrapperInit.java +++ b/core/java/com/android/internal/os/WrapperInit.java @@ -23,7 +23,7 @@ import android.system.Os; import android.system.OsConstants; import android.system.StructCapUserData; import android.system.StructCapUserHeader; -import android.util.BootTimingsTraceLog; +import android.util.TimingsTraceLog; import android.util.Slog; import dalvik.system.VMRuntime; import java.io.DataOutputStream; @@ -80,7 +80,7 @@ public class WrapperInit { } // Mimic system Zygote preloading. - ZygoteInit.preload(new BootTimingsTraceLog("WrapperInitTiming", + ZygoteInit.preload(new TimingsTraceLog("WrapperInitTiming", Trace.TRACE_TAG_DALVIK)); // Launch the application. diff --git a/core/java/com/android/internal/os/ZygoteInit.java b/core/java/com/android/internal/os/ZygoteInit.java index 948f20311905..25e90ad13a25 100644 --- a/core/java/com/android/internal/os/ZygoteInit.java +++ b/core/java/com/android/internal/os/ZygoteInit.java @@ -43,7 +43,7 @@ import android.system.ErrnoException; import android.system.Os; import android.system.OsConstants; import android.text.Hyphenator; -import android.util.BootTimingsTraceLog; +import android.util.TimingsTraceLog; import android.util.EventLog; import android.util.Log; import android.util.Slog; @@ -54,7 +54,6 @@ import com.android.internal.logging.MetricsLogger; import com.android.internal.util.Preconditions; import dalvik.system.DexFile; -import dalvik.system.PathClassLoader; import dalvik.system.VMRuntime; import dalvik.system.ZygoteHooks; @@ -120,7 +119,7 @@ public class ZygoteInit { private static boolean sPreloadComplete; - static void preload(BootTimingsTraceLog bootTimingsTraceLog) { + static void preload(TimingsTraceLog bootTimingsTraceLog) { Log.d(TAG, "begin preload"); bootTimingsTraceLog.traceBegin("BeginIcuCachePinning"); beginIcuCachePinning(); @@ -153,7 +152,7 @@ public class ZygoteInit { Preconditions.checkState(!sPreloadComplete); Log.i(TAG, "Lazily preloading resources."); - preload(new BootTimingsTraceLog("ZygoteInitTiming_lazy", Trace.TRACE_TAG_DALVIK)); + preload(new TimingsTraceLog("ZygoteInitTiming_lazy", Trace.TRACE_TAG_DALVIK)); } private static void beginIcuCachePinning() { @@ -719,7 +718,7 @@ public class ZygoteInit { } String bootTimeTag = Process.is64Bit() ? "Zygote64Timing" : "Zygote32Timing"; - BootTimingsTraceLog bootTimingsTraceLog = new BootTimingsTraceLog(bootTimeTag, + TimingsTraceLog bootTimingsTraceLog = new TimingsTraceLog(bootTimeTag, Trace.TRACE_TAG_DALVIK); bootTimingsTraceLog.traceBegin("ZygoteInit"); RuntimeInit.enableDdms(); diff --git a/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java b/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java index d8da5ed71894..49a076f07a25 100644 --- a/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java +++ b/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java @@ -30,10 +30,9 @@ import android.os.SystemProperties; import android.os.Trace; import android.os.UserHandle; import android.util.ArraySet; -import android.util.BootTimingsTraceLog; +import android.util.TimingsTraceLog; import android.util.Log; -import com.android.systemui.fragments.FragmentService; import com.android.systemui.globalactions.GlobalActionsComponent; import com.android.systemui.keyboard.KeyboardUI; import com.android.systemui.keyguard.KeyguardViewMediator; @@ -52,7 +51,6 @@ import com.android.systemui.stackdivider.Divider; import com.android.systemui.statusbar.CommandQueue; import com.android.systemui.statusbar.phone.StatusBar; import com.android.systemui.statusbar.phone.StatusBarWindowManager; -import com.android.systemui.tuner.TunerService; import com.android.systemui.usb.StorageNotification; import com.android.systemui.util.NotificationChannels; import com.android.systemui.util.leak.GarbageMonitor; @@ -194,7 +192,7 @@ public class SystemUIApplication extends Application implements SysUiServiceProv Log.v(TAG, "Starting SystemUI services for user " + Process.myUserHandle().getIdentifier() + "."); - BootTimingsTraceLog log = new BootTimingsTraceLog("SystemUIBootTiming", + TimingsTraceLog log = new TimingsTraceLog("SystemUIBootTiming", Trace.TRACE_TAG_APP); log.traceBegin("StartServices"); final int N = services.length; diff --git a/services/art-profile b/services/art-profile index 140465a1c35e..28762a8932db 100644 --- a/services/art-profile +++ b/services/art-profile @@ -5445,7 +5445,7 @@ PLcom/android/server/am/ActivityManagerService;->stopAppSwitches()V PLcom/android/server/am/ActivityManagerService;->stopAssociationLocked(ILjava/lang/String;ILandroid/content/ComponentName;)V PLcom/android/server/am/ActivityManagerService;->stopService(Landroid/app/IApplicationThread;Landroid/content/Intent;Ljava/lang/String;I)I PLcom/android/server/am/ActivityManagerService;->stopServiceToken(Landroid/content/ComponentName;Landroid/os/IBinder;I)Z -PLcom/android/server/am/ActivityManagerService;->systemReady(Ljava/lang/Runnable;Landroid/util/BootTimingsTraceLog;)V +PLcom/android/server/am/ActivityManagerService;->systemReady(Ljava/lang/Runnable;Landroid/util/TimingsTraceLog;)V PLcom/android/server/am/ActivityManagerService;->trimApplications()V PLcom/android/server/am/ActivityManagerService;->uidOnBackgroundWhitelist(I)Z PLcom/android/server/am/ActivityManagerService;->unbindFinished(Landroid/os/IBinder;Landroid/content/Intent;Z)V diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index 161bf9adce30..1d860d601601 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -338,7 +338,7 @@ import android.text.style.SuggestionSpan; import android.util.ArrayMap; import android.util.ArraySet; import android.util.AtomicFile; -import android.util.BootTimingsTraceLog; +import android.util.TimingsTraceLog; import android.util.DebugUtils; import android.util.DisplayMetrics; import android.util.EventLog; @@ -14049,7 +14049,7 @@ public class ActivityManagerService extends IActivityManager.Stub } } - public void systemReady(final Runnable goingCallback, BootTimingsTraceLog traceLog) { + public void systemReady(final Runnable goingCallback, TimingsTraceLog traceLog) { traceLog.traceBegin("PhaseActivityManagerReady"); synchronized(this) { if (mSystemReady) { diff --git a/services/core/java/com/android/server/pm/PackageManagerService.java b/services/core/java/com/android/server/pm/PackageManagerService.java index 88d7cf893184..9dec7d0ec990 100644 --- a/services/core/java/com/android/server/pm/PackageManagerService.java +++ b/services/core/java/com/android/server/pm/PackageManagerService.java @@ -227,7 +227,7 @@ import android.text.format.DateUtils; import android.util.ArrayMap; import android.util.ArraySet; import android.util.Base64; -import android.util.BootTimingsTraceLog; +import android.util.TimingsTraceLog; import android.util.DisplayMetrics; import android.util.EventLog; import android.util.ExceptionUtils; @@ -2940,7 +2940,7 @@ public class PackageManagerService extends IPackageManager.Stub UserHandle.USER_SYSTEM, storageFlags, true /* migrateAppData */, true /* onlyCoreApps */); mPrepareAppDataFuture = SystemServerInitThreadPool.get().submit(() -> { - BootTimingsTraceLog traceLog = new BootTimingsTraceLog("SystemServerTimingAsync", + TimingsTraceLog traceLog = new TimingsTraceLog("SystemServerTimingAsync", Trace.TRACE_TAG_PACKAGE_MANAGER); traceLog.traceBegin("AppDataFixup"); try { diff --git a/services/core/java/com/android/server/power/ShutdownThread.java b/services/core/java/com/android/server/power/ShutdownThread.java index d0ca57a5073f..d1a5953ee763 100644 --- a/services/core/java/com/android/server/power/ShutdownThread.java +++ b/services/core/java/com/android/server/power/ShutdownThread.java @@ -45,16 +45,15 @@ import android.os.ServiceManager; import android.os.SystemClock; import android.os.SystemProperties; import android.os.SystemVibrator; +import android.os.Trace; import android.os.UserHandle; import android.os.UserManager; import android.os.Vibrator; import android.os.storage.IStorageManager; import android.os.storage.IStorageShutdownObserver; import android.util.Log; -import android.view.ViewGroup; +import android.util.TimingsTraceLog; import android.view.WindowManager; -import android.widget.ProgressBar; -import android.widget.TextView; import com.android.internal.telephony.ITelephony; import com.android.server.RescueParty; @@ -108,6 +107,9 @@ public final class ShutdownThread extends Thread { .setUsage(AudioAttributes.USAGE_ASSISTANCE_SONIFICATION) .build(); + private static final TimingsTraceLog SHUTDOWN_TIMINGS_LOG = new TimingsTraceLog( + "ShutdownTiming", Trace.TRACE_TAG_SYSTEM_SERVER); + private final Object mActionDoneSync = new Object(); private boolean mActionDone; private Context mContext; @@ -346,6 +348,7 @@ public final class ShutdownThread extends Thread { } private static void beginShutdownSequence(Context context) { + SHUTDOWN_TIMINGS_LOG.traceBegin("SystemServerShutdown"); synchronized (sIsStartedGuard) { if (sIsStarted) { Log.d(TAG, "Shutdown sequence already running, returning."); @@ -427,6 +430,7 @@ public final class ShutdownThread extends Thread { SystemProperties.set(REBOOT_SAFEMODE_PROPERTY, "1"); } + SHUTDOWN_TIMINGS_LOG.traceBegin("SendShutdownBroadcast"); Log.i(TAG, "Sending shutdown broadcast..."); // First send the high-level shut down broadcast. @@ -458,8 +462,10 @@ public final class ShutdownThread extends Thread { if (mRebootHasProgressBar) { sInstance.setRebootProgress(BROADCAST_STOP_PERCENT, null); } + SHUTDOWN_TIMINGS_LOG.traceEnd(); // SendShutdownBroadcast Log.i(TAG, "Shutting down activity manager..."); + SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownActivityManager"); final IActivityManager am = IActivityManager.Stub.asInterface(ServiceManager.checkService("activity")); @@ -472,8 +478,10 @@ public final class ShutdownThread extends Thread { if (mRebootHasProgressBar) { sInstance.setRebootProgress(ACTIVITY_MANAGER_STOP_PERCENT, null); } + SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownActivityManager Log.i(TAG, "Shutting down package manager..."); + SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownPackageManager"); final PackageManagerService pm = (PackageManagerService) ServiceManager.getService("package"); @@ -483,12 +491,15 @@ public final class ShutdownThread extends Thread { if (mRebootHasProgressBar) { sInstance.setRebootProgress(PACKAGE_MANAGER_STOP_PERCENT, null); } + SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownPackageManager // Shutdown radios. + SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownRadios"); shutdownRadios(MAX_RADIO_WAIT_TIME); if (mRebootHasProgressBar) { sInstance.setRebootProgress(RADIO_STOP_PERCENT, null); } + SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownRadios // Shutdown StorageManagerService to ensure media is in a safe state IStorageShutdownObserver observer = new IStorageShutdownObserver.Stub() { @@ -499,6 +510,7 @@ public final class ShutdownThread extends Thread { }; Log.i(TAG, "Shutting down StorageManagerService"); + SHUTDOWN_TIMINGS_LOG.traceBegin("ShutdownStorageManager"); // Set initial variables and time out time. mActionDone = false; @@ -518,7 +530,7 @@ public final class ShutdownThread extends Thread { while (!mActionDone) { long delay = endShutTime - SystemClock.elapsedRealtime(); if (delay <= 0) { - Log.w(TAG, "Shutdown wait timed out"); + Log.w(TAG, "StorageManager shutdown wait timed out"); break; } else if (mRebootHasProgressBar) { int status = (int)((MAX_SHUTDOWN_WAIT_TIME - delay) * 1.0 * @@ -533,6 +545,8 @@ public final class ShutdownThread extends Thread { } } } + SHUTDOWN_TIMINGS_LOG.traceEnd(); // ShutdownStorageManager + if (mRebootHasProgressBar) { sInstance.setRebootProgress(MOUNT_SERVICE_STOP_PERCENT, null); @@ -576,7 +590,7 @@ public final class ShutdownThread extends Thread { final IBluetoothManager bluetooth = IBluetoothManager.Stub.asInterface(ServiceManager.checkService( BluetoothAdapter.BLUETOOTH_MANAGER_SERVICE)); - + final long nfcShutdownStarted = SystemClock.elapsedRealtime(); try { nfcOff = nfc == null || nfc.getState() == NfcAdapter.STATE_OFF; @@ -589,6 +603,7 @@ public final class ShutdownThread extends Thread { nfcOff = true; } + final long btShutdownStarted = SystemClock.elapsedRealtime(); try { bluetoothReadyForShutdown = bluetooth == null || bluetooth.getState() == BluetoothAdapter.STATE_OFF; @@ -601,6 +616,7 @@ public final class ShutdownThread extends Thread { bluetoothReadyForShutdown = true; } + final long radioShutdownStarted = SystemClock.elapsedRealtime(); try { radioOff = phone == null || !phone.needMobileRadioShutdown(); if (!radioOff) { @@ -637,6 +653,8 @@ public final class ShutdownThread extends Thread { } if (bluetoothReadyForShutdown) { Log.i(TAG, "Bluetooth turned off."); + SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownBt", + SystemClock.elapsedRealtime() - btShutdownStarted); } } if (!radioOff) { @@ -648,6 +666,8 @@ public final class ShutdownThread extends Thread { } if (radioOff) { Log.i(TAG, "Radio turned off."); + SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownRadio", + SystemClock.elapsedRealtime() - radioShutdownStarted); } } if (!nfcOff) { @@ -659,6 +679,8 @@ public final class ShutdownThread extends Thread { } if (nfcOff) { Log.i(TAG, "NFC turned off."); + SHUTDOWN_TIMINGS_LOG.logDuration("ShutdownNfc", + SystemClock.elapsedRealtime() - nfcShutdownStarted); } } @@ -714,7 +736,7 @@ public final class ShutdownThread extends Thread { } catch (InterruptedException unused) { } } - + SHUTDOWN_TIMINGS_LOG.traceEnd(); // SystemServerShutdown // Shutdown power Log.i(TAG, "Performing low-level shutdown..."); PowerManagerService.lowLevelShutdown(reason); diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java index a1b9099f8bab..3c1262f089bc 100644 --- a/services/java/com/android/server/SystemServer.java +++ b/services/java/com/android/server/SystemServer.java @@ -45,7 +45,7 @@ import android.os.SystemProperties; import android.os.Trace; import android.os.UserHandle; import android.os.storage.IStorageManager; -import android.util.BootTimingsTraceLog; +import android.util.TimingsTraceLog; import android.util.DisplayMetrics; import android.util.EventLog; import android.util.Slog; @@ -121,7 +121,6 @@ import java.io.File; import java.io.IOException; import java.util.Locale; import java.util.Timer; -import java.util.TimerTask; import java.util.concurrent.CountDownLatch; import java.util.concurrent.Future; @@ -135,8 +134,8 @@ public final class SystemServer { // Tag for timing measurement of non-main asynchronous operations. private static final String SYSTEM_SERVER_TIMING_ASYNC_TAG = SYSTEM_SERVER_TIMING_TAG + "Async"; - private static final BootTimingsTraceLog BOOT_TIMINGS_TRACE_LOG - = new BootTimingsTraceLog(SYSTEM_SERVER_TIMING_TAG, Trace.TRACE_TAG_SYSTEM_SERVER); + private static final TimingsTraceLog BOOT_TIMINGS_TRACE_LOG + = new TimingsTraceLog(SYSTEM_SERVER_TIMING_TAG, Trace.TRACE_TAG_SYSTEM_SERVER); private static final String ENCRYPTING_STATE = "trigger_restart_min_framework"; private static final String ENCRYPTED_STATE = "1"; @@ -638,7 +637,7 @@ public final class SystemServer { // Start sensor service in a separate thread. Completion should be checked // before using it. mSensorServiceStart = SystemServerInitThreadPool.get().submit(() -> { - BootTimingsTraceLog traceLog = new BootTimingsTraceLog( + TimingsTraceLog traceLog = new TimingsTraceLog( SYSTEM_SERVER_TIMING_ASYNC_TAG, Trace.TRACE_TAG_SYSTEM_SERVER); traceLog.traceBegin(START_SENSOR_SERVICE); startSensorService(); @@ -736,7 +735,7 @@ public final class SystemServer { mZygotePreload = SystemServerInitThreadPool.get().submit(() -> { try { Slog.i(TAG, SECONDARY_ZYGOTE_PRELOAD); - BootTimingsTraceLog traceLog = new BootTimingsTraceLog( + TimingsTraceLog traceLog = new TimingsTraceLog( SYSTEM_SERVER_TIMING_ASYNC_TAG, Trace.TRACE_TAG_SYSTEM_SERVER); traceLog.traceBegin(SECONDARY_ZYGOTE_PRELOAD); if (!Process.zygoteProcess.preloadDefault(Build.SUPPORTED_32_BIT_ABIS[0])) { @@ -1686,7 +1685,7 @@ public final class SystemServer { if (!mOnlyCore) { webviewPrep = SystemServerInitThreadPool.get().submit(() -> { Slog.i(TAG, WEBVIEW_PREPARATION); - BootTimingsTraceLog traceLog = new BootTimingsTraceLog( + TimingsTraceLog traceLog = new TimingsTraceLog( SYSTEM_SERVER_TIMING_ASYNC_TAG, Trace.TRACE_TAG_SYSTEM_SERVER); traceLog.traceBegin(WEBVIEW_PREPARATION); ConcurrentUtils.waitForFutureNoInterrupt(mZygotePreload, "Zygote preload"); |