1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
|
/*
* 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.
*
* <p><b>NOTE:</b> This class is not thread-safe. Use a separate copy for other threads.
*
* @hide
*/
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.
*
* <p>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.
*
* <p><b>NOTE:</b> 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<String> getUnfinishedTracesForDebug() {
if (mStartTimes == null || mCurrentLevel < 0) return Collections.emptyList();
final ArrayList<String> list = new ArrayList<>(mCurrentLevel + 1);
for (int i = 0; i <= mCurrentLevel; i++) {
list.add(mStartNames[i]);
}
return list;
}
}
|
