Merge "Add EventLogger, EventLoggerWrapper."
diff --git a/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/Reflect.java b/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/Reflect.java
new file mode 100644
index 0000000..a2603b5
--- /dev/null
+++ b/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/Reflect.java
@@ -0,0 +1,103 @@
+/*
+ * Copyright 2021 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.server.nearby.common.bluetooth.fastpair;
+
+import java.lang.reflect.InvocationTargetException;
+import java.lang.reflect.Method;
+
+/**
+ * Utilities for calling methods using reflection. The main benefit of using this helper is to avoid
+ * complications around exception handling when calling methods reflectively. It's not safe to use
+ * Java 8's multicatch on such exceptions, because the java compiler converts multicatch into
+ * ReflectiveOperationException in some instances, which doesn't work on older sdk versions.
+ * Instead, use these utilities and catch ReflectionException.
+ *
+ * <p>Example usage:
+ *
+ * <pre>{@code
+ * try {
+ * Reflect.on(btAdapter)
+ * .withMethod("setScanMode", int.class)
+ * .invoke(BluetoothAdapter.SCAN_MODE_CONNECTABLE_DISCOVERABLE)
+ * } catch (ReflectionException e) { }
+ * }</pre>
+ */
+// TODO(b/202549655): remove existing Reflect usage. New usage is not allowed! No exception!
+public final class Reflect {
+ private final Object mTargetObject;
+
+ private Reflect(Object targetObject) {
+ this.mTargetObject = targetObject;
+ }
+
+ /** Creates an instance of this helper to invoke methods on the given target object. */
+ public static Reflect on(Object targetObject) {
+ return new Reflect(targetObject);
+ }
+
+ /** Finds a method with the given name and parameter types. */
+ public ReflectionMethod withMethod(String methodName, Class<?>... paramTypes)
+ throws ReflectionException {
+ try {
+ return new ReflectionMethod(mTargetObject.getClass().getMethod(methodName, paramTypes));
+ } catch (NoSuchMethodException e) {
+ throw new ReflectionException(e);
+ }
+ }
+
+ /** Represents an invokable method found reflectively. */
+ public final class ReflectionMethod {
+ private final Method mMethod;
+
+ private ReflectionMethod(Method method) {
+ this.mMethod = method;
+ }
+
+ /**
+ * Invokes this instance method with the given parameters. The called method does not return
+ * a value.
+ */
+ public void invoke(Object... parameters) throws ReflectionException {
+ try {
+ mMethod.invoke(mTargetObject, parameters);
+ } catch (IllegalAccessException e) {
+ throw new ReflectionException(e);
+ } catch (InvocationTargetException e) {
+ throw new ReflectionException(e);
+ }
+ }
+
+ /**
+ * Invokes this instance method with the given parameters. The called method returns a non
+ * null value.
+ */
+ public Object get(Object... parameters) throws ReflectionException {
+ Object value;
+ try {
+ value = mMethod.invoke(mTargetObject, parameters);
+ } catch (IllegalAccessException e) {
+ throw new ReflectionException(e);
+ } catch (InvocationTargetException e) {
+ throw new ReflectionException(e);
+ }
+ if (value == null) {
+ throw new ReflectionException(new NullPointerException());
+ }
+ return value;
+ }
+ }
+}
diff --git a/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/ReflectionException.java b/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/ReflectionException.java
new file mode 100644
index 0000000..1c20c55
--- /dev/null
+++ b/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/ReflectionException.java
@@ -0,0 +1,27 @@
+/*
+ * Copyright 2021 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.server.nearby.common.bluetooth.fastpair;
+
+/**
+ * An exception thrown during a reflection operation. Like ReflectiveOperationException, except
+ * compatible on older API versions.
+ */
+public final class ReflectionException extends Exception {
+ ReflectionException(Throwable cause) {
+ super(cause.getMessage(), cause);
+ }
+}
diff --git a/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/TimingLogger.java b/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/TimingLogger.java
new file mode 100644
index 0000000..83ee309
--- /dev/null
+++ b/nearby/service/java/com/android/server/nearby/common/bluetooth/fastpair/TimingLogger.java
@@ -0,0 +1,237 @@
+/*
+ * Copyright 2021 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.server.nearby.common.bluetooth.fastpair;
+
+import android.os.SystemClock;
+import android.util.Log;
+
+import androidx.annotation.VisibleForTesting;
+
+import java.util.ArrayDeque;
+import java.util.List;
+import java.util.concurrent.CopyOnWriteArrayList;
+
+/**
+ * A profiler for performance metrics.
+ *
+ * <p>This class aim to break down the execution time for each steps of process to figure out the
+ * bottleneck.
+ */
+public class TimingLogger {
+
+ private static final String TAG = TimingLogger.class.getSimpleName();
+
+ /**
+ * The name of this session.
+ */
+ private final String mName;
+
+ private final Preferences mPreference;
+
+ /**
+ * The ordered timing sequence data. It's composed by a paired {@link Timing} generated from
+ * {@link #start} and {@link #end}.
+ */
+ private final List<Timing> mTimings;
+
+ private final long mStartTimestampMs;
+
+ /** Constructor. */
+ public TimingLogger(String name, Preferences mPreference) {
+ this.mName = name;
+ this.mPreference = mPreference;
+ mTimings = new CopyOnWriteArrayList<>();
+ mStartTimestampMs = SystemClock.elapsedRealtime();
+ }
+
+ @VisibleForTesting
+ List<Timing> getTimings() {
+ return mTimings;
+ }
+
+ /**
+ * Start a new paired timing.
+ *
+ * @param label The split name of paired timing.
+ */
+ public void start(String label) {
+ if (mPreference.getEvaluatePerformance()) {
+ mTimings.add(new Timing(label));
+ }
+ }
+
+ /**
+ * End a paired timing.
+ */
+ public void end() {
+ if (mPreference.getEvaluatePerformance()) {
+ mTimings.add(new Timing(Timing.END_LABEL));
+ }
+ }
+
+ /**
+ * Print out the timing data.
+ */
+ public void dump() {
+ if (!mPreference.getEvaluatePerformance()) {
+ return;
+ }
+
+ calculateTiming();
+ Log.i(TAG, mName + "[Exclusive time] / [Total time] ([Timestamp])");
+ int indentCount = 0;
+ for (Timing timing : mTimings) {
+ if (timing.isEndTiming()) {
+ indentCount--;
+ continue;
+ }
+ indentCount++;
+ if (timing.mExclusiveTime == timing.mTotalTime) {
+ Log.i(TAG, getIndentString(indentCount) + timing.mName + " " + timing.mExclusiveTime
+ + "ms (" + getRelativeTimestamp(timing.getTimestamp()) + ")");
+ } else {
+ Log.i(TAG, getIndentString(indentCount) + timing.mName + " " + timing.mExclusiveTime
+ + "ms / " + timing.mTotalTime + "ms (" + getRelativeTimestamp(
+ timing.getTimestamp()) + ")");
+ }
+ }
+ Log.i(TAG, mName + "end, " + getTotalTime() + "ms");
+ }
+
+ private void calculateTiming() {
+ ArrayDeque<Timing> arrayDeque = new ArrayDeque<>();
+ for (Timing timing : mTimings) {
+ if (timing.isStartTiming()) {
+ arrayDeque.addFirst(timing);
+ continue;
+ }
+
+ Timing timingStart = arrayDeque.removeFirst();
+ final long time = timing.mTimestamp - timingStart.mTimestamp;
+ timingStart.mExclusiveTime += time;
+ timingStart.mTotalTime += time;
+ if (!arrayDeque.isEmpty()) {
+ arrayDeque.peekFirst().mExclusiveTime -= time;
+ }
+ }
+ }
+
+ private String getIndentString(int indentCount) {
+ StringBuilder sb = new StringBuilder();
+ for (int i = 0; i < indentCount; i++) {
+ sb.append(" ");
+ }
+ return sb.toString();
+ }
+
+ private long getRelativeTimestamp(long timestamp) {
+ return timestamp - mTimings.get(0).mTimestamp;
+ }
+
+ @VisibleForTesting
+ long getTotalTime() {
+ return mTimings.get(mTimings.size() - 1).mTimestamp - mTimings.get(0).mTimestamp;
+ }
+
+ /**
+ * Gets the current latency since this object was created.
+ */
+ public long getLatencyMs() {
+ return SystemClock.elapsedRealtime() - mStartTimestampMs;
+ }
+
+ @VisibleForTesting
+ static class Timing {
+
+ private static final String END_LABEL = "END_LABEL";
+
+ /**
+ * The name of this paired timing.
+ */
+ private final String mName;
+
+ /**
+ * System uptime in millisecond.
+ */
+ private final long mTimestamp;
+
+ /**
+ * The execution time exclude inner split timings.
+ */
+ private long mExclusiveTime;
+
+ /**
+ * The execution time within a start and an end timing.
+ */
+ private long mTotalTime;
+
+ private Timing(String name) {
+ this.mName = name;
+ mTimestamp = SystemClock.elapsedRealtime();
+ mExclusiveTime = 0;
+ mTotalTime = 0;
+ }
+
+ @VisibleForTesting
+ String getName() {
+ return mName;
+ }
+
+ @VisibleForTesting
+ long getTimestamp() {
+ return mTimestamp;
+ }
+
+ @VisibleForTesting
+ long getExclusiveTime() {
+ return mExclusiveTime;
+ }
+
+ @VisibleForTesting
+ long getTotalTime() {
+ return mTotalTime;
+ }
+
+ @VisibleForTesting
+ boolean isStartTiming() {
+ return !isEndTiming();
+ }
+
+ @VisibleForTesting
+ boolean isEndTiming() {
+ return END_LABEL.equals(mName);
+ }
+ }
+
+ /**
+ * This class ensures each split timing is paired with a start and an end timing.
+ */
+ public static class ScopedTiming implements AutoCloseable {
+
+ private final TimingLogger mTimingLogger;
+
+ public ScopedTiming(TimingLogger logger, String label) {
+ mTimingLogger = logger;
+ mTimingLogger.start(label);
+ }
+
+ @Override
+ public void close() {
+ mTimingLogger.end();
+ }
+ }
+}
diff --git a/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/EventTest.java b/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/EventTest.java
index e2f42ee..d0c36ce 100644
--- a/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/EventTest.java
+++ b/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/EventTest.java
@@ -32,7 +32,7 @@
import org.junit.runner.RunWith;
/**
- * Unit tests for {@link EventTest}.
+ * Unit tests for {@link Event}.
*/
@Presubmit
@SmallTest
diff --git a/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/TimingLoggerTest.java b/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/TimingLoggerTest.java
new file mode 100644
index 0000000..0146ab3
--- /dev/null
+++ b/nearby/tests/src/com/android/server/nearby/common/bluetooth/fastpair/TimingLoggerTest.java
@@ -0,0 +1,214 @@
+/*
+ * Copyright (C) 2021 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.server.nearby.common.bluetooth.fastpair;
+
+import static com.google.common.truth.Truth.assertThat;
+
+import android.os.SystemClock;
+import android.platform.test.annotations.Presubmit;
+
+import androidx.test.filters.SmallTest;
+import androidx.test.runner.AndroidJUnit4;
+
+import com.android.server.nearby.common.bluetooth.fastpair.TimingLogger.ScopedTiming;
+import com.android.server.nearby.common.bluetooth.fastpair.TimingLogger.Timing;
+
+import org.junit.Test;
+import org.junit.runner.RunWith;
+
+
+/**
+ * Unit tests for {@link TimingLogger}.
+ */
+@Presubmit
+@SmallTest
+@RunWith(AndroidJUnit4.class)
+public class TimingLoggerTest {
+
+ private final Preferences mPrefs = Preferences.builder().setEvaluatePerformance(true).build();
+
+ @Test
+ public void logPairedTiming() {
+ String label = "start";
+ TimingLogger timingLogger = new TimingLogger("paired", mPrefs);
+ timingLogger.start(label);
+ SystemClock.sleep(1000);
+ timingLogger.end();
+
+ assertThat(timingLogger.getTimings()).hasSize(2);
+
+ // Calculate execution time and only store result at "start" timing.
+ // Expected output:
+ // <pre>
+ // I/FastPair: paired [Exclusive time] / [Total time]
+ // I/FastPair: start 1000ms
+ // I/FastPair: paired end, 1000ms
+ // </pre>
+ timingLogger.dump();
+
+ assertPairedTiming(label, timingLogger.getTimings().get(0),
+ timingLogger.getTimings().get(1));
+ }
+
+ @Test
+ public void logScopedTiming() {
+ String label = "scopedTiming";
+ TimingLogger timingLogger = new TimingLogger("scoped", mPrefs);
+ try (ScopedTiming scopedTiming = new ScopedTiming(timingLogger, label)) {
+ SystemClock.sleep(1000);
+ }
+
+ assertThat(timingLogger.getTimings()).hasSize(2);
+
+ // Calculate execution time and only store result at "start" timings.
+ // Expected output:
+ // <pre>
+ // I/FastPair: scoped [Exclusive time] / [Total time]
+ // I/FastPair: scopedTiming 1000ms
+ // I/FastPair: scoped end, 1000ms
+ // </pre>
+ timingLogger.dump();
+
+ assertPairedTiming(label, timingLogger.getTimings().get(0),
+ timingLogger.getTimings().get(1));
+ }
+
+ @Test
+ public void logOrderedTiming() {
+ String label1 = "t1";
+ String label2 = "t2";
+ TimingLogger timingLogger = new TimingLogger("ordered", mPrefs);
+ try (ScopedTiming t1 = new ScopedTiming(timingLogger, label1)) {
+ SystemClock.sleep(1000);
+ }
+ try (ScopedTiming t2 = new ScopedTiming(timingLogger, label2)) {
+ SystemClock.sleep(1000);
+ }
+
+ assertThat(timingLogger.getTimings()).hasSize(4);
+
+ // Calculate execution time and only store result at "start" timings.
+ // Expected output:
+ // <pre>
+ // I/FastPair: ordered [Exclusive time] / [Total time]
+ // I/FastPair: t1 1000ms
+ // I/FastPair: t2 1000ms
+ // I/FastPair: ordered end, 2000ms
+ // </pre>
+ timingLogger.dump();
+
+ // We expect get timings in this order: t1 start, t1 end, t2 start, t2 end.
+ Timing start1 = timingLogger.getTimings().get(0);
+ Timing end1 = timingLogger.getTimings().get(1);
+ Timing start2 = timingLogger.getTimings().get(2);
+ Timing end2 = timingLogger.getTimings().get(3);
+
+ // Verify the paired timings.
+ assertPairedTiming(label1, start1, end1);
+ assertPairedTiming(label2, start2, end2);
+
+ // Verify the order and total time.
+ assertOrderedTiming(start1, start2);
+ assertThat(start1.getExclusiveTime() + start2.getExclusiveTime())
+ .isEqualTo(timingLogger.getTotalTime());
+ }
+
+ @Test
+ public void logNestedTiming() {
+ String labelOuter = "outer";
+ String labelInner1 = "inner1";
+ String labelInner1Inner1 = "inner1inner1";
+ String labelInner2 = "inner2";
+ TimingLogger timingLogger = new TimingLogger("nested", mPrefs);
+ try (ScopedTiming outer = new ScopedTiming(timingLogger, labelOuter)) {
+ SystemClock.sleep(1000);
+ try (ScopedTiming inner1 = new ScopedTiming(timingLogger, labelInner1)) {
+ SystemClock.sleep(1000);
+ try (ScopedTiming inner1inner1 = new ScopedTiming(timingLogger,
+ labelInner1Inner1)) {
+ SystemClock.sleep(1000);
+ }
+ }
+ try (ScopedTiming inner2 = new ScopedTiming(timingLogger, labelInner2)) {
+ SystemClock.sleep(1000);
+ }
+ }
+
+ assertThat(timingLogger.getTimings()).hasSize(8);
+
+ // Calculate execution time and only store result at "start" timing.
+ // Expected output:
+ // <pre>
+ // I/FastPair: nested [Exclusive time] / [Total time]
+ // I/FastPair: outer 1000ms / 4000ms
+ // I/FastPair: inner1 1000ms / 2000ms
+ // I/FastPair: inner1inner1 1000ms
+ // I/FastPair: inner2 1000ms
+ // I/FastPair: nested end, 4000ms
+ // </pre>
+ timingLogger.dump();
+
+ // We expect get timings in this order: outer start, inner1 start, inner1inner1 start,
+ // inner1inner1 end, inner1 end, inner2 start, inner2 end, outer end.
+ Timing startOuter = timingLogger.getTimings().get(0);
+ Timing startInner1 = timingLogger.getTimings().get(1);
+ Timing startInner1Inner1 = timingLogger.getTimings().get(2);
+ Timing endInner1Inner1 = timingLogger.getTimings().get(3);
+ Timing endInner1 = timingLogger.getTimings().get(4);
+ Timing startInner2 = timingLogger.getTimings().get(5);
+ Timing endInner2 = timingLogger.getTimings().get(6);
+ Timing endOuter = timingLogger.getTimings().get(7);
+
+ // Verify the paired timings.
+ assertPairedTiming(labelOuter, startOuter, endOuter);
+ assertPairedTiming(labelInner1, startInner1, endInner1);
+ assertPairedTiming(labelInner1Inner1, startInner1Inner1, endInner1Inner1);
+ assertPairedTiming(labelInner2, startInner2, endInner2);
+
+ // Verify the order and total time.
+ assertOrderedTiming(startOuter, startInner1);
+ assertOrderedTiming(startInner1, startInner1Inner1);
+ assertOrderedTiming(startInner1Inner1, startInner2);
+ assertThat(
+ startOuter.getExclusiveTime() + startInner1.getTotalTime() + startInner2
+ .getTotalTime())
+ .isEqualTo(timingLogger.getTotalTime());
+
+ // Verify the nested execution time.
+ assertThat(startInner1Inner1.getTotalTime()).isAtMost(startInner1.getTotalTime());
+ assertThat(startInner1.getTotalTime() + startInner2.getTotalTime())
+ .isAtMost(startOuter.getTotalTime());
+ }
+
+ private void assertPairedTiming(String label, Timing start, Timing end) {
+ assertThat(start.isStartTiming()).isTrue();
+ assertThat(start.getName()).isEqualTo(label);
+ assertThat(end.isEndTiming()).isTrue();
+ assertThat(end.getTimestamp()).isAtLeast(start.getTimestamp());
+
+ assertThat(start.getExclusiveTime() > 0).isTrue();
+ assertThat(start.getTotalTime()).isAtLeast(start.getExclusiveTime());
+ assertThat(end.getExclusiveTime() == 0).isTrue();
+ assertThat(end.getTotalTime() == 0).isTrue();
+ }
+
+ private void assertOrderedTiming(Timing t1, Timing t2) {
+ assertThat(t1.isStartTiming()).isTrue();
+ assertThat(t2.isStartTiming()).isTrue();
+ assertThat(t2.getTimestamp()).isAtLeast(t1.getTimestamp());
+ }
+}