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

CHANGELOG.md

@@ -61,6 +61,10 @@
   - [changelog](https://github.com/getsentry/sentry-native/blob/master/CHANGELOG.md#0176)
   - [diff](https://github.com/getsentry/sentry-native/compare/0.17.4...0.17.6)
 
+### Internal
+
+- Measure ANR detection and ANR profiling durations on the internal `MonotonicTicker` ([#6041](https://github.com/getsentry/sentry-java/pull/6041))
+
 ## 8.62.0
 
 ### Improvements

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

@@ -29,33 +29,37 @@
 
 import android.app.ActivityManager;
 import android.content.Context;
-import android.os.SystemClock;
 import io.sentry.IDebugManager;
 import io.sentry.ILogger;
 import io.sentry.SentryLevel;
-import io.sentry.transport.ICurrentDateProvider;
+import io.sentry.time.Deadline;
+import io.sentry.time.MonotonicTicker;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
-import org.jetbrains.annotations.TestOnly;
 
 /** A watchdog timer thread that detects when the UI thread has frozen. */
 @SuppressWarnings("UnusedReturnValue")
 final class ANRWatchDog extends Thread {
 
+  private static final long DEFAULT_POLLING_INTERVAL_MS = 500;
+
   private final boolean reportInDebug;
   private final ANRListener anrListener;
   private final MainLooperHandler uiHandler;
-  private final ICurrentDateProvider timeProvider;
+  private final MonotonicTicker monotonicTicker;
 
   /** 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;
@@ -64,30 +68,24 @@ final class ANRWatchDog extends Thread {
   @SuppressWarnings("UnnecessaryLambda")
   private final Runnable ticker;
 
-  ANRWatchDog(
-      long timeoutIntervalMillis,
-      boolean reportInDebug,
-      @NotNull ANRListener listener,
-      @NotNull ILogger logger,
-      final @NotNull Context context,
-      final @Nullable IDebugManager debugManager) {
-    // avoid method refs on Android due to some issues with older AGP setups
-    // noinspection Convert2MethodRef
-    this(
-        () -> SystemClock.uptimeMillis(),
-        timeoutIntervalMillis,
-        500,
-        reportInDebug,
+  static @NotNull ANRWatchDog create(
+      final @NotNull SentryAndroidOptions options,
+      final @NotNull ANRListener listener,
+      final @NotNull Context context) {
+    return new ANRWatchDog(
+        options.getMonotonicTicker(),
+        options.getAnrTimeoutIntervalMillis(),
+        DEFAULT_POLLING_INTERVAL_MS,
+        options.isAnrReportInDebug(),
         listener,
-        logger,
+        options.getLogger(),
         new MainLooperHandler(),
         context,
-        debugManager);
+        options.getDebugManager());
   }
 
-  @TestOnly
   ANRWatchDog(
-      @NotNull final ICurrentDateProvider timeProvider,
+      @NotNull final MonotonicTicker monotonicTicker,
       long timeoutIntervalMillis,
       long pollingIntervalMillis,
       boolean reportInDebug,
@@ -99,7 +97,7 @@ final class ANRWatchDog extends Thread {
 
     super("|ANR-WatchDog|");
 
-    this.timeProvider = timeProvider;
+    this.monotonicTicker = monotonicTicker;
     this.timeoutIntervalMillis = timeoutIntervalMillis;
     this.pollingIntervalMs = pollingIntervalMillis;
     this.reportInDebug = reportInDebug;
@@ -108,9 +106,12 @@ final class ANRWatchDog extends Thread {
     this.uiHandler = uiHandler;
     this.context = context;
     this.debugManager = debugManager;
+    this.uiResponsiveUntil =
+        Deadline.after(monotonicTicker, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
     this.ticker =
         () -> {
-          lastKnownActiveUiTimestampMs = timeProvider.getCurrentTimeMillis();
+          uiResponsiveUntil =
+              Deadline.after(monotonicTicker, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
           reported.set(false);
         };
 
@@ -146,11 +147,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 && debugManager != null && debugManager.isDebuggerConnected()) {
           logger.log(
               SentryLevel.DEBUG,

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

@@ -95,13 +95,7 @@ private void startAnrWatchdog(
                 options.getAnrTimeoutIntervalMillis());
 
         anrWatchDog =
-            new ANRWatchDog(
-                options.getAnrTimeoutIntervalMillis(),
-                options.isAnrReportInDebug(),
-                error -> reportANR(scopes, options, error),
-                options.getLogger(),
-                context,
-                options.getDebugManager());
+            ANRWatchDog.create(options, error -> reportANR(scopes, options, error), context);
         anrWatchDog.start();
 
         options.getLogger().log(SentryLevel.DEBUG, "AnrIntegration installed.");

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.IDebugManager;
 import io.sentry.ILogger;
 import io.sentry.IScopes;
@@ -15,12 +14,15 @@
 import io.sentry.SentryOptions;
 import io.sentry.android.core.AppState;
 import io.sentry.android.core.SentryAndroidOptions;
+import io.sentry.time.MonotonicTicker;
+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;
@@ -44,12 +46,22 @@ 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 volatile @Nullable MonotonicTicker ticker;
+
+  private final @NotNull Runnable updater =
+      () -> {
+        final @Nullable MonotonicTicker currentTicker = ticker;
+        if (currentTicker != null) {
+          lastMainThreadExecutionNanos = currentTicker.tickNanos();
+        }
+      };
+
   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;
@@ -69,6 +81,10 @@ public void register(final @NotNull IScopes scopes, final @NotNull SentryOptions
             (options instanceof SentryAndroidOptions) ? (SentryAndroidOptions) options : null,
             "SentryAndroidOptions is required");
     this.logger = options.getLogger();
+    final @NotNull MonotonicTicker ticker = options.getMonotonicTicker();
+    // A tick's origin is arbitrary, so the default of 0 would read as a stall of unknown length.
+    this.lastMainThreadExecutionNanos = ticker.tickNanos();
+    this.ticker = ticker;
     this.debugManager = this.options.getDebugManager();
 
     if (this.options.isAnrProfilingEnabled()) {
@@ -223,8 +239,12 @@ protected void checkMainThread(final @NotNull Thread mainThread) throws IOExcept
       return;
     }
 
-    final long now = SystemClock.uptimeMillis();
-    final long diff = now - lastMainThreadExecutionTime;
+    final @Nullable MonotonicTicker currentTicker = ticker;
+    if (currentTicker == null) {
+      return;
+    }
+    final long diff =
+        TimeUnit.NANOSECONDS.toMillis(currentTicker.tickNanos() - lastMainThreadExecutionNanos);
 
     if (diff < THRESHOLD_SUSPICION_MS) {
       mainThreadState = MainThreadState.IDLE;
@@ -253,14 +273,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(currentTicker);
         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.TestMonotonicTicker
 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 ticker: TestMonotonicTicker
 
   @Before
   fun `setup`() {
-    currentTimeMs = 12341234
+    // an arbitrary, non-zero origin: no caller may assume a tick counts from zero
+    ticker = TestMonotonicTicker(MILLISECONDS.toNanos(12341234))
   }
 
   @Test
@@ -44,7 +45,7 @@ class ANRWatchDogTest {
 
     val sut =
       ANRWatchDog(
-        timeProvider,
+        ticker,
         interval,
         1L,
         true,
@@ -63,7 +64,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        ticker.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
 
@@ -91,7 +92,7 @@ class ANRWatchDogTest {
 
     val sut =
       ANRWatchDog(
-        timeProvider,
+        ticker,
         interval,
         1L,
         true,
@@ -107,7 +108,7 @@ class ANRWatchDogTest {
 
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        ticker.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize his runner always runs
       } while (!invoked && waitCount++ < 100)
 
@@ -143,7 +144,7 @@ class ANRWatchDogTest {
 
     val sut =
       ANRWatchDog(
-        timeProvider,
+        ticker,
         interval,
         1L,
         true,
@@ -162,7 +163,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        ticker.advance(100, MILLISECONDS)
         Thread.sleep(100) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
 
@@ -199,7 +200,7 @@ class ANRWatchDogTest {
 
     val sut =
       ANRWatchDog(
-        timeProvider,
+        ticker,
         interval,
         1L,
         true,
@@ -218,7 +219,7 @@ class ANRWatchDogTest {
       ) // Wait until worker posts the job for the "UI thread"
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        ticker.advance(100, MILLISECONDS)
         Thread.sleep(100L) // Let worker realize this is ANR
       } while (anr == null && waitCount++ < 100)
       assertNull(anr) // callback never ran
@@ -227,4 +228,39 @@ class ANRWatchDogTest {
       es.shutdown()
     }
   }
+
+  @Test
+  fun `measures the ANR threshold on the ticker, not on wall time`() {
+    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(
+        ticker,
+        10L,
+        1L,
+        true,
+        { a -> anr = a },
+        mock(),
+        handler,
+        mock(),
+        AndroidDebugManager(),
+      )
+    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 while the ticker stands still
+
+      assertNull(anr)
+    } finally {
+      sut.interrupt()
+      es.shutdown()
+    }
+  }
 }