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

1 files changed, 190 insertions, 0 deletions

diff --git a/core/tests/mockingcoretests/src/android/util/TimingsTraceLogTest.java b/core/tests/mockingcoretests/src/android/util/TimingsTraceLogTest.java
new file mode 100644
index 000000000000..5dc44d21c6b7
--- /dev/null
+++ b/core/tests/mockingcoretests/src/android/util/TimingsTraceLogTest.java
@@ -0,0 +1,190 @@
+/*
+ * Copyright (C) 2017 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.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;
+
+/**
+ * Tests for {@link TimingsTraceLog}.
+ *
+ * <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(TAG, TRACE_TAG_APP);
+        // Should be able to log on the same thread
+        log.traceBegin("test");
+        log.traceEnd();
+        final List<String> errors = new ArrayList<>();
+        // Calling from a different thread should fail
+        Thread t = new Thread(() -> {
+            try {
+                log.traceBegin("test");
+                errors.add("traceBegin should fail on a different thread");
+            } catch (IllegalStateException expected) {
+            }
+            try {
+                log.traceEnd();
+                errors.add("traceEnd should fail on a different thread");
+            } catch (IllegalStateException expected) {
+            }
+            // Verify that creating a new log will work
+            TimingsTraceLog log2 = new TimingsTraceLog(TAG, TRACE_TAG_APP);
+            log2.traceBegin("test");
+            log2.traceEnd();
+
+        });
+        t.start();
+        t.join();
+        assertThat(errors).isEmpty();
+    }
+
+    @Test
+    public void testGetUnfinishedTracesForDebug() {
+        TimingsTraceLog log = new TimingsTraceLog("TEST", Trace.TRACE_TAG_APP);
+        assertThat(log.getUnfinishedTracesForDebug()).isEmpty();
+
+        log.traceBegin("One");
+        assertThat(log.getUnfinishedTracesForDebug()).containsExactly("One").inOrder();
+
+        log.traceBegin("Two");
+        assertThat(log.getUnfinishedTracesForDebug()).containsExactly("One", "Two").inOrder();
+
+        log.traceEnd();
+        assertThat(log.getUnfinishedTracesForDebug()).containsExactly("One").inOrder();
+
+        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"));
+    }
+}