1 /* 2 * Copyright (C) 2016 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package android.util; 18 19 import android.annotation.NonNull; 20 import android.os.Build; 21 import android.os.SystemClock; 22 import android.os.Trace; 23 24 import com.android.internal.annotations.VisibleForTesting; 25 26 import java.util.ArrayList; 27 import java.util.Collections; 28 import java.util.List; 29 30 /** 31 * Helper class for reporting boot and shutdown timing metrics. 32 * 33 * <p><b>NOTE:</b> This class is not thread-safe. Use a separate copy for other threads. 34 * 35 * @hide 36 */ 37 public class TimingsTraceLog { 38 // Debug boot time for every step if it's non-user build. 39 private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER; 40 41 // Maximum number of nested calls that are stored 42 private static final int MAX_NESTED_CALLS = 10; 43 44 private final String[] mStartNames; 45 private final long[] mStartTimes; 46 47 private final String mTag; 48 private final long mTraceTag; 49 private final long mThreadId; 50 private final int mMaxNestedCalls; 51 52 private int mCurrentLevel = -1; 53 TimingsTraceLog(String tag, long traceTag)54 public TimingsTraceLog(String tag, long traceTag) { 55 this(tag, traceTag, DEBUG_BOOT_TIME ? MAX_NESTED_CALLS : -1); 56 } 57 58 @VisibleForTesting TimingsTraceLog(String tag, long traceTag, int maxNestedCalls)59 public TimingsTraceLog(String tag, long traceTag, int maxNestedCalls) { 60 mTag = tag; 61 mTraceTag = traceTag; 62 mThreadId = Thread.currentThread().getId(); 63 mMaxNestedCalls = maxNestedCalls; 64 if (maxNestedCalls > 0) { 65 mStartNames = new String[maxNestedCalls]; 66 mStartTimes = new long[maxNestedCalls]; 67 } else { 68 mStartNames = null; 69 mStartTimes = null; 70 } 71 } 72 73 /** 74 * Begin tracing named section 75 * @param name name to appear in trace 76 */ traceBegin(String name)77 public void traceBegin(String name) { 78 assertSameThread(); 79 Trace.traceBegin(mTraceTag, name); 80 81 if (!DEBUG_BOOT_TIME) return; 82 83 if (mCurrentLevel + 1 >= mMaxNestedCalls) { 84 Slog.w(mTag, "not tracing duration of '" + name + "' because already reached " 85 + mMaxNestedCalls + " levels"); 86 return; 87 } 88 89 mCurrentLevel++; 90 mStartNames[mCurrentLevel] = name; 91 mStartTimes[mCurrentLevel] = SystemClock.elapsedRealtime(); 92 } 93 94 /** 95 * End tracing previously {@link #traceBegin(String) started} section. 96 * 97 * <p>Also {@link #logDuration logs} the duration. 98 */ traceEnd()99 public void traceEnd() { 100 assertSameThread(); 101 Trace.traceEnd(mTraceTag); 102 103 if (!DEBUG_BOOT_TIME) return; 104 105 if (mCurrentLevel < 0) { 106 Slog.w(mTag, "traceEnd called more times than traceBegin"); 107 return; 108 } 109 110 final String name = mStartNames[mCurrentLevel]; 111 final long duration = SystemClock.elapsedRealtime() - mStartTimes[mCurrentLevel]; 112 mCurrentLevel--; 113 114 logDuration(name, duration); 115 } 116 assertSameThread()117 private void assertSameThread() { 118 final Thread currentThread = Thread.currentThread(); 119 if (currentThread.getId() != mThreadId) { 120 throw new IllegalStateException("Instance of TimingsTraceLog can only be called from " 121 + "the thread it was created on (tid: " + mThreadId + "), but was from " 122 + currentThread.getName() + " (tid: " + currentThread.getId() + ")"); 123 } 124 } 125 126 /** 127 * Logs a duration so it can be parsed by external tools for performance reporting. 128 */ logDuration(String name, long timeMs)129 public void logDuration(String name, long timeMs) { 130 Slog.d(mTag, name + " took to complete: " + timeMs + "ms"); 131 } 132 133 /** 134 * Gets the names of the traces that {@link #traceBegin(String) have begun} but 135 * {@link #traceEnd() have not finished} yet. 136 * 137 * <p><b>NOTE:</b> this method is expensive and it should not be used in "production" - it 138 * should only be used for debugging purposes during development (and/or guarded by 139 * static {@code DEBUG} constants that are {@code false}). 140 */ 141 @NonNull getUnfinishedTracesForDebug()142 public final List<String> getUnfinishedTracesForDebug() { 143 if (mStartTimes == null || mCurrentLevel < 0) return Collections.emptyList(); 144 final ArrayList<String> list = new ArrayList<>(mCurrentLevel + 1); 145 for (int i = 0; i <= mCurrentLevel; i++) { 146 list.add(mStartNames[i]); 147 } 148 return list; 149 } 150 } 151