tests/GamePerformance/src/android/gameperformance/GraphicBufferMetrics.java - platform/frameworks/base - Git at Google

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