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

Commit 3235e0c2 authored by Fyodor Kupolov's avatar Fyodor Kupolov
Browse files

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
parent 7317467c

core/java/android/util/BootTimingsTraceLog.java

0 → 100644
+65 −0
Original line number Diff line number Diff line 
/*

 * 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");

    }

}

core/java/com/android/internal/os/WrapperInit.java

+4 −1
Original line number Diff line number Diff line
@@ -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 @@ public class WrapperInit { 
            }



            // 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];

core/java/com/android/internal/os/ZygoteInit.java

+24 −15
Original line number Diff line number Diff line
@@ -36,11 +36,13 @@ import android.system.ErrnoException; 
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 @@ public class ZygoteInit { 
    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 @@ public class ZygoteInit { 
        }



        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 @@ public class ZygoteInit { 
            }



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

services/java/com/android/server/SystemServer.java

+11 −27
Original line number Diff line number Diff line
@@ -41,12 +41,10 @@ import android.os.SystemClock; 
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.app.NightDisplayController; 
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.statusbar.StatusBarManagerService; 
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 com.android.server.wm.WindowManagerService; 


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 @@ import static android.view.Display.DEFAULT_DISPLAY; 
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 @@ public final class SystemServer { 
            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 @@ public final class SystemServer { 
    }



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

    }

}