/*
* Copyright (C) 2018 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.gameperformance;
import java.io.BufferedReader;
import java.io.FileReader;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collections;
import java.util.Comparator;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.StringTokenizer;
import java.util.TreeMap;
import java.util.TreeSet;
/**
* Utility class that performs analysis of atrace logs. This is implemented without Android
* dependencies and therefore can be used in stand-alone mode.
* Idea of this is to track atrace gfx event from graphics buffer producer/consumer.
* We analyze here from surfaceflinger
* queueBuffer - event when buffer was queued.
* acquireBuffer - event when buffer was requested for composition.
* releaseBuffer - even when buffer was released after composition.
* This also track events, issued locally
* localPostBuffer - event when buffer was posted from the local app.
*
* queueBuffer, acquireBuffer, releaseBuffer is accompanied with buffer name so we
* can track life-cycle of particular buffer.
* We don't have such information for localPostBuffer, however we can track next queueBuffer
* from surfaceflinger corresponds to previous localPostBuffer.
*
* Following results are calculated:
* post_time_[min/max/avr]_mcs - time for localPostBuffer duration.
* ready_time_[min/max/avr]_mcs - time from localPostBuffer to when buffer was acquired by
* surfaceflinger.
* latency_[min/max/avr]_mcs - time from localPostBuffer to when buffer was released by
* surfaceflinger.
* missed_frame_percents - percentage of missed frames (frames that do not have right sequence
* of events).
*
* Following is example of atrace logs from different platforms
* <...>-5237 (-----) [000] ...1 228.380392: tracing_mark_write: B|11|SurfaceView - android.gameperformance/android.gameperformance.GamePerformanceActivity#0: 2
* surfaceflinger-5855 ( 5855) [001] ...1 169.627364: tracing_mark_write: B|24|acquireBuffer
* HwBinder:617_2-652 ( 617) [002] d..1 360262.921756: sde_evtlog: 617|sde_encoder_virt_atomic_check:855|19|0|0|0|0|0|0|0|0|0|0|0|0|0|0
*/
public class GraphicBufferMetrics {
private final static String TAG = "GraphicBufferMetrics";
private final static String KEY_POST_TIME = "post_time";
private final static String KEY_READY_TIME = "ready_time";
private final static String KEY_LATENCY = "latency";
private final static String SUFFIX_MIN = "min";
private final static String SUFFIX_MAX = "max";
private final static String SUFFIX_MEDIAN = "median";
private final static String KEY_MISSED_FRAME_RATE = "missed_frame_percents";
private final static int EVENT_POST_BUFFER = 0;
private final static int EVENT_QUEUE_BUFFER = 1;
private final static int EVENT_ACQUIRE_BUFFER = 2;
private final static int EVENT_RELEASE_BUFFER = 3;
// atrace prints this line. Used as a marker to make sure that we can parse its output.
private final static String ATRACE_HEADER =
"# TASK-PID TGID CPU# |||| TIMESTAMP FUNCTION";
private final static String[] KNOWN_PHRASES = new String[] {
"capturing trace... done", "TRACE:"};
private final static List<String> KNWON_PHRASES_LIST = Arrays.asList(KNOWN_PHRASES);
// Type of the atrace event we can parse and analyze.
private final static String FUNCTION_TRACING_MARK_WRITE = "tracing_mark_write";
// Trace event we can ignore. It contains current timestamp information for the atrace output.
private final static String TRACE_EVENT_CLOCK_SYNC = "trace_event_clock_sync:";
// Threshold we consider test passes successfully. If we cannot collect enough amount of frames
// let fail the test. 50 is calculated 10 frames per second running for five seconds.
private final static int MINIMAL_SAMPLE_CNT_TO_PASS = 50;
/**
* Raw event in atrace. Stored hierarchically.
*/
private static class RawEvent {
// Parent of this event or null for the root holder.
public final RawEvent mParent;
// Time of the event in mcs.
public final long mTime;
// Duration of the event in mcs.
public long mDuration;
// Name/body of the event.
public final String mName;
// Children events.
public final List<RawEvent> mChildren;
public RawEvent(RawEvent parent, long time, String name) {
mParent = parent;
mTime = time;
mName = name;
mDuration = -1;
mChildren = new ArrayList<>();
}
/**
* Recursively finds child events.
* @param path specify path to events. For example a/b. That means to find child with name
* 'a' of the current event and in this child find child with name 'b'. Path
* can consist from only one segment and that means we analyze only children of
* the current event.
* @param collector to collect found events.
*/
public void findEvents(String path, List<RawEvent> collector) {
final int separator = path.indexOf('/');
final String current = separator > 0 ? path.substring(0, separator) : path;
final String nextPath = separator > 0 ? path.substring(separator + 1) : null;
for (RawEvent child : mChildren) {
if (child.mName.equals(current)) {
if (nextPath != null) {
child.findEvents(nextPath, collector);
} else {
collector.add(child);
}
}
}
}
public void dump(String prefix) {
System.err.print(prefix);
System.err.println(mTime + "[" + mDuration + "] " + mName);
for (RawEvent e : mChildren) {
e.dump(prefix + " ");
}
}
}
/**
* Describes graphic buffer event. local post, queued, acquired, released.
*/
private static class BufferEvent {
public final int mType;
public final long mTime;
public final long mDuration;
public final String mBufferId;
public BufferEvent(int type, long time, long duration, String bufferId) {
mType = type;
mTime = time;
mDuration = duration;
mBufferId = bufferId;
}
@Override
public String toString() {
return "Type: " + mType + ". Time: " + mTime +
"[" + mDuration + "]. Buffer: " + mBufferId + ".";
}
}
/**
* Returns true if given char is digit.
*/
private static boolean isDigitChar(char c) {
return (c >= '0') && (c <= '9');
}
/**
* Returns true if given char is digit or '.'.
*/
private static boolean isDoubleDigitChar(char c) {
return (c == '.') || isDigitChar(c);
}
/**
* Convert timestamp string that represents double value in seconds to long time that represents
* timestamp in microseconds.
*/
private static long getTimeStamp(String timeStampStr) {
return (long)(1000000.0 * Double.parseDouble(timeStampStr));
}
/**
* Reads atrace log and build event model. Result is a map, where key specifies event for the
* particular thread. Value is the synthetic root RawEvent that holds all events for the
* thread. Events are stored hierarchically.
*/
private static Map<Integer, RawEvent> buildEventModel(String fileName) throws IOException {
Map<Integer, RawEvent> result = new HashMap<>();
BufferedReader bufferedReader = null;
String line = "";
boolean headerDetected = false;
try {
bufferedReader = new BufferedReader(new FileReader(fileName));
while ((line = bufferedReader.readLine()) != null) {
// Make sure we find comment that describes output format we can with.
headerDetected |= line.equals(ATRACE_HEADER);
// Skip comments.
if (line.startsWith("#")) {
continue;
}
// Skip known service output
if (KNWON_PHRASES_LIST.contains(line)) {
continue;
}
if (!headerDetected) {
// We don't know the format of this line.
throw new IllegalStateException("Header was not detected");
}
// TASK-PID in header exists at position 12. PID position 17 should contains first
// digit of thread id after the '-'.
if (!isDigitChar(line.charAt(17)) || line.charAt(16) != '-') {
throw new IllegalStateException("Failed to parse thread id: " + line);
}
int rightIndex = line.indexOf(' ', 17);
final String threadIdStr = line.substring(17, rightIndex);
final int threadId = Integer.parseInt(threadIdStr);
// TIMESTAMP in header exists at position 45
// This position should point in the middle of timestamp which is ended by ':'.
int leftIndex = 45;
while (isDoubleDigitChar(line.charAt(leftIndex))) {
--leftIndex;
}
rightIndex = line.indexOf(':', 45);
final String timeStampString = line.substring(leftIndex + 1, rightIndex);
final long timeStampMcs = getTimeStamp(timeStampString);
// Find function name, pointed by FUNCTION. Long timestamp can shift if position
// so use end of timestamp to find the function which is ended by ':'.
leftIndex = rightIndex + 1;
while (Character.isWhitespace(line.charAt(leftIndex))) {
++leftIndex;
}
rightIndex = line.indexOf(':', leftIndex);
final String function = line.substring(leftIndex, rightIndex);
if (!function.equals(FUNCTION_TRACING_MARK_WRITE)) {
continue;
}
// Rest of the line is event body.
leftIndex = rightIndex + 1;
while (Character.isWhitespace(line.charAt(leftIndex))) {
++leftIndex;
}
final String event = line.substring(leftIndex);
if (event.startsWith(TRACE_EVENT_CLOCK_SYNC)) {
continue;
}
// Parse event, for example:
// B|615|SurfaceView - android.gameperformance.GamePerformanceActivity#0: 1
// E|615
// C|11253|operation id|2
StringTokenizer eventTokenizer = new StringTokenizer(event, "|");
final String eventType = eventTokenizer.nextToken();
// Attach root on demand.
if (!result.containsKey(threadId)) {
result.put(threadId, new RawEvent(null /* parent */,
timeStampMcs,
"#ROOT_" + threadId));
}
switch (eventType) {
case "B": {
// Log entry starts.
eventTokenizer.nextToken(); // PID
String eventText = eventTokenizer.nextToken();
while (eventTokenizer.hasMoreTokens()) {
eventText += " ";
eventText += eventTokenizer.nextToken();
}
RawEvent parent = result.get(threadId);
RawEvent current = new RawEvent(parent, timeStampMcs, eventText);
parent.mChildren.add(current);
result.put(threadId, current);
}
break;
case "E": {
// Log entry ends.
RawEvent current = result.get(threadId);
current.mDuration = timeStampMcs - current.mTime;
if (current.mParent == null) {
// Detect a tail of the previous call. Remove last child element if it
// exists once it does not belong to the root.
if (!current.mChildren.isEmpty()) {
current.mChildren.remove(current.mChildren.size() -1);
}
} else {
result.put(threadId, current.mParent);
}
}
break;
case "C":
// Counter, ignore
break;
default:
throw new IllegalStateException(
"Unrecognized trace: " + line + " # " + eventType + " # " + event);
}
}
// Detect incomplete events and detach from the root.
Set<Integer> threadIds = new TreeSet<>();
threadIds.addAll(result.keySet());
for (int threadId : threadIds) {
RawEvent root = result.get(threadId);
if (root.mParent == null) {
// Last trace was closed.
continue;
}
// Find the root.
while (root.mParent != null) {
root = root.mParent;
}
// Discard latest incomplete element.
root.mChildren.remove(root.mChildren.size() - 1);
result.put(threadId, root);
}
} catch (Exception e) {
throw new IOException("Failed to process " + line, e);
} finally {
Utils.closeQuietly(bufferedReader);
}
return result;
}
/**
* Processes provided atrace log and calculates graphics buffer metrics.
* @param fileName name of atrace log file.
* @param testTag tag to separate results for the different passes.
*/
public static Map<String, Double> processGraphicBufferResult(
String fileName, String testTag) throws IOException {
final Map<Integer, RawEvent> model = buildEventModel(fileName);
List<RawEvent> collectorPostBuffer = new ArrayList<>();
List<RawEvent> collectorQueueBuffer = new ArrayList<>();
List<RawEvent> collectorReleaseBuffer = new ArrayList<>();
List<RawEvent> collectorAcquireBuffer = new ArrayList<>();
// Collect required events.
for (RawEvent root : model.values()) {
// Surface view
root.findEvents("localPostBuffer", collectorPostBuffer);
// OpengGL view
root.findEvents("eglSwapBuffersWithDamageKHR", collectorPostBuffer);
root.findEvents("queueBuffer", collectorQueueBuffer);
root.findEvents("onMessageReceived/handleMessageInvalidate/latchBuffer/" +
"updateTexImage/acquireBuffer",
collectorAcquireBuffer);
// PI stack
root.findEvents(
"onMessageReceived/handleMessageRefresh/postComposition/releaseBuffer",
collectorReleaseBuffer);
// NYC stack
root.findEvents(
"onMessageReceived/handleMessageRefresh/releaseBuffer",
collectorReleaseBuffer);
}
// Convert raw event to buffer events.
List<BufferEvent> bufferEvents = new ArrayList<>();
for (RawEvent event : collectorPostBuffer) {
bufferEvents.add(
new BufferEvent(EVENT_POST_BUFFER, event.mTime, event.mDuration, null));
}
toBufferEvents(EVENT_QUEUE_BUFFER, collectorQueueBuffer, bufferEvents);
toBufferEvents(EVENT_ACQUIRE_BUFFER, collectorAcquireBuffer, bufferEvents);
toBufferEvents(EVENT_RELEASE_BUFFER, collectorReleaseBuffer, bufferEvents);
// Sort events based on time. These events are originally taken from different threads so
// order is not always preserved.
Collections.sort(bufferEvents, new Comparator<BufferEvent>() {
@Override
public int compare(BufferEvent o1, BufferEvent o2) {
if (o1.mTime < o2.mTime) {
return -1;
} if (o1.mTime > o2.mTime) {
return +1;
} else {
return 0;
}
}
});
// Collect samples.
List<Long> postTimes = new ArrayList<>();
List<Long> readyTimes = new ArrayList<>();
List<Long> latencyTimes = new ArrayList<>();
long missedCnt = 0;
for (int i = 0; i < bufferEvents.size(); ++i) {
if (bufferEvents.get(i).mType != EVENT_POST_BUFFER) {
continue;
}
final int queueIndex = findNextOfType(bufferEvents, i + 1, EVENT_QUEUE_BUFFER);
if (queueIndex < 0) {
break;
}
final int acquireIndex = findNextOfBufferId(bufferEvents, queueIndex + 1,
bufferEvents.get(queueIndex).mBufferId);
if (acquireIndex < 0) {
break;
}
if (bufferEvents.get(acquireIndex).mType != EVENT_ACQUIRE_BUFFER) {
// Was not actually presented.
++missedCnt;
continue;
}
final int releaseIndex = findNextOfBufferId(bufferEvents, acquireIndex + 1,
bufferEvents.get(queueIndex).mBufferId);
if (releaseIndex < 0) {
break;
}
if (bufferEvents.get(releaseIndex).mType != EVENT_RELEASE_BUFFER) {
// Was not actually presented.
++missedCnt;
continue;
}
postTimes.add(bufferEvents.get(i).mDuration);
readyTimes.add(
bufferEvents.get(acquireIndex).mTime - bufferEvents.get(i).mTime);
latencyTimes.add(
bufferEvents.get(releaseIndex).mTime - bufferEvents.get(i).mTime);
}
if (postTimes.size() < MINIMAL_SAMPLE_CNT_TO_PASS) {
throw new IllegalStateException("Too few sample cnt: " + postTimes.size() +". " +
MINIMAL_SAMPLE_CNT_TO_PASS + " is required.");
}
Map<String, Double> status = new TreeMap<>();
addResults(status, testTag, KEY_POST_TIME, postTimes);
addResults(status, testTag, KEY_READY_TIME, readyTimes);
addResults(status, testTag, KEY_LATENCY, latencyTimes);
status.put(testTag + "_" + KEY_MISSED_FRAME_RATE,
100.0 * missedCnt / (missedCnt + postTimes.size()));
return status;
}
private static void addResults(
Map<String, Double> status, String tag, String key, List<Long> times) {
Collections.sort(times);
long min = times.get(0);
long max = times.get(0);
for (long time : times) {
min = Math.min(min, time);
max = Math.max(max, time);
}
status.put(tag + "_" + key + "_" + SUFFIX_MIN, (double)min);
status.put(tag + "_" + key + "_" + SUFFIX_MAX, (double)max);
status.put(tag + "_" + key + "_" + SUFFIX_MEDIAN, (double)times.get(times.size() / 2));
}
// Helper to convert surface flinger events to buffer events.
private static void toBufferEvents(
int type, List<RawEvent> rawEvents, List<BufferEvent> bufferEvents) {
for (RawEvent event : rawEvents) {
if (event.mChildren.isEmpty()) {
throw new IllegalStateException("Buffer name is expected");
}
final String bufferName = event.mChildren.get(0).mName;
if (bufferName.startsWith("SurfaceView - android.gameperformance")) {
bufferEvents.add(
new BufferEvent(type, event.mTime, event.mDuration, bufferName));
}
}
}
private static int findNextOfType(List<BufferEvent> events, int startIndex, int type) {
for (int i = startIndex; i < events.size(); ++i) {
if (events.get(i).mType == type) {
return i;
}
}
return -1;
}
private static int findNextOfBufferId(
List<BufferEvent> events, int startIndex, String bufferId) {
for (int i = startIndex; i < events.size(); ++i) {
if (bufferId.equals(events.get(i).mBufferId)) {
return i;
}
}
return -1;
}
public static void main(String[] args) {
if (args.length != 1) {
System.err.println("Usage: " + TAG + " atrace.log");
return;
}
try {
System.out.println("Results:");
for (Map.Entry<?, ?> entry :
processGraphicBufferResult(args[0], "default").entrySet()) {
System.out.println(" " + entry.getKey() + " = " + entry.getValue());
}
} catch (IOException e) {
e.printStackTrace();
}
}
}