Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit b7692965 authored by Felipe Leme's avatar Felipe Leme
Browse files

Improved TimingsTraceLog performance by using arrays, instead of Deque of Pairs. 

Test: manual verification
Test: atest FrameworksMockingCoreTests:android.util.TimingsTraceLogTest

Fixes: 135754571

Change-Id: I7a3571a422d09cd618f6610d3403a870af1ebafa
parent 3daa38b7

core/java/android/util/TimingsTraceLog.java

+57 −21
Original line number Diff line number Diff line
@@ -21,10 +21,10 @@ import android.os.Build; 
import android.os.SystemClock;

import android.os.Trace;



import java.util.ArrayDeque;

import com.android.internal.annotations.VisibleForTesting;



import java.util.ArrayList;

import java.util.Collections;

import java.util.Deque;

import java.util.List;



/**
@@ -37,16 +37,37 @@ import java.util.List; 
public class TimingsTraceLog {

    // Debug boot time for every step if it's non-user build.

    private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER;

    private final Deque<Pair<String, Long>> mStartTimes =

            DEBUG_BOOT_TIME ? new ArrayDeque<>() : null;



    // Maximum number of nested calls that are stored

    private static final int MAX_NESTED_CALLS = 10;



    private final String[] mStartNames;

    private final long[] mStartTimes;



    private final String mTag;

    private long mTraceTag;

    private long mThreadId;

    private final long mTraceTag;

    private final long mThreadId;

    private final int mMaxNestedCalls;



    private int mCurrentLevel = -1;



    public TimingsTraceLog(String tag, long traceTag) {

        this(tag, traceTag, DEBUG_BOOT_TIME ? MAX_NESTED_CALLS : -1);

    }



    @VisibleForTesting

    public TimingsTraceLog(String tag, long traceTag, int maxNestedCalls) {

        mTag = tag;

        mTraceTag = traceTag;

        mThreadId = Thread.currentThread().getId();

        mMaxNestedCalls = maxNestedCalls;

        if (maxNestedCalls > 0) {

            mStartNames = new String[maxNestedCalls];

            mStartTimes = new long[maxNestedCalls];

        } else {

            mStartNames = null;

            mStartTimes = null;

        }

    }



    /**
@@ -56,27 +77,41 @@ public class TimingsTraceLog { 
    public void traceBegin(String name) {

        assertSameThread();

        Trace.traceBegin(mTraceTag, name);

        if (DEBUG_BOOT_TIME) {

            mStartTimes.push(Pair.create(name, SystemClock.elapsedRealtime()));



        if (!DEBUG_BOOT_TIME) return;



        if (mCurrentLevel + 1 >= mMaxNestedCalls) {

            Slog.w(mTag, "not tracing duration of '" + name + "' because already reached "

                    + mMaxNestedCalls + " levels");

            return;

        }



        mCurrentLevel++;

        mStartNames[mCurrentLevel] = name;

        mStartTimes[mCurrentLevel] = SystemClock.elapsedRealtime();

    }



    /**

     * End tracing previously {@link #traceBegin(String) started} section.

     * Also {@link #logDuration logs} the duration.

     *

     * <p>Also {@link #logDuration logs} the duration.

     */

    public void traceEnd() {

        assertSameThread();

        Trace.traceEnd(mTraceTag);

        if (!DEBUG_BOOT_TIME) {

            return;

        }

        if (mStartTimes.peek() == null) {



        if (!DEBUG_BOOT_TIME) return;



        if (mCurrentLevel < 0) {

            Slog.w(mTag, "traceEnd called more times than traceBegin");

            return;

        }

        Pair<String, Long> event = mStartTimes.pop();

        logDuration(event.first, (SystemClock.elapsedRealtime() - event.second));



        final String name = mStartNames[mCurrentLevel];

        final long duration = SystemClock.elapsedRealtime() - mStartTimes[mCurrentLevel];

        mCurrentLevel--;



        logDuration(name, duration);

    }



    private void assertSameThread() {
@@ -89,7 +124,7 @@ public class TimingsTraceLog { 
    }



    /**

     * Log the duration so it can be parsed by external tools for performance reporting

     * Logs a duration so it can be parsed by external tools for performance reporting.

     */

    public void logDuration(String name, long timeMs) {

        Slog.d(mTag, name + " took to complete: " + timeMs + "ms");
@@ -105,10 +140,11 @@ public class TimingsTraceLog { 
     */

    @NonNull

    public final List<String> getUnfinishedTracesForDebug() {

        if (mStartTimes == null || mStartTimes.isEmpty()) return Collections.emptyList();



        final ArrayList<String> stack = new ArrayList<>(mStartTimes.size());

        mStartTimes.descendingIterator().forEachRemaining((pair) -> stack.add(pair.first));

        return stack;

        if (mStartTimes == null || mCurrentLevel < 0) return Collections.emptyList();

        final ArrayList<String> list = new ArrayList<>(mCurrentLevel + 1);

        for (int i = 0; i <= mCurrentLevel; i++) {

            list.add(mStartNames[i]);

        }

        return list;

    }

}

core/tests/coretests/src/android/util/TimingsTraceLogTest.java→core/tests/mockingcoretests/src/android/util/TimingsTraceLogTest.java

+190 −0
Original line number Diff line number Diff line
@@ -13,18 +13,34 @@ 
 * See the License for the specific language governing permissions and

 * limitations under the License.

 */



package android.util;



import static android.os.Trace.TRACE_TAG_APP;



import static com.android.dx.mockito.inline.extended.ExtendedMockito.mockitoSession;

import static com.android.dx.mockito.inline.extended.ExtendedMockito.verify;



import static com.google.common.truth.Truth.assertThat;



import static org.mockito.Matchers.anyString;

import static org.mockito.Matchers.contains;

import static org.mockito.Matchers.eq;

import static org.mockito.Matchers.matches;

import static org.mockito.Mockito.never;

import static org.mockito.Mockito.times;



import android.os.Trace;



import androidx.test.filters.SmallTest;

import androidx.test.runner.AndroidJUnit4;



import com.android.dx.mockito.inline.extended.MockedVoidMethod;



import org.junit.After;

import org.junit.Before;

import org.junit.Test;

import org.junit.runner.RunWith;

import org.mockito.MockitoSession;



import java.util.ArrayList;

import java.util.List;
@@ -32,15 +48,32 @@ import java.util.List; 
/**

 * Tests for {@link TimingsTraceLog}.

 *

 * <p>Usage: {@code atest FrameworksCoreTests:android.util.TimingsTraceLogTest}

 * <p>Usage: {@code atest FrameworksMockingCoreTests:android.util.TimingsTraceLogTest}

 */

@SmallTest

@RunWith(AndroidJUnit4.class)

public class TimingsTraceLogTest {



    private static final String TAG = "TEST";



    private MockitoSession mSession;



    @Before

    public final void startMockSession() {

        mSession = mockitoSession()

                .spyStatic(Slog.class)

                .spyStatic(Trace.class)

                .startMocking();

    }



    @After

    public final void finishMockSession() {

        mSession.finishMocking();

    }



    @Test

    public void testDifferentThreads() throws Exception {

        TimingsTraceLog log = new TimingsTraceLog("TEST", Trace.TRACE_TAG_APP);

        TimingsTraceLog log = new TimingsTraceLog(TAG, TRACE_TAG_APP);

        // Should be able to log on the same thread

        log.traceBegin("test");

        log.traceEnd();
@@ -58,7 +91,7 @@ public class TimingsTraceLogTest { 
            } catch (IllegalStateException expected) {

            }

            // Verify that creating a new log will work

            TimingsTraceLog log2 = new TimingsTraceLog("TEST", Trace.TRACE_TAG_APP);

            TimingsTraceLog log2 = new TimingsTraceLog(TAG, TRACE_TAG_APP);

            log2.traceBegin("test");

            log2.traceEnd();
@@ -85,4 +118,73 @@ public class TimingsTraceLogTest { 
        log.traceEnd();

        assertThat(log.getUnfinishedTracesForDebug()).isEmpty();

    }



    @Test

    public void testLogDuration() throws Exception {

        TimingsTraceLog log = new TimingsTraceLog(TAG, TRACE_TAG_APP, 10);

        log.logDuration("logro", 42);

        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), contains("logro took to complete: 42ms")));

    }



    @Test

    public void testOneLevel() throws Exception {

        TimingsTraceLog log = new TimingsTraceLog(TAG, TRACE_TAG_APP, 10);

        log.traceBegin("test");

        log.traceEnd();



        verify((MockedVoidMethod) () -> Trace.traceBegin(TRACE_TAG_APP, "test"));

        verify((MockedVoidMethod) () -> Trace.traceEnd(TRACE_TAG_APP));

        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), matches("test took to complete: \\dms")));

    }



    @Test

    public void testMultipleLevels() throws Exception {

        TimingsTraceLog log = new TimingsTraceLog(TAG, Trace.TRACE_TAG_APP, 10);

        log.traceBegin("L1");

        log.traceBegin("L2");

        log.traceEnd();

        log.traceEnd();



        verify((MockedVoidMethod) () -> Trace.traceBegin(TRACE_TAG_APP, "L1"));

        verify((MockedVoidMethod) () -> Trace.traceBegin(TRACE_TAG_APP, "L2"));

        verify((MockedVoidMethod) () -> Trace.traceEnd(TRACE_TAG_APP), times(2)); // L1 and L2



        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), matches("L2 took to complete: \\d+ms")));

        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), matches("L1 took to complete: \\d+ms")));

    }



    @Test

    public void testTooManyLevels() throws Exception {

        TimingsTraceLog log = new TimingsTraceLog(TAG, Trace.TRACE_TAG_APP, 2);



        log.traceBegin("L1"); // ok

        log.traceBegin("L2"); // ok

        log.traceBegin("L3"); // logging ignored ( > 2)



        log.traceEnd();

        log.traceEnd();

        log.traceEnd();



        verify((MockedVoidMethod) () -> Trace.traceBegin(TRACE_TAG_APP, "L1"));

        verify((MockedVoidMethod) () -> Trace.traceBegin(TRACE_TAG_APP, "L2"));

        verify((MockedVoidMethod) () -> Trace.traceBegin(TRACE_TAG_APP, "L3"));

        verify((MockedVoidMethod) () -> Trace.traceEnd(TRACE_TAG_APP), times(3));



        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), matches("L2 took to complete: \\d+ms")));

        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), matches("L1 took to complete: \\d+ms")));

        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), matches("L3 took to complete: \\d+ms")),

                never());



        verify((MockedVoidMethod) () -> Slog.w(TAG, "not tracing duration of 'L3' "

                + "because already reached 2 levels"));

    }



    @Test

    public void testEndNoBegin() throws Exception {

        TimingsTraceLog log = new TimingsTraceLog(TAG, TRACE_TAG_APP);

        log.traceEnd();

        verify((MockedVoidMethod) () -> Trace.traceEnd(TRACE_TAG_APP));

        verify((MockedVoidMethod) () -> Slog.d(eq(TAG), anyString()), never());

        verify((MockedVoidMethod) () -> Slog.w(TAG, "traceEnd called more times than traceBegin"));

    }

}