ref(android): Measure ANR thresholds on the monotonic clock (JAVA-579)

CHANGELOG.md

@@ -16,6 +16,7 @@
 - Add an internal `MonotonicClock` abstraction with `Deadline` and `Stopwatch` primitives ([#6028](https://github.com/getsentry/sentry-java/pull/6028))
 - Add internal `Timestamp`, `Timing` and `EpochClock`, separating a serialized wall-clock instant from a monotonically measured duration ([#6045](https://github.com/getsentry/sentry-java/pull/6045))
 - Deprecate `RateLimiter(ICurrentDateProvider, SentryOptions)` in favour of `RateLimiter(MonotonicClock, RateLimiterConfig)` ([#6030](https://github.com/getsentry/sentry-java/pull/6030))
+- Measure ANR detection thresholds on the internal `MonotonicClock`, so the clock is named by the type instead of chosen at each call site ([#6041](https://github.com/getsentry/sentry-java/pull/6041))
 
 ## 8.55.0
 

sentry-android-core/src/main/java/io/sentry/android/core/ANRWatchDog.java

@@ -30,11 +30,13 @@
 import android.app.ActivityManager;
 import android.content.Context;
 import android.os.Debug;
-import android.os.SystemClock;
 import io.sentry.ILogger;
 import io.sentry.SentryLevel;
-import io.sentry.transport.ICurrentDateProvider;
+import io.sentry.android.core.internal.time.AndroidMonotonicClock;
+import io.sentry.time.Deadline;
+import io.sentry.time.MonotonicClock;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.TestOnly;
@@ -46,15 +48,17 @@ final class ANRWatchDog extends Thread {
   private final boolean reportInDebug;
   private final ANRListener anrListener;
   private final MainLooperHandler uiHandler;
-  private final ICurrentDateProvider timeProvider;
+  private final MonotonicClock clock;
 
   /** the interval in which we check if there's an ANR, in ms */
   private long pollingIntervalMs;
 
   private final long timeoutIntervalMillis;
   private final @NotNull ILogger logger;
 
-  private volatile long lastKnownActiveUiTimestampMs = 0;
+  /** How long the main thread has left to run the ticker before we call it an ANR. */
+  private volatile @NotNull Deadline uiResponsiveUntil;
+
   private final AtomicBoolean reported = new AtomicBoolean(false);
 
   private final @NotNull Context context;
@@ -68,10 +72,8 @@ final class ANRWatchDog extends Thread {
       @NotNull ANRListener listener,
       @NotNull ILogger logger,
       final @NotNull Context context) {
-    // avoid method refs on Android due to some issues with older AGP setups
-    // noinspection Convert2MethodRef
     this(
-        () -> SystemClock.uptimeMillis(),
+        AndroidMonotonicClock.getInstance(),
         timeoutIntervalMillis,
         500,
         reportInDebug,
@@ -83,7 +85,7 @@ final class ANRWatchDog extends Thread {
 
   @TestOnly
   ANRWatchDog(
-      @NotNull final ICurrentDateProvider timeProvider,
+      @NotNull final MonotonicClock clock,
       long timeoutIntervalMillis,
       long pollingIntervalMillis,
       boolean reportInDebug,
@@ -94,17 +96,18 @@ final class ANRWatchDog extends Thread {
 
     super("|ANR-WatchDog|");
 
-    this.timeProvider = timeProvider;
+    this.clock = clock;
     this.timeoutIntervalMillis = timeoutIntervalMillis;
     this.pollingIntervalMs = pollingIntervalMillis;
     this.reportInDebug = reportInDebug;
     this.anrListener = listener;
     this.logger = logger;
     this.uiHandler = uiHandler;
     this.context = context;
+    this.uiResponsiveUntil = Deadline.after(clock, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
     this.ticker =
         () -> {
-          lastKnownActiveUiTimestampMs = timeProvider.getCurrentTimeMillis();
+          uiResponsiveUntil = Deadline.after(clock, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
           reported.set(false);
         };
 
@@ -140,11 +143,8 @@ public void run() {
         return;
       }
 
-      final long unresponsiveDurationMs =
-          timeProvider.getCurrentTimeMillis() - lastKnownActiveUiTimestampMs;
-
       // If the main thread has not handled ticker, it is blocked. ANR.
-      if (unresponsiveDurationMs > timeoutIntervalMillis) {
+      if (uiResponsiveUntil.hasPassed()) {
         if (!reportInDebug && (Debug.isDebuggerConnected() || Debug.waitingForDebugger())) {
           logger.log(
               SentryLevel.DEBUG,

sentry-android-core/src/main/java/io/sentry/android/core/anr/AnrProfilingIntegration.java

@@ -4,7 +4,6 @@
 
 import android.os.Handler;
 import android.os.Looper;
-import android.os.SystemClock;
 import io.sentry.ILogger;
 import io.sentry.IScopes;
 import io.sentry.ISentryLifecycleToken;
@@ -14,12 +13,16 @@
 import io.sentry.SentryOptions;
 import io.sentry.android.core.AppState;
 import io.sentry.android.core.SentryAndroidOptions;
+import io.sentry.android.core.internal.time.AndroidMonotonicClock;
+import io.sentry.time.MonotonicClock;
+import io.sentry.time.Stopwatch;
 import io.sentry.util.AutoClosableReentrantLock;
 import io.sentry.util.Objects;
 import io.sentry.util.SentryRandom;
 import java.io.Closeable;
 import java.io.File;
 import java.io.IOException;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
 import org.jetbrains.annotations.ApiStatus;
@@ -43,12 +46,13 @@ public class AnrProfilingIntegration
   static final int MAX_NUM_STACKS = (int) (10_000 / POLLING_INTERVAL_MS);
 
   private final AtomicBoolean enabled = new AtomicBoolean(true);
-  private final Runnable updater = () -> lastMainThreadExecutionTime = SystemClock.uptimeMillis();
+  private final @NotNull MonotonicClock clock;
+  private final @NotNull Runnable updater;
   private final @NotNull AutoClosableReentrantLock lifecycleLock = new AutoClosableReentrantLock();
   private final @NotNull AutoClosableReentrantLock profileManagerLock =
       new AutoClosableReentrantLock();
 
-  private volatile long lastMainThreadExecutionTime = SystemClock.uptimeMillis();
+  private volatile long lastMainThreadExecutionNanos;
   final AtomicInteger numCollectedStacks = new AtomicInteger();
   private volatile MainThreadState mainThreadState = MainThreadState.IDLE;
   private volatile @Nullable AnrProfileManager profileManager;
@@ -60,6 +64,17 @@ public class AnrProfilingIntegration
   private volatile @Nullable Handler mainHandler;
   private volatile @Nullable Thread mainThread;
 
+  public AnrProfilingIntegration() {
+    this(AndroidMonotonicClock.getInstance());
+  }
+
+  @TestOnly
+  AnrProfilingIntegration(final @NotNull MonotonicClock clock) {
+    this.clock = clock;
+    this.lastMainThreadExecutionNanos = clock.tickNanos();
+    this.updater = () -> lastMainThreadExecutionNanos = clock.tickNanos();
+  }
+
   @Override
   public void register(final @NotNull IScopes scopes, final @NotNull SentryOptions options) {
     this.options =
@@ -211,8 +226,8 @@ public void run() {
 
   @ApiStatus.Internal
   protected void checkMainThread(final @NotNull Thread mainThread) throws IOException {
-    final long now = SystemClock.uptimeMillis();
-    final long diff = now - lastMainThreadExecutionTime;
+    final long diff =
+        TimeUnit.NANOSECONDS.toMillis(clock.tickNanos() - lastMainThreadExecutionNanos);
 
     if (diff < THRESHOLD_SUSPICION_MS) {
       mainThreadState = MainThreadState.IDLE;
@@ -241,14 +256,15 @@ protected void checkMainThread(final @NotNull Thread mainThread) throws IOExcept
         && (mainThreadState == MainThreadState.SUSPICIOUS
             || mainThreadState == MainThreadState.ANR_DETECTED)) {
       if (numCollectedStacks.get() < MAX_NUM_STACKS) {
-        final long start = SystemClock.uptimeMillis();
+        final @NotNull Stopwatch stopwatch = Stopwatch.started(clock);
         final @NotNull AnrStackTrace trace =
             new AnrStackTrace(System.currentTimeMillis(), mainThread.getStackTrace());
-        final long duration = SystemClock.uptimeMillis() - start;
         if (logger.isEnabled(SentryLevel.DEBUG)) {
           logger.log(
               SentryLevel.DEBUG,
-              "AnrWatchdog: capturing main thread stacktrace took " + duration + "ms");
+              "AnrWatchdog: capturing main thread stacktrace took "
+                  + stopwatch.elapsed(TimeUnit.MILLISECONDS)
+                  + "ms");
         }
         addStackTrace(trace);
       } else {

sentry-android-core/src/test/java/io/sentry/android/core/ANRWatchDogTest.kt

@@ -4,10 +4,11 @@ import android.app.ActivityManager
 import android.app.ActivityManager.ProcessErrorStateInfo.NOT_RESPONDING
 import android.app.ActivityManager.ProcessErrorStateInfo.NO_ERROR
 import android.content.Context
-import io.sentry.transport.ICurrentDateProvider
+import io.sentry.time.TestMonotonicClock
 import java.util.concurrent.CountDownLatch
 import java.util.concurrent.Executors
 import java.util.concurrent.TimeUnit
+import java.util.concurrent.TimeUnit.MILLISECONDS
 import kotlin.test.Test
 import kotlin.test.assertEquals
 import kotlin.test.assertNotNull
@@ -20,12 +21,12 @@ import org.mockito.kotlin.mock
 import org.mockito.kotlin.whenever
 
 class ANRWatchDogTest {
-  private var currentTimeMs = 0L
-  private val timeProvider = ICurrentDateProvider { currentTimeMs }
+  private lateinit var clock: TestMonotonicClock
 
   @Before
   fun `setup`() {
-    currentTimeMs = 12341234
+    // an arbitrary, non-zero origin: no caller may assume a tick counts from zero
+    clock = TestMonotonicClock(MILLISECONDS.toNanos(12341234))
   }
 
   @Test
@@ -42,8 +43,7 @@ class ANRWatchDogTest {
     whenever(handler.thread).thenReturn(thread)
     val interval = 10L
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
@@ -53,7 +53,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
 
@@ -79,15 +79,14 @@ class ANRWatchDogTest {
     whenever(handler.thread).thenReturn(thread)
     val interval = 10L
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
 
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize his runner always runs
       } while (!invoked && waitCount++ < 100)
 
@@ -121,8 +120,7 @@ class ANRWatchDogTest {
     val anrs = listOf(stateInfo)
     whenever(am.processesInErrorState).thenReturn(anrs)
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
@@ -132,7 +130,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
 
@@ -167,8 +165,7 @@ class ANRWatchDogTest {
     val anrs = listOf(stateInfo)
     whenever(am.processesInErrorState).thenReturn(anrs)
 
-    val sut =
-      ANRWatchDog(timeProvider, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
+    val sut = ANRWatchDog(clock, interval, 1L, true, { a -> anr = a }, mock(), handler, context)
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
@@ -178,7 +175,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        clock.advance(100, MILLISECONDS)
         Thread.sleep(100L) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
       assertNull(anr) // callback never ran
@@ -187,4 +184,31 @@ class ANRWatchDogTest {
       es.shutdown()
     }
   }
+
+  @Test
+  fun `a device suspend does not trip the ANR threshold`() {
+    // The uptime clock stands still while the device is suspended, so a suspend cannot be mistaken
+    // for a blocked main thread. On an elapsed-real-time clock the suspended interval would count
+    // against the main thread and fabricate an ANR.
+    var anr: ApplicationNotResponding? = null
+    val handler = mock<MainLooperHandler>()
+    val latch = CountDownLatch(1)
+    whenever(handler.post(any())).then { latch.countDown() }
+    whenever(handler.thread).thenReturn(mock<Thread>())
+
+    // context is a mock, so ActivityManager is absent and any passed deadline reports an ANR
+    val sut = ANRWatchDog(clock, 10L, 1L, true, { a -> anr = a }, mock(), handler, mock())
+    val es = Executors.newSingleThreadExecutor()
+    try {
+      es.submit { sut.run() }
+
+      assertTrue(latch.await(10L, TimeUnit.SECONDS)) // wait until the watchdog is polling
+      Thread.sleep(200) // hundreds of polls of wall time, none of it uptime
+
+      assertNull(anr)
+    } finally {
+      sut.interrupt()
+      es.shutdown()
+    }
+  }
 }