Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 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 |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 14 | * limitations under the License. |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 15 | */ |
| 16 | |
| 17 | package android.util; |
| 18 | |
Felipe Leme | 137e781 | 2019-06-10 11:38:05 -0700 | [diff] [blame] | 19 | import android.annotation.NonNull; |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 20 | import android.os.Build; |
| 21 | import android.os.SystemClock; |
| 22 | import android.os.Trace; |
| 23 | |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 24 | import com.android.internal.annotations.VisibleForTesting; |
| 25 | |
Felipe Leme | 137e781 | 2019-06-10 11:38:05 -0700 | [diff] [blame] | 26 | import java.util.ArrayList; |
| 27 | import java.util.Collections; |
Felipe Leme | 137e781 | 2019-06-10 11:38:05 -0700 | [diff] [blame] | 28 | import java.util.List; |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 29 | |
| 30 | /** |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 31 | * Helper class for reporting boot and shutdown timing metrics. |
Felipe Leme | 137e781 | 2019-06-10 11:38:05 -0700 | [diff] [blame] | 32 | * |
| 33 | * <p><b>NOTE:</b> This class is not thread-safe. Use a separate copy for other threads. |
| 34 | * |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 35 | * @hide |
| 36 | */ |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 37 | public class TimingsTraceLog { |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 38 | // Debug boot time for every step if it's non-user build. |
Jeff Sharkey | 5ab0243 | 2017-06-27 11:01:36 -0600 | [diff] [blame] | 39 | private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER; |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 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 | |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 47 | private final String mTag; |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 48 | private final long mTraceTag; |
| 49 | private final long mThreadId; |
| 50 | private final int mMaxNestedCalls; |
| 51 | |
| 52 | private int mCurrentLevel = -1; |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 53 | |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 54 | public TimingsTraceLog(String tag, long traceTag) { |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 55 | this(tag, traceTag, DEBUG_BOOT_TIME ? MAX_NESTED_CALLS : -1); |
| 56 | } |
| 57 | |
| 58 | @VisibleForTesting |
| 59 | public TimingsTraceLog(String tag, long traceTag, int maxNestedCalls) { |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 60 | mTag = tag; |
| 61 | mTraceTag = traceTag; |
Fyodor Kupolov | 6042245 | 2017-08-28 17:15:44 -0700 | [diff] [blame] | 62 | mThreadId = Thread.currentThread().getId(); |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 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 | } |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 71 | } |
| 72 | |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 73 | /** |
| 74 | * Begin tracing named section |
| 75 | * @param name name to appear in trace |
| 76 | */ |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 77 | public void traceBegin(String name) { |
Fyodor Kupolov | 6042245 | 2017-08-28 17:15:44 -0700 | [diff] [blame] | 78 | assertSameThread(); |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 79 | Trace.traceBegin(mTraceTag, name); |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 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; |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 87 | } |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 88 | |
| 89 | mCurrentLevel++; |
| 90 | mStartNames[mCurrentLevel] = name; |
| 91 | mStartTimes[mCurrentLevel] = SystemClock.elapsedRealtime(); |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 92 | } |
| 93 | |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 94 | /** |
| 95 | * End tracing previously {@link #traceBegin(String) started} section. |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 96 | * |
| 97 | * <p>Also {@link #logDuration logs} the duration. |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 98 | */ |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 99 | public void traceEnd() { |
Fyodor Kupolov | 6042245 | 2017-08-28 17:15:44 -0700 | [diff] [blame] | 100 | assertSameThread(); |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 101 | Trace.traceEnd(mTraceTag); |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 102 | |
| 103 | if (!DEBUG_BOOT_TIME) return; |
| 104 | |
| 105 | if (mCurrentLevel < 0) { |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 106 | Slog.w(mTag, "traceEnd called more times than traceBegin"); |
| 107 | return; |
| 108 | } |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 109 | |
| 110 | final String name = mStartNames[mCurrentLevel]; |
| 111 | final long duration = SystemClock.elapsedRealtime() - mStartTimes[mCurrentLevel]; |
| 112 | mCurrentLevel--; |
| 113 | |
| 114 | logDuration(name, duration); |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 115 | } |
| 116 | |
Fyodor Kupolov | 6042245 | 2017-08-28 17:15:44 -0700 | [diff] [blame] | 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 | |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 126 | /** |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 127 | * Logs a duration so it can be parsed by external tools for performance reporting. |
Fyodor Kupolov | 6e3461b | 2017-08-10 17:00:43 -0700 | [diff] [blame] | 128 | */ |
| 129 | public void logDuration(String name, long timeMs) { |
| 130 | Slog.d(mTag, name + " took to complete: " + timeMs + "ms"); |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 131 | } |
Felipe Leme | 137e781 | 2019-06-10 11:38:05 -0700 | [diff] [blame] | 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 |
| 142 | public final List<String> getUnfinishedTracesForDebug() { |
Felipe Leme | b769296 | 2019-06-24 16:22:45 -0700 | [diff] [blame] | 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; |
Felipe Leme | 137e781 | 2019-06-10 11:38:05 -0700 | [diff] [blame] | 149 | } |
Fyodor Kupolov | 3235e0c | 2016-11-17 11:44:49 -0800 | [diff] [blame] | 150 | } |