diff options
3 files changed, 247 insertions, 109 deletions
diff --git a/core/java/android/util/TimingsTraceLog.java b/core/java/android/util/TimingsTraceLog.java index bc2172297f83..5370645d31bc 100644 --- a/core/java/android/util/TimingsTraceLog.java +++ b/core/java/android/util/TimingsTraceLog.java @@ -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; } } diff --git a/core/tests/coretests/src/android/util/TimingsTraceLogTest.java b/core/tests/coretests/src/android/util/TimingsTraceLogTest.java deleted file mode 100644 index f76471c015e6..000000000000 --- a/core/tests/coretests/src/android/util/TimingsTraceLogTest.java +++ /dev/null @@ -1,88 +0,0 @@ -/* - * 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 com.google.common.truth.Truth.assertThat; - -import android.os.Trace; - -import androidx.test.filters.SmallTest; -import androidx.test.runner.AndroidJUnit4; - -import org.junit.Test; -import org.junit.runner.RunWith; - -import java.util.ArrayList; -import java.util.List; - -/** - * Tests for {@link TimingsTraceLog}. - * - * <p>Usage: {@code atest FrameworksCoreTests:android.util.TimingsTraceLogTest} - */ -@SmallTest -@RunWith(AndroidJUnit4.class) -public class TimingsTraceLogTest { - - @Test - public void testDifferentThreads() throws Exception { - TimingsTraceLog log = new TimingsTraceLog("TEST", Trace.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("TEST", Trace.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(); - } -} 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")); + } +} |