/* * 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.annotation.NonNull; import android.os.Build; import android.os.SystemClock; import android.os.Trace; import com.android.internal.annotations.VisibleForTesting; import java.util.ArrayList; import java.util.Collections; import java.util.List; /** * Helper class for reporting boot and shutdown timing metrics. * *

NOTE: This class is not thread-safe. Use a separate copy for other threads. * * @hide */ @android.ravenwood.annotation.RavenwoodKeepWholeClass 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; // Maximum number of nested calls that are stored private static final int MAX_NESTED_CALLS = 10; private final String[] mStartNames; private final long[] mStartTimes; private final String mTag; private final long mTraceTag; private final long mThreadId; private final int mMaxNestedCalls; private int mCurrentLevel = -1; public TimingsTraceLog(String tag, long traceTag) { this(tag, traceTag, DEBUG_BOOT_TIME ? MAX_NESTED_CALLS : -1); } @VisibleForTesting public TimingsTraceLog(String tag, long traceTag, int maxNestedCalls) { mTag = tag; mTraceTag = traceTag; mThreadId = Thread.currentThread().getId(); mMaxNestedCalls = maxNestedCalls; this.mStartNames = createAndGetStartNamesArray(); this.mStartTimes = createAndGetStartTimesArray(); } /** * Note: all fields will be copied except for {@code mStartNames} and {@code mStartTimes} * in order to save memory. The copied object is only expected to be used at levels deeper than * the value of {@code mCurrentLevel} when the object is copied. * * @param other object to be copied */ protected TimingsTraceLog(TimingsTraceLog other) { this.mTag = other.mTag; this.mTraceTag = other.mTraceTag; this.mThreadId = Thread.currentThread().getId(); this.mMaxNestedCalls = other.mMaxNestedCalls; this.mStartNames = createAndGetStartNamesArray(); this.mStartTimes = createAndGetStartTimesArray(); this.mCurrentLevel = other.mCurrentLevel; } private String[] createAndGetStartNamesArray() { return mMaxNestedCalls > 0 ? new String[mMaxNestedCalls] : null; } private long[] createAndGetStartTimesArray() { return mMaxNestedCalls > 0 ? new long[mMaxNestedCalls] : null; } /** * Begin tracing named section * @param name name to appear in trace */ public void traceBegin(String name) { assertSameThread(); Trace.traceBegin(mTraceTag, name); if (!DEBUG_BOOT_TIME) return; if (mCurrentLevel + 1 >= mMaxNestedCalls) { Slog.w(mTag, "not tracing duration of '" + name + "' because already reached " + mMaxNestedCalls + " levels"); return; } mCurrentLevel++; mStartNames[mCurrentLevel] = name; mStartTimes[mCurrentLevel] = SystemClock.elapsedRealtime(); } /** * End tracing previously {@link #traceBegin(String) started} section. * *

Also {@link #logDuration logs} the duration. */ public void traceEnd() { assertSameThread(); Trace.traceEnd(mTraceTag); if (!DEBUG_BOOT_TIME) return; if (mCurrentLevel < 0) { Slog.w(mTag, "traceEnd called more times than traceBegin"); return; } final String name = mStartNames[mCurrentLevel]; final long duration = SystemClock.elapsedRealtime() - mStartTimes[mCurrentLevel]; mCurrentLevel--; logDuration(name, duration); } private void assertSameThread() { final Thread currentThread = Thread.currentThread(); if (currentThread.getId() != mThreadId) { throw new IllegalStateException("Instance of TimingsTraceLog can only be called from " + "the thread it was created on (tid: " + mThreadId + "), but was from " + currentThread.getName() + " (tid: " + currentThread.getId() + ")"); } } /** * Logs a duration so it can be parsed by external tools for performance reporting. */ public void logDuration(String name, long timeMs) { Slog.v(mTag, name + " took to complete: " + timeMs + "ms"); } /** * Gets the names of the traces that {@link #traceBegin(String) have begun} but * {@link #traceEnd() have not finished} yet. * *

NOTE: this method is expensive and it should not be used in "production" - it * should only be used for debugging purposes during development (and/or guarded by * static {@code DEBUG} constants that are {@code false}). */ @NonNull public final List getUnfinishedTracesForDebug() { if (mStartTimes == null || mCurrentLevel < 0) return Collections.emptyList(); final ArrayList list = new ArrayList<>(mCurrentLevel + 1); for (int i = 0; i <= mCurrentLevel; i++) { list.add(mStartNames[i]); } return list; } }