1 /*
2  * Copyright (C) 2019 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.perftests.utils;
18 
19 import java.util.ArrayList;
20 import java.util.HashMap;
21 import java.util.List;
22 import java.util.Map;
23 import java.util.function.BiConsumer;
24 import java.util.function.Predicate;
25 
26 /**
27  * Utility to get the slice of tracing_mark_write S,F,B,E (Async: start, finish, Sync: begin, end).
28  * Use {@link #visit(String)} to process the trace in text form. The filtered results can be
29  * obtained by {@link #forAllSlices(BiConsumer)}.
30  *
31  * @see android.os.Trace
32  */
33 public class TraceMarkParser {
34     /** All slices by the name of {@link TraceMarkLine}. */
35     private final Map<String, List<TraceMarkSlice>> mSlicesMap = new HashMap<>();
36     /** The nested depth of each task-pid. */
37     private final Map<String, Integer> mDepthMap = new HashMap<>();
38     /** The start trace lines that haven't matched the corresponding end. */
39     private final Map<String, TraceMarkLine> mPendingStarts = new HashMap<>();
40 
41     private final Predicate<TraceMarkLine> mTraceLineFilter;
42 
43     private static final long MICROS_PER_SECOND = 1000L * 1000L;
44 
TraceMarkParser(Predicate<TraceMarkLine> traceLineFilter)45     public TraceMarkParser(Predicate<TraceMarkLine> traceLineFilter) {
46         mTraceLineFilter = traceLineFilter;
47     }
48 
49     /** Only accept the trace event with the given names. */
TraceMarkParser(String... traceNames)50     public TraceMarkParser(String... traceNames) {
51         this(line -> {
52             for (String name : traceNames) {
53                 if (name.equals(line.name)) {
54                     return true;
55                 }
56             }
57             return false;
58         });
59     }
60 
61     /** Computes {@link TraceMarkSlice} by the given trace line. */
visit(String textTraceLine)62     public void visit(String textTraceLine) {
63         final TraceMarkLine line = TraceMarkLine.parse(textTraceLine);
64         if (line == null) {
65             return;
66         }
67 
68         if (line.isAsync) {
69             // Async-trace contains name in the start and finish event.
70             if (mTraceLineFilter.test(line)) {
71                 if (line.isBegin) {
72                     mPendingStarts.put(line.name, line);
73                 } else {
74                     final TraceMarkLine start = mPendingStarts.remove(line.name);
75                     if (start != null) {
76                         addSlice(start, line);
77                     }
78                 }
79             }
80             return;
81         }
82 
83         int depth = 1;
84         if (line.isBegin) {
85             final Integer existingDepth = mDepthMap.putIfAbsent(line.taskPid, 1);
86             if (existingDepth != null) {
87                 mDepthMap.put(line.taskPid, depth = existingDepth + 1);
88             }
89             // Sync-trace only contains name in the begin event.
90             if (mTraceLineFilter.test(line)) {
91                 mPendingStarts.put(getSyncPendingStartKey(line, depth), line);
92             }
93         } else {
94             final Integer existingDepth = mDepthMap.get(line.taskPid);
95             if (existingDepth != null) {
96                 depth = existingDepth;
97                 mDepthMap.put(line.taskPid, existingDepth - 1);
98             }
99             final TraceMarkLine begin = mPendingStarts.remove(getSyncPendingStartKey(line, depth));
100             if (begin != null) {
101                 addSlice(begin, line);
102             }
103         }
104     }
105 
getSyncPendingStartKey(TraceMarkLine line, int depth)106     private static String getSyncPendingStartKey(TraceMarkLine line, int depth) {
107         return line.taskPid + "@" + depth;
108     }
109 
addSlice(TraceMarkLine begin, TraceMarkLine end)110     private void addSlice(TraceMarkLine begin, TraceMarkLine end) {
111         mSlicesMap.computeIfAbsent(
112                 begin.name, k -> new ArrayList<>()).add(new TraceMarkSlice(begin, end));
113     }
114 
forAllSlices(BiConsumer<String, List<TraceMarkSlice>> consumer)115     public void forAllSlices(BiConsumer<String, List<TraceMarkSlice>> consumer) {
116         for (Map.Entry<String, List<TraceMarkSlice>> entry : mSlicesMap.entrySet()) {
117             consumer.accept(entry.getKey(), entry.getValue());
118         }
119     }
120 
reset()121     public void reset() {
122         mSlicesMap.clear();
123         mDepthMap.clear();
124         mPendingStarts.clear();
125     }
126 
127     @Override
toString()128     public String toString() {
129         final StringBuilder sb = new StringBuilder();
130         forAllSlices((key, slices) -> {
131             double totalMs = 0;
132             for (TraceMarkSlice s : slices) {
133                 totalMs += s.getDurationInSeconds() * 1000;
134             }
135             sb.append(key).append(" count=").append(slices.size()).append(" avg=")
136                     .append(totalMs / slices.size()).append("ms\n");
137         });
138 
139         if (!mPendingStarts.isEmpty()) {
140             sb.append("[Warning] Unresolved events:").append(mPendingStarts).append("\n");
141         }
142         return sb.toString();
143     }
144 
microsecondToSeconds(long ms)145     static double microsecondToSeconds(long ms) {
146         return (ms * 1.0d) / MICROS_PER_SECOND;
147     }
148 
149     public static class TraceMarkSlice {
150         public final TraceMarkLine begin;
151         public final TraceMarkLine end;
152 
TraceMarkSlice(TraceMarkLine begin, TraceMarkLine end)153         TraceMarkSlice(TraceMarkLine begin, TraceMarkLine end) {
154             this.begin = begin;
155             this.end = end;
156         }
157 
getDurationInSeconds()158         public double getDurationInSeconds() {
159             return microsecondToSeconds(end.timestamp - begin.timestamp);
160         }
161 
getDurationInMicroseconds()162         public long getDurationInMicroseconds() {
163             return end.timestamp - begin.timestamp;
164         }
165     }
166 
167     // taskPid                               timestamp                           name
168     // # Async:
169     // Binder:129_F-349  ( 1296) [003] ...1  12.2776: tracing_mark_write: S|1296|launching: a.test|0
170     // android.anim-135  ( 1296) [005] ...1  12.3361: tracing_mark_write: F|1296|launching: a.test|0
171     // # Normal:
172     // Binder:129_6-315  ( 1296) [007] ...1  97.4576: tracing_mark_write: B|1296|relayoutWindow: xxx
173     // ... there may have other nested begin/end
174     // Binder:129_6-315  ( 1296) [007] ...1  97.4580: tracing_mark_write: E|1296
175     public static class TraceMarkLine {
176         static final String EVENT_KEYWORD = ": tracing_mark_write: ";
177         static final char ASYNC_START = 'S';
178         static final char ASYNC_FINISH = 'F';
179         static final char SYNC_BEGIN = 'B';
180         static final char SYNC_END = 'E';
181 
182         public final String taskPid;
183         public final long timestamp; // in microseconds
184         public final String name;
185         public final boolean isAsync;
186         public final boolean isBegin;
187 
TraceMarkLine(String rawLine, int typePos, int type)188         TraceMarkLine(String rawLine, int typePos, int type) throws IllegalArgumentException {
189             taskPid = rawLine.substring(0, rawLine.indexOf('(')).trim();
190             final int timeEnd = rawLine.indexOf(':', taskPid.length());
191             if (timeEnd < 0) {
192                 throw new IllegalArgumentException("Timestamp end not found");
193             }
194             final int timeBegin = rawLine.lastIndexOf(' ', timeEnd);
195             if (timeBegin < 0) {
196                 throw new IllegalArgumentException("Timestamp start not found");
197             }
198             timestamp = parseMicroseconds(rawLine.substring(timeBegin, timeEnd));
199             isAsync = type == ASYNC_START || type == ASYNC_FINISH;
200             isBegin = type == ASYNC_START || type == SYNC_BEGIN;
201 
202             if (!isAsync && !isBegin) {
203                 name = "";
204             } else {
205                 // Get the position of the second '|' from "S|1234|name".
206                 final int nameBegin = rawLine.indexOf('|', typePos + 2) + 1;
207                 if (nameBegin == 0) {
208                     throw new IllegalArgumentException("Name begin not found");
209                 }
210                 if (isAsync) {
211                     // Get the name from "S|1234|name|0".
212                     name = rawLine.substring(nameBegin, rawLine.lastIndexOf('|'));
213                 } else {
214                     name = rawLine.substring(nameBegin);
215                 }
216             }
217         }
218 
parse(String rawLine)219         static TraceMarkLine parse(String rawLine) {
220             final int eventPos = rawLine.indexOf(EVENT_KEYWORD);
221             if (eventPos < 0) {
222                 return null;
223             }
224             final int typePos = eventPos + EVENT_KEYWORD.length();
225             if (typePos >= rawLine.length()) {
226                 return null;
227             }
228             final int type = rawLine.charAt(typePos);
229             if (type != ASYNC_START && type != ASYNC_FINISH
230                     && type != SYNC_BEGIN  && type != SYNC_END) {
231                 return null;
232             }
233 
234             try {
235                 return new TraceMarkLine(rawLine, typePos, type);
236             } catch (IllegalArgumentException e) {
237                 e.printStackTrace();
238             }
239             return null;
240         }
241 
242         /**
243          * Parse the timestamp from atrace output, the format will be like:
244          * 84962.920719  where the decimal part will be always exactly 6 digits.
245          * ^^^^^ ^^^^^^
246          * |     |
247          * sec   microsec
248          */
parseMicroseconds(String line)249         static long parseMicroseconds(String line) {
250             int end = line.length();
251             long t = 0;
252             for (int i = 0; i < end; i++) {
253                 char c = line.charAt(i);
254                 if (c >= '0' && c <= '9') {
255                     t = t * 10 + (c - '0');
256                 }
257             }
258             return t;
259         }
260 
261         @Override
toString()262         public String toString() {
263             return "TraceMarkLine{pid=" + taskPid + " time="
264                     + microsecondToSeconds(timestamp) + " name=" + name
265                     + " async=" + isAsync + " begin=" + isBegin + "}";
266         }
267     }
268 }
269