path: root/traceview/src/com/android/traceview/DmTraceReader.java

/*
 * Copyright (C) 2006 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 com.android.traceview;

import java.io.BufferedReader;
import java.io.File;
import java.io.FileInputStream;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.io.InputStreamReader;
import java.nio.BufferUnderflowException;
import java.nio.ByteOrder;
import java.nio.MappedByteBuffer;
import java.nio.channels.FileChannel;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collection;
import java.util.Comparator;
import java.util.HashMap;
import java.util.regex.Matcher;
import java.util.regex.Pattern;

public class DmTraceReader extends TraceReader {
    private static final int TRACE_MAGIC = 0x574f4c53;

    private static final int METHOD_TRACE_ENTER = 0x00; // method entry
    private static final int METHOD_TRACE_EXIT = 0x01; // method exit
    private static final int METHOD_TRACE_UNROLL = 0x02; // method exited by exception unrolling

    // When in dual clock mode, we report that a context switch has occurred
    // when skew between the real time and thread cpu clocks is more than this
    // many microseconds.
    private static final long MIN_CONTEXT_SWITCH_TIME_USEC = 100;

    private enum ClockSource {
        THREAD_CPU, WALL, DUAL,
    };

    private int mVersionNumber;
    private boolean mRegression;
    private ProfileProvider mProfileProvider;
    private String mTraceFileName;
    private MethodData mTopLevel;
    private ArrayList<Call> mCallList;
    private HashMap<String, String> mPropertiesMap;
    private HashMap<Integer, MethodData> mMethodMap;
    private HashMap<Integer, ThreadData> mThreadMap;
    private ThreadData[] mSortedThreads;
    private MethodData[] mSortedMethods;
    private long mTotalCpuTime;
    private long mTotalRealTime;
    private MethodData mContextSwitch;
    private int mRecordSize;
    private ClockSource mClockSource;

    // A regex for matching the thread "id name" lines in the .key file
    private static final Pattern mIdNamePattern = Pattern.compile("(\\d+)\t(.*)");  //$NON-NLS-1$

    public DmTraceReader(String traceFileName, boolean regression) throws IOException {
        mTraceFileName = traceFileName;
        mRegression = regression;
        mPropertiesMap = new HashMap<String, String>();
        mMethodMap = new HashMap<Integer, MethodData>();
        mThreadMap = new HashMap<Integer, ThreadData>();
        mCallList = new ArrayList<Call>();

        // Create a single top-level MethodData object to hold the profile data
        // for time spent in the unknown caller.
        mTopLevel = new MethodData(0, "(toplevel)");
        mContextSwitch = new MethodData(-1, "(context switch)");
        mMethodMap.put(0, mTopLevel);
        mMethodMap.put(-1, mContextSwitch);
        generateTrees();
    }

    void generateTrees() throws IOException {
        long offset = parseKeys();
        parseData(offset);
        analyzeData();
    }

    @Override
    public ProfileProvider getProfileProvider() {
        if (mProfileProvider == null)
            mProfileProvider = new ProfileProvider(this);
        return mProfileProvider;
    }

    private MappedByteBuffer mapFile(String filename, long offset) throws IOException {
        MappedByteBuffer buffer = null;
        FileInputStream dataFile = new FileInputStream(filename);
        File file = new File(filename);
        FileChannel fc = dataFile.getChannel();
        buffer = fc.map(FileChannel.MapMode.READ_ONLY, offset, file.length() - offset);
        buffer.order(ByteOrder.LITTLE_ENDIAN);

        return buffer;
    }

    private void readDataFileHeader(MappedByteBuffer buffer) {
        int magic = buffer.getInt();
        if (magic != TRACE_MAGIC) {
            System.err.printf(
                    "Error: magic number mismatch; got 0x%x, expected 0x%x\n",
                    magic, TRACE_MAGIC);
            throw new RuntimeException();
        }

        // read version
        int version = buffer.getShort();
        if (version != mVersionNumber) {
            System.err.printf(
                    "Error: version number mismatch; got %d in data header but %d in options\n",
                    version, mVersionNumber);
            throw new RuntimeException();
        }
        if (version < 1 || version > 3) {
            System.err.printf(
                    "Error: unsupported trace version number %d.  "
                    + "Please use a newer version of TraceView to read this file.", version);
            throw new RuntimeException();
        }

        // read offset
        int offsetToData = buffer.getShort() - 16;

        // read startWhen
        buffer.getLong();

        // read record size
        if (version == 1) {
            mRecordSize = 9;
        } else if (version == 2) {
            mRecordSize = 10;
        } else {
            mRecordSize = buffer.getShort();
            offsetToData -= 2;
        }

        // Skip over offsetToData bytes
        while (offsetToData-- > 0) {
            buffer.get();
        }
    }

    private void parseData(long offset) throws IOException {
        MappedByteBuffer buffer = mapFile(mTraceFileName, offset);
        readDataFileHeader(buffer);

        ArrayList<TraceAction> trace = null;
        if (mClockSource == ClockSource.THREAD_CPU) {
            trace = new ArrayList<TraceAction>();
        }

        final boolean haveThreadClock = mClockSource != ClockSource.WALL;
        final boolean haveGlobalClock = mClockSource != ClockSource.THREAD_CPU;

        // Parse all call records to obtain elapsed time information.
        ThreadData prevThreadData = null;
        for (;;) {
            int threadId;
            int methodId;
            long threadTime, globalTime;
            try {
                int recordSize = mRecordSize;

                if (mVersionNumber == 1) {
                    threadId = buffer.get();
                    recordSize -= 1;
                } else {
                    threadId = buffer.getShort();
                    recordSize -= 2;
                }

                methodId = buffer.getInt();
                recordSize -= 4;

                switch (mClockSource) {
                    case WALL:
                        threadTime = 0;
                        globalTime = buffer.getInt();
                        recordSize -= 4;
                        break;
                    case DUAL:
                        threadTime = buffer.getInt();
                        globalTime = buffer.getInt();
                        recordSize -= 8;
                        break;
                    default:
                    case THREAD_CPU:
                        threadTime = buffer.getInt();
                        globalTime = 0;
                        recordSize -= 4;
                        break;
                }

                while (recordSize-- > 0) {
                    buffer.get();
                }
            } catch (BufferUnderflowException ex) {
                break;
            }

            int methodAction = methodId & 0x03;
            methodId = methodId & ~0x03;
            MethodData methodData = mMethodMap.get(methodId);
            if (methodData == null) {
                String name = String.format("(0x%1$x)", methodId);  //$NON-NLS-1$
                methodData = new MethodData(methodId, name);
                mMethodMap.put(methodId, methodData);
            }

            ThreadData threadData = mThreadMap.get(threadId);
            if (threadData == null) {
                String name = String.format("[%1$d]", threadId);  //$NON-NLS-1$
                threadData = new ThreadData(threadId, name, mTopLevel);
                mThreadMap.put(threadId, threadData);
            }

            long elapsedGlobalTime = 0;
            if (haveGlobalClock) {
                if (!threadData.mHaveGlobalTime) {
                    threadData.mGlobalStartTime = globalTime;
                    threadData.mHaveGlobalTime = true;
                } else {
                    elapsedGlobalTime = globalTime - threadData.mGlobalEndTime;
                }
                threadData.mGlobalEndTime = globalTime;
            }

            if (haveThreadClock) {
                long elapsedThreadTime = 0;
                if (!threadData.mHaveThreadTime) {
                    threadData.mThreadStartTime = threadTime;
                    threadData.mThreadCurrentTime = threadTime;
                    threadData.mHaveThreadTime = true;
                } else {
                    elapsedThreadTime = threadTime - threadData.mThreadEndTime;
                }
                threadData.mThreadEndTime = threadTime;

                if (!haveGlobalClock) {
                    // Detect context switches whenever execution appears to switch from one
                    // thread to another.  This assumption is only valid on uniprocessor
                    // systems (which is why we now have a dual clock mode).
                    // We represent context switches in the trace by pushing a call record
                    // with MethodData mContextSwitch onto the stack of the previous
                    // thread.  We arbitrarily set the start and end time of the context
                    // switch such that the context switch occurs in the middle of the thread
                    // time and itself accounts for zero thread time.
                    if (prevThreadData != null && prevThreadData != threadData) {
                        // Begin context switch from previous thread.
                        Call switchCall = prevThreadData.enter(mContextSwitch, trace);
                        switchCall.mThreadStartTime = prevThreadData.mThreadEndTime;
                        mCallList.add(switchCall);

                        // Return from context switch to current thread.
                        Call top = threadData.top();
                        if (top.getMethodData() == mContextSwitch) {
                            threadData.exit(mContextSwitch, trace);
                            long beforeSwitch = elapsedThreadTime / 2;
                            top.mThreadStartTime += beforeSwitch;
                            top.mThreadEndTime = top.mThreadStartTime;
                        }
                    }
                    prevThreadData = threadData;
                } else {
                    // If we have a global clock, then we can detect context switches (or blocking
                    // calls or cpu suspensions or clock anomalies) by comparing global time to
                    // thread time for successive calls that occur on the same thread.
                    // As above, we represent the context switch using a special method call.
                    long sleepTime = elapsedGlobalTime - elapsedThreadTime;
                    if (sleepTime > MIN_CONTEXT_SWITCH_TIME_USEC) {
                        Call switchCall = threadData.enter(mContextSwitch, trace);
                        long beforeSwitch = elapsedThreadTime / 2;
                        long afterSwitch = elapsedThreadTime - beforeSwitch;
                        switchCall.mGlobalStartTime = globalTime - elapsedGlobalTime + beforeSwitch;
                        switchCall.mGlobalEndTime = globalTime - afterSwitch;
                        switchCall.mThreadStartTime = threadTime - afterSwitch;
                        switchCall.mThreadEndTime = switchCall.mThreadStartTime;
                        threadData.exit(mContextSwitch, trace);
                        mCallList.add(switchCall);
                    }
                }

                // Add thread CPU time.
                Call top = threadData.top();
                top.addCpuTime(elapsedThreadTime);
            }

            switch (methodAction) {
                case METHOD_TRACE_ENTER: {
                    Call call = threadData.enter(methodData, trace);
                    if (haveGlobalClock) {
                        call.mGlobalStartTime = globalTime;
                    }
                    if (haveThreadClock) {
                        call.mThreadStartTime = threadTime;
                    }
                    mCallList.add(call);
                    break;
                }
                case METHOD_TRACE_EXIT:
                case METHOD_TRACE_UNROLL: {
                    Call call = threadData.exit(methodData, trace);
                    if (call != null) {
                        if (haveGlobalClock) {
                            call.mGlobalEndTime = globalTime;
                        }
                        if (haveThreadClock) {
                            call.mThreadEndTime = threadTime;
                        }
                    }
                    break;
                }
                default:
                    throw new RuntimeException("Unrecognized method action: " + methodAction);
            }
        }

        // Exit any pending open-ended calls.
        for (ThreadData threadData : mThreadMap.values()) {
            threadData.endTrace(trace);
        }

        // Recreate the global timeline from thread times, if needed.
        if (!haveGlobalClock) {
            long globalTime = 0;
            prevThreadData = null;
            for (TraceAction traceAction : trace) {
                Call call = traceAction.mCall;
                ThreadData threadData = call.getThreadData();

                if (traceAction.mAction == TraceAction.ACTION_ENTER) {
                    long threadTime = call.mThreadStartTime;
                    globalTime += call.mThreadStartTime - threadData.mThreadCurrentTime;
                    call.mGlobalStartTime = globalTime;
                    if (!threadData.mHaveGlobalTime) {
                        threadData.mHaveGlobalTime = true;
                        threadData.mGlobalStartTime = globalTime;
                    }
                    threadData.mThreadCurrentTime = threadTime;
                } else if (traceAction.mAction == TraceAction.ACTION_EXIT) {
                    long threadTime = call.mThreadEndTime;
                    globalTime += call.mThreadEndTime - threadData.mThreadCurrentTime;
                    call.mGlobalEndTime = globalTime;
                    threadData.mGlobalEndTime = globalTime;
                    threadData.mThreadCurrentTime = threadTime;
                } // else, ignore ACTION_INCOMPLETE calls, nothing to do
                prevThreadData = threadData;
            }
        }

        // Finish updating all calls and calculate the total time spent.
        for (int i = mCallList.size() - 1; i >= 0; i--) {
            Call call = mCallList.get(i);

            // Calculate exclusive real-time by subtracting inclusive real time
            // accumulated by children from the total span.
            long realTime = call.mGlobalEndTime - call.mGlobalStartTime;
            call.mExclusiveRealTime = Math.max(realTime - call.mInclusiveRealTime, 0);
            call.mInclusiveRealTime = realTime;

            call.finish();
        }
        mTotalCpuTime = 0;
        mTotalRealTime = 0;
        for (ThreadData threadData : mThreadMap.values()) {
            Call rootCall = threadData.getRootCall();
            threadData.updateRootCallTimeBounds();
            rootCall.finish();
            mTotalCpuTime += rootCall.mInclusiveCpuTime;
            mTotalRealTime += rootCall.mInclusiveRealTime;
        }

        if (mRegression) {
            System.out.format("totalCpuTime %dus\n", mTotalCpuTime);
            System.out.format("totalRealTime %dus\n", mTotalRealTime);

            dumpThreadTimes();
            dumpCallTimes();
        }
    }

    static final int PARSE_VERSION = 0;
    static final int PARSE_THREADS = 1;
    static final int PARSE_METHODS = 2;
    static final int PARSE_OPTIONS = 4;

    long parseKeys() throws IOException {
        BufferedReader in = null;
        try {
            in = new BufferedReader(new InputStreamReader(
                    new FileInputStream(mTraceFileName), "US-ASCII"));
        } catch (FileNotFoundException ex) {
            System.err.println(ex.getMessage());
        }

        long offset = 0;
        int mode = PARSE_VERSION;
        String line = null;
        while (true) {
            line = in.readLine();
            if (line == null) {
                throw new IOException("Key section does not have an *end marker");
            }

            // Calculate how much we have read from the file so far.  The
            // extra byte is for the line ending not included by readLine().
            offset += line.length() + 1;
            if (line.startsWith("*")) {
                if (line.equals("*version")) {
                    mode = PARSE_VERSION;
                    continue;
                }
                if (line.equals("*threads")) {
                    mode = PARSE_THREADS;
                    continue;
                }
                if (line.equals("*methods")) {
                    mode = PARSE_METHODS;
                    continue;
                }
                if (line.equals("*end")) {
                    break;
                }
            }
            switch (mode) {
            case PARSE_VERSION:
                mVersionNumber = Integer.decode(line);
                mode = PARSE_OPTIONS;
                break;
            case PARSE_THREADS:
                parseThread(line);
                break;
            case PARSE_METHODS:
                parseMethod(line);
                break;
            case PARSE_OPTIONS:
                parseOption(line);
                break;
            }
        }

        if (mClockSource == null) {
            mClockSource = ClockSource.THREAD_CPU;
        }
        return offset;
    }

    void parseOption(String line) {
        String[] tokens = line.split("=");
        if (tokens.length == 2) {
            String key = tokens[0];
            String value = tokens[1];
            mPropertiesMap.put(key, value);

            if (key.equals("clock")) {
                if (value.equals("thread-cpu")) {
                    mClockSource = ClockSource.THREAD_CPU;
                } else if (value.equals("wall")) {
                    mClockSource = ClockSource.WALL;
                } else if (value.equals("dual")) {
                    mClockSource = ClockSource.DUAL;
                }
            }
        }
    }

    void parseThread(String line) {
        String idStr = null;
        String name = null;
        Matcher matcher = mIdNamePattern.matcher(line);
        if (matcher.find()) {
            idStr = matcher.group(1);
            name = matcher.group(2);
        }
        if (idStr == null) return;
        if (name == null) name = "(unknown)";

        int id = Integer.decode(idStr);
        mThreadMap.put(id, new ThreadData(id, name, mTopLevel));
    }

    void parseMethod(String line) {
        String[] tokens = line.split("\t");
        int id = Long.decode(tokens[0]).intValue();
        String className = tokens[1];
        String methodName = null;
        String signature = null;
        String pathname = null;
        int lineNumber = -1;
        if (tokens.length == 6) {
            methodName = tokens[2];
            signature = tokens[3];
            pathname = tokens[4];
            lineNumber = Integer.decode(tokens[5]);
            pathname = constructPathname(className, pathname);
        } else if (tokens.length > 2) {
            if (tokens[3].startsWith("(")) {
                methodName = tokens[2];
                signature = tokens[3];
            } else {
                pathname = tokens[2];
                lineNumber = Integer.decode(tokens[3]);
            }
        }

        mMethodMap.put(id, new MethodData(id, className, methodName, signature,
                pathname, lineNumber));
    }

    private String constructPathname(String className, String pathname) {
        int index = className.lastIndexOf('/');
        if (index > 0 && index < className.length() - 1
                && pathname.endsWith(".java"))
            pathname = className.substring(0, index + 1) + pathname;
        return pathname;
    }

    private void analyzeData() {
        final TimeBase timeBase = getPreferredTimeBase();

        // Sort the threads into decreasing cpu time
        Collection<ThreadData> tv = mThreadMap.values();
        mSortedThreads = tv.toArray(new ThreadData[tv.size()]);
        Arrays.sort(mSortedThreads, new Comparator<ThreadData>() {
            @Override
            public int compare(ThreadData td1, ThreadData td2) {
                if (timeBase.getTime(td2) > timeBase.getTime(td1))
                    return 1;
                if (timeBase.getTime(td2) < timeBase.getTime(td1))
                    return -1;
                return td2.getName().compareTo(td1.getName());
            }
        });

        // Sort the methods into decreasing inclusive time
        Collection<MethodData> mv = mMethodMap.values();
        MethodData[] methods;
        methods = mv.toArray(new MethodData[mv.size()]);
        Arrays.sort(methods, new Comparator<MethodData>() {
            @Override
            public int compare(MethodData md1, MethodData md2) {
                if (timeBase.getElapsedInclusiveTime(md2) > timeBase.getElapsedInclusiveTime(md1))
                    return 1;
                if (timeBase.getElapsedInclusiveTime(md2) < timeBase.getElapsedInclusiveTime(md1))
                    return -1;
                return md1.getName().compareTo(md2.getName());
            }
        });

        // Count the number of methods with non-zero inclusive time
        int nonZero = 0;
        for (MethodData md : methods) {
            if (timeBase.getElapsedInclusiveTime(md) == 0)
                break;
            nonZero += 1;
        }

        // Copy the methods with non-zero time
        mSortedMethods = new MethodData[nonZero];
        int ii = 0;
        for (MethodData md : methods) {
            if (timeBase.getElapsedInclusiveTime(md) == 0)
                break;
            md.setRank(ii);
            mSortedMethods[ii++] = md;
        }

        // Let each method analyze its profile data
        for (MethodData md : mSortedMethods) {
            md.analyzeData(timeBase);
        }

        // Update all the calls to include the method rank in
        // their name.
        for (Call call : mCallList) {
            call.updateName();
        }

        if (mRegression) {
            dumpMethodStats();
        }
    }

    /*
     * This method computes a list of records that describe the the execution
     * timeline for each thread. Each record is a pair: (row, block) where: row:
     * is the ThreadData object block: is the call (containing the start and end
     * times)
     */
    @Override
    public ArrayList<TimeLineView.Record> getThreadTimeRecords() {
        TimeLineView.Record record;
        ArrayList<TimeLineView.Record> timeRecs;
        timeRecs = new ArrayList<TimeLineView.Record>();

        // For each thread, push a "toplevel" call that encompasses the
        // entire execution of the thread.
        for (ThreadData threadData : mSortedThreads) {
            if (!threadData.isEmpty() && threadData.getId() != 0) {
                record = new TimeLineView.Record(threadData, threadData.getRootCall());
                timeRecs.add(record);
            }
        }

        for (Call call : mCallList) {
            record = new TimeLineView.Record(call.getThreadData(), call);
            timeRecs.add(record);
        }

        if (mRegression) {
            dumpTimeRecs(timeRecs);
            System.exit(0);
        }
        return timeRecs;
    }

    private void dumpThreadTimes() {
        System.out.print("\nThread Times\n");
        System.out.print("id  t-start    t-end  g-start    g-end     name\n");
        for (ThreadData threadData : mThreadMap.values()) {
            System.out.format("%2d %8d %8d %8d %8d  %s\n",
                    threadData.getId(),
                    threadData.mThreadStartTime, threadData.mThreadEndTime,
                    threadData.mGlobalStartTime, threadData.mGlobalEndTime,
                    threadData.getName());
        }
    }

    private void dumpCallTimes() {
        System.out.print("\nCall Times\n");
        System.out.print("id  t-start    t-end  g-start    g-end    excl.    incl.  method\n");
        for (Call call : mCallList) {
            System.out.format("%2d %8d %8d %8d %8d %8d %8d  %s\n",
                    call.getThreadId(), call.mThreadStartTime, call.mThreadEndTime,
                    call.mGlobalStartTime, call.mGlobalEndTime,
                    call.mExclusiveCpuTime, call.mInclusiveCpuTime,
                    call.getMethodData().getName());
        }
    }

    private void dumpMethodStats() {
        System.out.print("\nMethod Stats\n");
        System.out.print("Excl Cpu  Incl Cpu  Excl Real Incl Real    Calls  Method\n");
        for (MethodData md : mSortedMethods) {
            System.out.format("%9d %9d %9s  %s\n",
                    md.getElapsedExclusiveCpuTime(), md.getElapsedInclusiveCpuTime(),
                    md.getElapsedExclusiveRealTime(), md.getElapsedInclusiveRealTime(),
                    md.getCalls(), md.getProfileName());
        }
    }

    private void dumpTimeRecs(ArrayList<TimeLineView.Record> timeRecs) {
        System.out.print("\nTime Records\n");
        System.out.print("id  t-start    t-end  g-start    g-end  method\n");
        for (TimeLineView.Record record : timeRecs) {
            Call call = (Call) record.block;
            System.out.format("%2d %8d %8d %8d %8d  %s\n",
                    call.getThreadId(), call.mThreadStartTime, call.mThreadEndTime,
                    call.mGlobalStartTime, call.mGlobalEndTime,
                    call.getMethodData().getName());
        }
    }

    @Override
    public HashMap<Integer, String> getThreadLabels() {
        HashMap<Integer, String> labels = new HashMap<Integer, String>();
        for (ThreadData t : mThreadMap.values()) {
            labels.put(t.getId(), t.getName());
        }
        return labels;
    }

    @Override
    public MethodData[] getMethods() {
        return mSortedMethods;
    }

    @Override
    public ThreadData[] getThreads() {
        return mSortedThreads;
    }

    @Override
    public long getTotalCpuTime() {
        return mTotalCpuTime;
    }

    @Override
    public long getTotalRealTime() {
        return mTotalRealTime;
    }

    @Override
    public boolean haveCpuTime() {
        return mClockSource != ClockSource.WALL;
    }

    @Override
    public boolean haveRealTime() {
        return mClockSource != ClockSource.THREAD_CPU;
    }

    @Override
    public HashMap<String, String> getProperties() {
        return mPropertiesMap;
    }

    @Override
    public TimeBase getPreferredTimeBase() {
        if (mClockSource == ClockSource.WALL) {
            return TimeBase.REAL_TIME;
        }
        return TimeBase.CPU_TIME;
    }

    @Override
    public String getClockSource() {
        switch (mClockSource) {
            case THREAD_CPU:
                return "cpu time";
            case WALL:
                return "real time";
            case DUAL:
                return "real time, dual clock";
        }
        return null;
    }
}