android/perftests/utils/TraceMarkParser.java

/*
 * Copyright (C) 2019 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.perftests.utils;

import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.function.BiConsumer;
import java.util.function.Predicate;

/**
 * Utility to get the slice of tracing_mark_write S,F,B,E (Async: start, finish, Sync: begin, end).
 * Use {@link #visit(String)} to process the trace in text form. The filtered results can be
 * obtained by {@link #forAllSlices(BiConsumer)}.
 *
 * @see android.os.Trace
 */
public class TraceMarkParser {
    /** All slices by the name of {@link TraceMarkLine}. */
    private final Map<String, List<TraceMarkSlice>> mSlicesMap = new HashMap<>();
    /** The nested depth of each task-pid. */
    private final Map<String, Integer> mDepthMap = new HashMap<>();
    /** The start trace lines that haven't matched the corresponding end. */
    private final Map<String, TraceMarkLine> mPendingStarts = new HashMap<>();

    private final Predicate<TraceMarkLine> mTraceLineFilter;

    private static final long MICROS_PER_SECOND = 1000L * 1000L;

    public TraceMarkParser(Predicate<TraceMarkLine> traceLineFilter) {
        mTraceLineFilter = traceLineFilter;
    }

    /** Only accept the trace event with the given names. */
    public TraceMarkParser(String... traceNames) {
        this(line -> {
            for (String name : traceNames) {
                if (name.equals(line.name)) {
                    return true;
                }
            }
            return false;
        });
    }

    /** Computes {@link TraceMarkSlice} by the given trace line. */
    public void visit(String textTraceLine) {
        final TraceMarkLine line = TraceMarkLine.parse(textTraceLine);
        if (line == null) {
            return;
        }

        if (line.isAsync) {
            // Async-trace contains name in the start and finish event.
            if (mTraceLineFilter.test(line)) {
                if (line.isBegin) {
                    mPendingStarts.put(line.name, line);
                } else {
                    final TraceMarkLine start = mPendingStarts.remove(line.name);
                    if (start != null) {
                        addSlice(start, line);
                    }
                }
            }
            return;
        }

        int depth = 1;
        if (line.isBegin) {
            final Integer existingDepth = mDepthMap.putIfAbsent(line.taskPid, 1);
            if (existingDepth != null) {
                mDepthMap.put(line.taskPid, depth = existingDepth + 1);
            }
            // Sync-trace only contains name in the begin event.
            if (mTraceLineFilter.test(line)) {
                mPendingStarts.put(getSyncPendingStartKey(line, depth), line);
            }
        } else {
            final Integer existingDepth = mDepthMap.get(line.taskPid);
            if (existingDepth != null) {
                depth = existingDepth;
                mDepthMap.put(line.taskPid, existingDepth - 1);
            }
            final TraceMarkLine begin = mPendingStarts.remove(getSyncPendingStartKey(line, depth));
            if (begin != null) {
                addSlice(begin, line);
            }
        }
    }

    private static String getSyncPendingStartKey(TraceMarkLine line, int depth) {
        return line.taskPid + "@" + depth;
    }

    private void addSlice(TraceMarkLine begin, TraceMarkLine end) {
        mSlicesMap.computeIfAbsent(
                begin.name, k -> new ArrayList<>()).add(new TraceMarkSlice(begin, end));
    }

    public void forAllSlices(BiConsumer<String, List<TraceMarkSlice>> consumer) {
        for (Map.Entry<String, List<TraceMarkSlice>> entry : mSlicesMap.entrySet()) {
            consumer.accept(entry.getKey(), entry.getValue());
        }
    }

    public void reset() {
        mSlicesMap.clear();
        mDepthMap.clear();
        mPendingStarts.clear();
    }

    @Override
    public String toString() {
        final StringBuilder sb = new StringBuilder();
        forAllSlices((key, slices) -> {
            double totalMs = 0;
            for (TraceMarkSlice s : slices) {
                totalMs += s.getDurationInSeconds() * 1000;
            }
            sb.append(key).append(" count=").append(slices.size()).append(" avg=")
                    .append(totalMs / slices.size()).append("ms\n");
        });

        if (!mPendingStarts.isEmpty()) {
            sb.append("[Warning] Unresolved events:").append(mPendingStarts).append("\n");
        }
        return sb.toString();
    }

    static double microsecondToSeconds(long ms) {
        return (ms * 1.0d) / MICROS_PER_SECOND;
    }

    public static class TraceMarkSlice {
        public final TraceMarkLine begin;
        public final TraceMarkLine end;

        TraceMarkSlice(TraceMarkLine begin, TraceMarkLine end) {
            this.begin = begin;
            this.end = end;
        }

        public double getDurationInSeconds() {
            return microsecondToSeconds(end.timestamp - begin.timestamp);
        }

        public long getDurationInMicroseconds() {
            return end.timestamp - begin.timestamp;
        }
    }

    // taskPid                               timestamp                           name
    // # Async:
    // Binder:129_F-349  ( 1296) [003] ...1  12.2776: tracing_mark_write: S|1296|launching: a.test|0
    // android.anim-135  ( 1296) [005] ...1  12.3361: tracing_mark_write: F|1296|launching: a.test|0
    // # Normal:
    // Binder:129_6-315  ( 1296) [007] ...1  97.4576: tracing_mark_write: B|1296|relayoutWindow: xxx
    // ... there may have other nested begin/end
    // Binder:129_6-315  ( 1296) [007] ...1  97.4580: tracing_mark_write: E|1296
    public static class TraceMarkLine {
        static final String EVENT_KEYWORD = ": tracing_mark_write: ";
        static final char ASYNC_START = 'S';
        static final char ASYNC_FINISH = 'F';
        static final char SYNC_BEGIN = 'B';
        static final char SYNC_END = 'E';

        public final String taskPid;
        public final long timestamp; // in microseconds
        public final String name;
        public final boolean isAsync;
        public final boolean isBegin;

        TraceMarkLine(String rawLine, int typePos, int type) throws IllegalArgumentException {
            taskPid = rawLine.substring(0, rawLine.indexOf('(')).trim();
            final int timeEnd = rawLine.indexOf(':', taskPid.length());
            if (timeEnd < 0) {
                throw new IllegalArgumentException("Timestamp end not found");
            }
            final int timeBegin = rawLine.lastIndexOf(' ', timeEnd);
            if (timeBegin < 0) {
                throw new IllegalArgumentException("Timestamp start not found");
            }
            timestamp = parseMicroseconds(rawLine.substring(timeBegin, timeEnd));
            isAsync = type == ASYNC_START || type == ASYNC_FINISH;
            isBegin = type == ASYNC_START || type == SYNC_BEGIN;

            if (!isAsync && !isBegin) {
                name = "";
            } else {
                // Get the position of the second '|' from "S|1234|name".
                final int nameBegin = rawLine.indexOf('|', typePos + 2) + 1;
                if (nameBegin == 0) {
                    throw new IllegalArgumentException("Name begin not found");
                }
                if (isAsync) {
                    // Get the name from "S|1234|name|0".
                    name = rawLine.substring(nameBegin, rawLine.lastIndexOf('|'));
                } else {
                    name = rawLine.substring(nameBegin);
                }
            }
        }

        static TraceMarkLine parse(String rawLine) {
            final int eventPos = rawLine.indexOf(EVENT_KEYWORD);
            if (eventPos < 0) {
                return null;
            }
            final int typePos = eventPos + EVENT_KEYWORD.length();
            if (typePos >= rawLine.length()) {
                return null;
            }
            final int type = rawLine.charAt(typePos);
            if (type != ASYNC_START && type != ASYNC_FINISH
                    && type != SYNC_BEGIN  && type != SYNC_END) {
                return null;
            }

            try {
                return new TraceMarkLine(rawLine, typePos, type);
            } catch (IllegalArgumentException e) {
                e.printStackTrace();
            }
            return null;
        }

        /**
         * Parse the timestamp from atrace output, the format will be like:
         * 84962.920719  where the decimal part will be always exactly 6 digits.
         * ^^^^^ ^^^^^^
         * |     |
         * sec   microsec
         */
        static long parseMicroseconds(String line) {
            int end = line.length();
            long t = 0;
            for (int i = 0; i < end; i++) {
                char c = line.charAt(i);
                if (c >= '0' && c <= '9') {
                    t = t * 10 + (c - '0');
                }
            }
            return t;
        }

        @Override
        public String toString() {
            return "TraceMarkLine{pid=" + taskPid + " time="
                    + microsecondToSeconds(timestamp) + " name=" + name
                    + " async=" + isAsync + " begin=" + isBegin + "}";
        }
    }
}