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

CHANGELOG.md

@@ -34,6 +34,10 @@
 - Sentry can now configure Log4j2 automatically for Spring Boot 3 when `sentry-log4j2` is on the classpath and Log4j2 Core is the active logging backend ([#6072](https://github.com/getsentry/sentry-java/pull/6072))
   - Disabled by default for now; enable it and configure levels the same way as described in the Spring Boot 4 entry above (`sentry.logging.enabled=true`)
 
+### Internal
+
+- Measure ANR detection and ANR profiling durations on the internal `MonotonicTicker` ([#6041](https://github.com/getsentry/sentry-java/pull/6041))
+
 ## 8.56.0
 
 ### Behavioral Changes

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

@@ -30,60 +30,60 @@
 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.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.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;
 
   @SuppressWarnings("UnnecessaryLambda")
   private final Runnable ticker;
 
-  ANRWatchDog(
-      long timeoutIntervalMillis,
-      boolean reportInDebug,
-      @NotNull ANRListener listener,
-      @NotNull ILogger logger,
+  /** Reads the timeout, the debug behavior, the logger and the ticker off {@code options}. */
+  static @NotNull ANRWatchDog create(
+      final @NotNull SentryAndroidOptions options,
+      final @NotNull ANRListener listener,
       final @NotNull Context context) {
-    // avoid method refs on Android due to some issues with older AGP setups
-    // noinspection Convert2MethodRef
-    this(
-        () -> SystemClock.uptimeMillis(),
-        timeoutIntervalMillis,
-        500,
-        reportInDebug,
+    return new ANRWatchDog(
+        options.getMonotonicTicker(),
+        options.getAnrTimeoutIntervalMillis(),
+        DEFAULT_POLLING_INTERVAL_MS,
+        options.isAnrReportInDebug(),
         listener,
-        logger,
+        options.getLogger(),
         new MainLooperHandler(),
         context);
   }
 
-  @TestOnly
   ANRWatchDog(
-      @NotNull final ICurrentDateProvider timeProvider,
+      @NotNull final MonotonicTicker monotonicTicker,
       long timeoutIntervalMillis,
       long pollingIntervalMillis,
       boolean reportInDebug,
@@ -94,17 +94,20 @@ final class ANRWatchDog extends Thread {
 
     super("|ANR-WatchDog|");
 
-    this.timeProvider = timeProvider;
+    this.monotonicTicker = monotonicTicker;
     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(monotonicTicker, timeoutIntervalMillis, TimeUnit.MILLISECONDS);
     this.ticker =
         () -> {
-          lastKnownActiveUiTimestampMs = timeProvider.getCurrentTimeMillis();
+          uiResponsiveUntil =
+              Deadline.after(monotonicTicker, 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/AnrIntegration.java

@@ -95,12 +95,7 @@ private void startAnrWatchdog(
                 options.getAnrTimeoutIntervalMillis());
 
         anrWatchDog =
-            new ANRWatchDog(
-                options.getAnrTimeoutIntervalMillis(),
-                options.isAnrReportInDebug(),
-                error -> reportANR(scopes, options, error),
-                options.getLogger(),
-                context);
+            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.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.time.MonotonicTicker;
+import io.sentry.time.MonotonicTickerProvider;
+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,23 @@ 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;
+
+  @SuppressWarnings("UnnecessaryLambda")
+  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;
@@ -60,13 +74,27 @@ public class AnrProfilingIntegration
   private volatile @Nullable Handler mainHandler;
   private volatile @Nullable Thread mainThread;
 
+  /**
+   * Installs the ticker to measure main-thread stalls with. Also resets the last-execution reading,
+   * so a stall is never measured against a tick from a different ticker.
+   *
+   * <p>Package-private so a test can install a fake ticker after {@link #register}, which {@code
+   * SentryAndroidOptions} cannot supply.
+   */
+  void installTickerFrom(final @NotNull MonotonicTickerProvider provider) {
+    final @NotNull MonotonicTicker installedTicker = provider.getMonotonicTicker();
+    this.ticker = installedTicker;
+    this.lastMainThreadExecutionNanos = installedTicker.tickNanos();
+  }
+
   @Override
   public void register(final @NotNull IScopes scopes, final @NotNull SentryOptions options) {
     this.options =
         Objects.requireNonNull(
             (options instanceof SentryAndroidOptions) ? (SentryAndroidOptions) options : null,
             "SentryAndroidOptions is required");
     this.logger = options.getLogger();
+    installTickerFrom(options);
 
     if (this.options.isAnrProfilingEnabled()) {
       if (this.options.getCacheDirPath() == null) {
@@ -211,8 +239,12 @@ 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 @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;
@@ -241,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
@@ -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(ticker, 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
+        ticker.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(ticker, interval, 1L, true, { a -> anr = a }, mock(), handler, mock())
     val es = Executors.newSingleThreadExecutor()
     try {
       es.submit { sut.run() }
 
       var waitCount = 0
       do {
-        currentTimeMs += 100L
+        ticker.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(ticker, 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
+        ticker.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(ticker, 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
+        ticker.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(ticker, 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()
+    }
+  }
 }