Merge "Improved TimingsTraceLog performance by using arrays, instead of Deque of Pairs." (482c2c99) · Commits · e / os / android_frameworks_base

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"));
		}
		}