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

Commit 6e3461b6 authored by Fyodor Kupolov's avatar Fyodor Kupolov
Browse files

Log timings for shutdown stages 

Renamed BootTimingsTraceLog to TimingsTraceLog. It is now used for
 boot and shutdown logging.

Added measurements for main stages of shutdown in the system server:
ShutdownTiming: SendShutdownBroadcast took to complete: 734ms
ShutdownTiming: ShutdownActivityManager took to complete: 203ms
ShutdownTiming: ShutdownPackageManager took to complete: 17ms
ShutdownTiming: ShutdownBt took to complete: 533ms
ShutdownTiming: ShutdownRadio took to complete: 534ms
ShutdownTiming: ShutdownNfc took to complete: 1536ms
ShutdownTiming: ShutdownRadios took to complete: 1538ms
ShutdownTiming: ShutdownStorageManager took to complete: 906ms
ShutdownTiming: SystemServerShutdown took to complete: 3918ms

Bug: 64569080
Test: shutdown/reboot and check logs
Change-Id: I636c045852cd1ed6be1c58af6608f70e95756389
parent a2991d04

config/compiled-classes-phone

+1 −1
Original line number Diff line number Diff line
@@ -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

config/preloaded-classes

+1 −1
Original line number Diff line number Diff line
@@ -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

core/java/android/util/BootTimingsTraceLog.java→core/java/android/util/TimingsTraceLog.java

+22 −9
Original line number Diff line number Diff line
@@ -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");

    }

}

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

+2 −2
Original line number Diff line number Diff line
@@ -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.

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

+4 −5
Original line number Diff line number Diff line
@@ -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();