Additional boot metrics
Extracted duration measurement functionality into BootTimingTraceLog.
It is now shared between system_server and zygote.
Log the following metrics to tron:
- boot_zygote_init - Time in milliseconds to boot into Zygote init stage.
- boot_android_init - Time in milliseconds to boot into Android init stage.
Test: manual - device boots, metrics are logged to system/event log
Bug: 32780225
Bug: 31115337
Change-Id: I600ac7fc83d35fa226ac92c37cc4b19192b25f59
diff --git a/core/java/android/util/BootTimingsTraceLog.java b/core/java/android/util/BootTimingsTraceLog.java
new file mode 100644
index 0000000..c782ad7f
--- /dev/null
+++ b/core/java/android/util/BootTimingsTraceLog.java
@@ -0,0 +1,65 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * 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
+ */
+
+package android.util;
+
+import android.os.Build;
+import android.os.SystemClock;
+import android.os.Trace;
+
+import java.util.ArrayDeque;
+import java.util.Deque;
+
+/**
+ * Helper class for reporting boot timing metrics.
+ * @hide
+ */
+public class BootTimingsTraceLog {
+ // Debug boot time for every step if it's non-user build.
+ private static final boolean DEBUG_BOOT_TIME = !"user".equals(Build.TYPE);
+ 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) {
+ mTag = tag;
+ mTraceTag = traceTag;
+ }
+
+ public void traceBegin(String name) {
+ Trace.traceBegin(mTraceTag, name);
+ if (DEBUG_BOOT_TIME) {
+ mStartTimes.push(Pair.create(name, SystemClock.elapsedRealtime()));
+ }
+ }
+
+ public void traceEnd() {
+ Trace.traceEnd(mTraceTag);
+ if (!DEBUG_BOOT_TIME) {
+ return;
+ }
+ // Pop the top element without throwing NoSuchElementException
+ Pair<String, Long> event = mStartTimes.pollFirst();
+ if (event == null) {
+ Slog.w(mTag, "traceEnd called more times than traceBegin");
+ return;
+ }
+ // 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");
+ }
+}
diff --git a/core/java/com/android/internal/os/WrapperInit.java b/core/java/com/android/internal/os/WrapperInit.java
index 594b6ab..c03bcdf 100644
--- a/core/java/com/android/internal/os/WrapperInit.java
+++ b/core/java/com/android/internal/os/WrapperInit.java
@@ -17,6 +17,8 @@
package com.android.internal.os;
import android.os.Process;
+import android.os.Trace;
+import android.util.BootTimingsTraceLog;
import android.util.Slog;
import dalvik.system.VMRuntime;
@@ -75,7 +77,8 @@
}
// Mimic system Zygote preloading.
- ZygoteInit.preload();
+ ZygoteInit.preload(new BootTimingsTraceLog("WrapperInitTiming",
+ Trace.TRACE_TAG_DALVIK));
// Launch the application.
String[] runtimeArgs = new String[args.length - 2];
diff --git a/core/java/com/android/internal/os/ZygoteInit.java b/core/java/com/android/internal/os/ZygoteInit.java
index e1118d8..cdd267e 100644
--- a/core/java/com/android/internal/os/ZygoteInit.java
+++ b/core/java/com/android/internal/os/ZygoteInit.java
@@ -36,11 +36,13 @@
import android.system.Os;
import android.system.OsConstants;
import android.text.Hyphenator;
+import android.util.BootTimingsTraceLog;
import android.util.EventLog;
import android.util.Log;
import android.webkit.WebViewFactory;
import android.widget.TextView;
+import com.android.internal.logging.MetricsLogger;
import com.android.internal.os.InstallerConnection.InstallerException;
import dalvik.system.DexFile;
@@ -106,20 +108,20 @@
private static final int ROOT_UID = 0;
private static final int ROOT_GID = 0;
- static void preload() {
+ static void preload(BootTimingsTraceLog bootTimingsTraceLog) {
Log.d(TAG, "begin preload");
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "BeginIcuCachePinning");
+ bootTimingsTraceLog.traceBegin("BeginIcuCachePinning");
beginIcuCachePinning();
- Trace.traceEnd(Trace.TRACE_TAG_DALVIK);
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "PreloadClasses");
+ bootTimingsTraceLog.traceEnd(); // BeginIcuCachePinning
+ bootTimingsTraceLog.traceBegin("PreloadClasses");
preloadClasses();
- Trace.traceEnd(Trace.TRACE_TAG_DALVIK);
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "PreloadResources");
+ bootTimingsTraceLog.traceEnd(); // PreloadClasses
+ bootTimingsTraceLog.traceBegin("PreloadResources");
preloadResources();
- Trace.traceEnd(Trace.TRACE_TAG_DALVIK);
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "PreloadOpenGL");
+ bootTimingsTraceLog.traceEnd(); // PreloadResources
+ bootTimingsTraceLog.traceBegin("PreloadOpenGL");
preloadOpenGL();
- Trace.traceEnd(Trace.TRACE_TAG_DALVIK);
+ bootTimingsTraceLog.traceEnd(); // PreloadOpenGL
preloadSharedLibraries();
preloadTextResources();
// Ask the WebViewFactory to do any initialization that must run in the zygote process,
@@ -639,7 +641,13 @@
}
try {
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "ZygoteInit");
+ // Report Zygote start time to tron
+ MetricsLogger.histogram(null, "boot_zygote_init", (int) SystemClock.uptimeMillis());
+
+ String bootTimeTag = Process.is64Bit() ? "Zygote64Timing" : "Zygote32Timing";
+ BootTimingsTraceLog bootTimingsTraceLog = new BootTimingsTraceLog(bootTimeTag,
+ Trace.TRACE_TAG_DALVIK);
+ bootTimingsTraceLog.traceBegin("ZygoteInit");
RuntimeInit.enableDdms();
// Start profiling the zygote initialization.
SamplingProfilerIntegration.start();
@@ -664,22 +672,23 @@
}
zygoteServer.registerServerSocket(socketName);
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "ZygotePreload");
+ bootTimingsTraceLog.traceBegin("ZygotePreload");
EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_START,
SystemClock.uptimeMillis());
- preload();
+ preload(bootTimingsTraceLog);
EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_END,
SystemClock.uptimeMillis());
- Trace.traceEnd(Trace.TRACE_TAG_DALVIK);
+ bootTimingsTraceLog.traceEnd(); // ZygotePreload
// Finish profiling the zygote initialization.
SamplingProfilerIntegration.writeZygoteSnapshot();
// Do an initial gc to clean up after startup
- Trace.traceBegin(Trace.TRACE_TAG_DALVIK, "PostZygoteInitGC");
+ bootTimingsTraceLog.traceBegin("PostZygoteInitGC");
gcAndFinalize();
- Trace.traceEnd(Trace.TRACE_TAG_DALVIK);
+ bootTimingsTraceLog.traceEnd(); // PostZygoteInitGC
+ bootTimingsTraceLog.traceEnd(); // ZygoteInit
// Disable tracing so that forked processes do not inherit stale tracing tags from
// Zygote.
Trace.setTracingEnabled(false);
diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java
index ba23f21..1fc4378 100644
--- a/services/java/com/android/server/SystemServer.java
+++ b/services/java/com/android/server/SystemServer.java
@@ -41,12 +41,10 @@
import android.os.SystemProperties;
import android.os.Trace;
import android.os.UserHandle;
-import android.os.UserManager;
import android.os.storage.IStorageManager;
-import android.provider.Settings;
+import android.util.BootTimingsTraceLog;
import android.util.DisplayMetrics;
import android.util.EventLog;
-import android.util.Pair;
import android.util.Slog;
import android.view.WindowManager;
@@ -55,7 +53,6 @@
import com.android.internal.logging.MetricsLogger;
import com.android.internal.os.BinderInternal;
import com.android.internal.os.SamplingProfilerIntegration;
-import com.android.internal.os.ZygoteInit;
import com.android.internal.policy.EmergencyAffordanceManager;
import com.android.internal.widget.ILockSettings;
import com.android.server.accessibility.AccessibilityManagerService;
@@ -102,8 +99,8 @@
import com.android.server.storage.DeviceStorageMonitorService;
import com.android.server.telecom.TelecomLoaderService;
import com.android.server.trust.TrustManagerService;
-import com.android.server.tv.TvRemoteService;
import com.android.server.tv.TvInputManagerService;
+import com.android.server.tv.TvRemoteService;
import com.android.server.twilight.TwilightService;
import com.android.server.usage.UsageStatsService;
import com.android.server.vr.VrManagerService;
@@ -112,8 +109,6 @@
import dalvik.system.VMRuntime;
-import java.util.ArrayDeque;
-import java.util.Deque;
import java.io.File;
import java.io.IOException;
import java.util.Locale;
@@ -125,11 +120,8 @@
public final class SystemServer {
private static final String TAG = "SystemServer";
- private static final boolean LOG_BOOT_TIME = true;
- // Debug boot time for every step if it's non-user build.
- private static final boolean DEBUG_BOOT_TIME = LOG_BOOT_TIME && !"user".equals(Build.TYPE);
- private static final String TAG_BOOT_TIME = "SystemServerTiming";
- private static final Deque<Pair<String, Long>> START_TIMES = new ArrayDeque<>();
+ private static final BootTimingsTraceLog BOOT_TIMINGS_TRACE_LOG
+ = new BootTimingsTraceLog("SystemServerTiming", Trace.TRACE_TAG_SYSTEM_SERVER);
private static final String ENCRYPTING_STATE = "trigger_restart_min_framework";
private static final String ENCRYPTED_STATE = "1";
@@ -279,6 +271,11 @@
int uptimeMillis = (int) SystemClock.uptimeMillis();
EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_SYSTEM_RUN, uptimeMillis);
MetricsLogger.histogram(null, "boot_system_server_init", uptimeMillis);
+ // Also report when first stage of init has started
+ long initStartNs = SystemProperties.getLong("init.start", -1);
+ if (initStartNs >= 0) {
+ MetricsLogger.histogram(null, "boot_android_init", (int)(initStartNs / 1000000));
+ }
// In case the runtime switched since last boot (such as when
// the old runtime was removed in an OTA), set the system
@@ -1643,24 +1640,11 @@
}
private static void traceBeginAndSlog(String name) {
- Trace.traceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, name);
Slog.i(TAG, name);
- if (DEBUG_BOOT_TIME) {
- START_TIMES.push(Pair.create(name, Long.valueOf(SystemClock.elapsedRealtime())));
- }
+ BOOT_TIMINGS_TRACE_LOG.traceBegin(name);
}
private static void traceEnd() {
- Trace.traceEnd(Trace.TRACE_TAG_SYSTEM_SERVER);
- if (!DEBUG_BOOT_TIME) {
- return;
- }
- Pair<String, Long> event = START_TIMES.pollFirst();
- if (event == null) {
- Slog.w(TAG, "traceEnd called more times than traceBeginAndSlog");
- return;
- }
- Slog.d(TAG_BOOT_TIME, event.first + " took to complete: "
- + (SystemClock.elapsedRealtime() - event.second) + "ms");
+ BOOT_TIMINGS_TRACE_LOG.traceEnd();
}
}