VmTraceParserTest.java

/*
 * Copyright (C) 2013 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.tools.perflib.vmtrace;

import com.google.common.primitives.Ints;

import junit.framework.TestCase;

import java.io.File;
import java.io.IOException;
import java.net.URL;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Collections;
import java.util.Comparator;
import java.util.Iterator;
import java.util.List;
import java.util.Locale;
import java.util.Map;
import java.util.concurrent.TimeUnit;

public class VmTraceParserTest extends TestCase {
    public void testParseHeader() throws IOException {
        File f = getFile("/header.trace");
        VmTraceParser parser = new VmTraceParser(f);
        parser.parseHeader(f);
        VmTraceData traceData = parser.getTraceData();

        assertEquals(3, traceData.getVersion());
        assertTrue(traceData.isDataFileOverflow());
        assertEquals(VmTraceData.VmClockType.DUAL, traceData.getVmClockType());
        assertEquals("dalvik", traceData.getVm());

        Collection<ThreadInfo> threads = traceData.getThreads();
        assertEquals(2, threads.size());
        assertEquals(1, traceData.getThread("main").getId());
        assertEquals(11, traceData.getThread("AsyncTask #1").getId());

        Map<Long, MethodInfo> methods = traceData.getMethods();
        assertEquals(4, methods.size());

        MethodInfo info = traceData.getMethod(0x62830738);
        assertNotNull(info);
        assertEquals("android/graphics/Bitmap", info.className);
        assertEquals("access$100", info.methodName);
        assertEquals("(I)V", info.signature);
        assertEquals("android/graphics/BitmapF.java", info.srcPath);
        assertEquals(29, info.srcLineNumber);

        info = traceData.getMethod(0x6282b4b0);
        assertNotNull(info);
        assertEquals(-1, info.srcLineNumber);
    }

    private class CallFormatter implements Call.Formatter {
        private final Map<Long, MethodInfo> mMethodInfo;

        public CallFormatter(Map<Long, MethodInfo> methodInfo) {
            mMethodInfo = methodInfo;
        }

        @Override
        public String format(Call c) {
            MethodInfo info = mMethodInfo.get(c.getMethodId());
            return info == null ? Long.toString(c.getMethodId()) : info.getFullName();
        }
    }

    private void testTrace(String traceName, String threadName, String expectedCallSequence)
            throws IOException {
        VmTraceData traceData = getVmTraceData(traceName);

        ThreadInfo thread = traceData.getThread(threadName);
        assertNotNull(String.format("Thread %s was not found in the trace", threadName), thread);

        Call call = thread.getTopLevelCall();
        assertNotNull(call);
        String actual = call.format(new CallFormatter(traceData.getMethods()));
        assertEquals(expectedCallSequence, actual);
    }

    public void testBasicTrace() throws IOException {
        String expected =
                          " -> AsyncTask #1.:  -> android/os/Debug.startMethodTracing: (Ljava/lang/String;)V -> android/os/Debug.startMethodTracing: (Ljava/lang/String;II)V -> dalvik/system/VMDebug.startMethodTracing: (Ljava/lang/String;II)V\n"
                        + "                    -> com/test/android/traceview/Basic.foo: ()V -> com/test/android/traceview/Basic.bar: ()I\n"
                        + "                    -> android/os/Debug.stopMethodTracing: ()V -> dalvik/system/VMDebug.stopMethodTracing: ()V";
        testTrace("/basic.trace", "AsyncTask #1", expected);

        // verify that the same results show up when trace is generated from an older device
        testTrace("/basic-api10.trace", "AsyncTask #1", expected);
    }

    public void testMisMatchedTrace() throws IOException {
        String expected =
                  " -> AsyncTask #1.:  -> com/test/android/traceview/MisMatched.foo: ()V -> com/test/android/traceview/MisMatched.bar: ()V -> android/os/Debug.startMethodTracing: (Ljava/lang/String;)V -> android/os/Debug.startMethodTracing: (Ljava/lang/String;II)V -> dalvik/system/VMDebug.startMethodTracing: (Ljava/lang/String;II)V\n"
                + "                                                                                                                        -> com/test/android/traceview/MisMatched.baz: ()I\n"
                + "                    -> android/os/Debug.stopMethodTracing: ()V -> dalvik/system/VMDebug.stopMethodTracing: ()V";
        testTrace("/mismatched.trace", "AsyncTask #1", expected);
    }

    public void testExceptionTrace() throws IOException {
        String expected =
                  " -> AsyncTask #1.:  -> android/os/Debug.startMethodTracing: (Ljava/lang/String;)V -> android/os/Debug.startMethodTracing: (Ljava/lang/String;II)V -> dalvik/system/VMDebug.startMethodTracing: (Ljava/lang/String;II)V\n"
                + "                    -> com/test/android/traceview/Exceptions.foo: ()V -> com/test/android/traceview/Exceptions.bar: ()V -> com/test/android/traceview/Exceptions.baz: ()V -> java/lang/RuntimeException.<init>: ()V -> java/lang/Exception.<init>: ()V -> java/lang/Throwable.<init>: ()V -> java/util/Collections.emptyList: ()Ljava/util/List;\n"
                + "                                                                                                                                                                                                                                                                                          -> java/lang/Throwable.fillInStackTrace: ()Ljava/lang/Throwable; -> java/lang/Throwable.nativeFillInStackTrace: ()Ljava/lang/Object;\n"
                + "                    -> android/os/Debug.stopMethodTracing: ()V -> dalvik/system/VMDebug.stopMethodTracing: ()V";
        testTrace("/exception.trace", "AsyncTask #1", expected);
    }

    public void testCallDurations() throws IOException {
        validateCallDurations("/basic.trace", "AsyncTask #1");
        validateCallDurations("/mismatched.trace", "AsyncTask #1");
        validateCallDurations("/exception.trace", "AsyncTask #1");
    }

    private void validateCallDurations(String traceName, String threadName) throws IOException {
        VmTraceData traceData = getVmTraceData(traceName);

        ThreadInfo thread = traceData.getThread(threadName);
        assertNotNull(String.format("Thread %s was not found in the trace", threadName), thread);

        Call topLevelCall = thread.getTopLevelCall();
        assertNotNull(topLevelCall);
        Iterator<Call> it = topLevelCall.getCallHierarchyIterator();
        while (it.hasNext()) {
            Call c = it.next();

            assertTrue(c.getEntryTime(ClockType.GLOBAL, TimeUnit.NANOSECONDS) <=
                    c.getExitTime(ClockType.GLOBAL, TimeUnit.NANOSECONDS));
            assertTrue(c.getEntryTime(ClockType.THREAD, TimeUnit.NANOSECONDS) <=
                    c.getExitTime(ClockType.THREAD, TimeUnit.NANOSECONDS));
        }
    }

    public void testMethodStats() throws IOException {
        VmTraceData traceData = getVmTraceData("/basic.trace");
        final ThreadInfo thread = traceData.getThread("AsyncTask #1");
        List<Map.Entry<Long, MethodInfo>> methods = new ArrayList<Map.Entry<Long, MethodInfo>>(
                traceData.getMethods().entrySet());
        Collections.sort(methods, new Comparator<Map.Entry<Long, MethodInfo>>() {
            @Override
            public int compare(Map.Entry<Long, MethodInfo> o1, Map.Entry<Long, MethodInfo> o2) {
                long diff =
                        o2.getValue().getProfileData().getInclusiveTime(
                                thread, ClockType.THREAD, TimeUnit.NANOSECONDS) -
                        o1.getValue().getProfileData().getInclusiveTime(
                                thread, ClockType.THREAD, TimeUnit.NANOSECONDS);
                return Ints.saturatedCast(diff);
            }
        });

        // verify that the top level actually comes out with the max time
        // note that while this works for the simple traces currently being tested, this
        // condition itself isn't valid in case some methods are being called from multiple
        // threads, in which their inclusive time could be higher than any of the thread's
        // toplevel time.
        assertEquals("AsyncTask #1.: ", methods.get(0).getValue().getFullName());
    }

    // Validate that the inclusive time of the top level call = sum of all inclusive times of
    // all methods called from that top level
    public void testMethodStats2() throws IOException {
        VmTraceData traceData = getVmTraceData("/basic.trace");
        ThreadInfo thread = traceData.getThread("AsyncTask #1");
        Call top = thread.getTopLevelCall();

        assertNotNull(top);

        long topThreadTime = top.getInclusiveTime(ClockType.THREAD, TimeUnit.NANOSECONDS);

        Collection<MethodInfo> methods = traceData.getMethods().values();
        Iterator<MethodInfo> it = methods.iterator();
        long sum = 0;

        while (it.hasNext()) {
            MethodInfo method = it.next();
            sum += method.getProfileData().getExclusiveTime(thread, ClockType.THREAD,
                    TimeUnit.NANOSECONDS);
        }

        assertEquals(topThreadTime, sum);
    }

    public void testMethodProfileData() throws IOException {
        VmTraceData traceData = getVmTraceData("/basic.trace");
        ThreadInfo thread = traceData.getThread("AsyncTask #1");
        Call top = thread.getTopLevelCall();

        assertNotNull(top);

        MethodProfileData topProfileData = traceData.getMethod(top.getMethodId()).getProfileData();

        // There should only be 1 instance of the top level method, so that call's time
        // should match its corresponding method's time.
        assertEquals(top.getExclusiveTime(ClockType.GLOBAL, TimeUnit.NANOSECONDS),
                topProfileData.getExclusiveTime(thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS));
        assertEquals(top.getInclusiveTime(ClockType.GLOBAL, TimeUnit.NANOSECONDS),
                topProfileData.getInclusiveTime(thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS));

        // The top level call's time should match the sum of all its callee's inclusive times
        // plus the top level's exclusive time.
        long sum = 0;
        for (Long callee : topProfileData.getCallees(thread)) {
            sum += topProfileData.getInclusiveTimeByCallee(thread, callee, ClockType.GLOBAL,
                    TimeUnit.NANOSECONDS);
        }

        long exclusiveTime = top.getExclusiveTime(ClockType.GLOBAL, TimeUnit.NANOSECONDS);
        assertEquals(top.getInclusiveTime(ClockType.GLOBAL, TimeUnit.NANOSECONDS),
                exclusiveTime + sum);

        for (MethodInfo method : traceData.getMethods().values()) {
            MethodProfileData profile = method.getProfileData();
            if (profile.getInvocationCount(thread) == 0) {
                continue;
            }

            boolean isTop = method.id == top.getMethodId();

            // Top level call should not have any callers, everyone else should have atleast 1
            assertEquals(isTop, profile.getCallers(thread).isEmpty());

            if (profile.isRecursive()) {
                continue;
            }

            // Validate that the inclusive time is properly split across all callees
            long methodInclusiveTime =
                    profile.getInclusiveTime(thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS);
            long methodExclusiveTime =
                    profile.getExclusiveTime(thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS);
            long sumCalleeInclusiveTime = sumInclusiveTimesByCallee(
                    profile, thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS);
            assertEquals(methodInclusiveTime, methodExclusiveTime + sumCalleeInclusiveTime);

            if (!isTop) {
                // Validate that the inclusive time is properly attributed to all its callers
                long sumInclusiveTimeByCaller = sumInclusiveTimesByCaller(
                        profile, thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS);
                assertEquals(methodInclusiveTime, sumInclusiveTimeByCaller);

                // Validate that exclusive time is properly attributed to all callers
                long sumCallerExclusiveTimeByCaller = sumExclusiveTimesByCaller(
                        profile, thread, ClockType.GLOBAL, TimeUnit.NANOSECONDS);
                assertEquals(methodExclusiveTime, sumCallerExclusiveTimeByCaller);

                // Validate that the method count is correctly distributed among the callers
                assertEquals(profile.getInvocationCount(thread), sumInvocationCountsByCaller(
                        profile,
                        thread));
            }
        }
    }

    private long sumInvocationCountsByCaller(MethodProfileData profile, ThreadInfo thread) {
        long sum = 0;
        for (Long callerId : profile.getCallers(thread)) {
            sum += profile.getInvocationCountFromCaller(thread, callerId);
        }
        return sum;
    }

    private long sumInclusiveTimesByCaller(MethodProfileData profile, ThreadInfo thread,
            ClockType type, TimeUnit unit) {
        long sum = 0;
        for (Long calleeId : profile.getCallers(thread)) {
            sum += profile.getInclusiveTimeByCaller(thread, calleeId, type, unit);
        }
        return sum;
    }

    private long sumExclusiveTimesByCaller(MethodProfileData profile, ThreadInfo thread,
            ClockType type, TimeUnit unit) {
        long sum = 0;
        for (Long calleeId : profile.getCallers(thread)) {
            sum += profile.getExclusiveTimeByCaller(thread, calleeId, type, unit);
        }
        return sum;
    }

    private long sumInclusiveTimesByCallee(MethodProfileData profile, ThreadInfo thread,
            ClockType type, TimeUnit unit) {
        long sum = 0;
        for (Long calleeId : profile.getCallees(thread)) {
            sum += profile.getInclusiveTimeByCallee(thread, calleeId, type, unit);
        }
        return sum;
    }


    public void testSearch() throws IOException {
        VmTraceData traceData = getVmTraceData("/basic.trace");
        ThreadInfo thread = traceData.getThread("AsyncTask #1");

        SearchResult results = traceData.searchFor("startMethodTracing", thread);

        // 3 different methods (varying in parameter list) of name startMethodTracing are called
        assertEquals(3, results.getMethods().size());
        assertEquals(3, results.getInstances().size());
    }

    // Validates that search is not impacted by current locale
    public void testSearchLocale() throws IOException {
        VmTraceData traceData = getVmTraceData("/basic.trace");
        ThreadInfo thread = traceData.getThread("AsyncTask #1");

        String pattern = "ii)v";
        SearchResult results = traceData.searchFor(pattern, thread);

        Locale originalDefaultLocale = Locale.getDefault();

        try {
            // Turkish has two different variants for lowercase i
            Locale.setDefault(new Locale("tr", "TR"));
            SearchResult turkish = traceData.searchFor(pattern, thread);

            assertEquals(results.getInstances().size(), turkish.getInstances().size());
            assertEquals(results.getMethods().size(), turkish.getMethods().size());
        } finally {
            Locale.setDefault(originalDefaultLocale);
        }
    }

    private VmTraceData getVmTraceData(String traceFilePath) throws IOException {
        VmTraceParser parser = new VmTraceParser(getFile(traceFilePath));
        parser.parse();
        return parser.getTraceData();
    }

    private File getFile(String path) {
        URL resource = getClass().getResource(path);
        // Note: When running from an IntelliJ, make sure the IntelliJ compiler settings treats
        // *.trace files as resources, otherwise they are excluded from compiler output
        // resulting in a NPE.
        assertNotNull(path + " not found", resource);
        return new File(resource.getFile());
    }
}