android/gameperformance/GraphicBufferMetrics.java

/*
 * 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();
        }
    }
}