diff --git a/CHANGELOG.md b/CHANGELOG.md index c1c3c7416d0..cdecf72ceb8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,6 +30,10 @@ - [changelog](https://github.com/getsentry/sentry-native/blob/master/CHANGELOG.md#0175) - [diff](https://github.com/getsentry/sentry-native/compare/0.17.4...0.17.5) +### 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 diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/ANRWatchDog.java b/sentry-android-core/src/main/java/io/sentry/android/core/ANRWatchDog.java index c8f1bf5e361..6f8fedcecea 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/ANRWatchDog.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/ANRWatchDog.java @@ -29,25 +29,27 @@ 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; @@ -55,7 +57,9 @@ final class ANRWatchDog extends Thread { 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, diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AnrIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/AnrIntegration.java index b9fd0b781d8..275914e3fe2 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/AnrIntegration.java +++ b/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."); diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/anr/AnrProfilingIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/anr/AnrProfilingIntegration.java index bc41f3faf6a..d61b768475f 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/anr/AnrProfilingIntegration.java +++ b/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,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; @@ -62,6 +75,18 @@ 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. + * + *

Package-private so a test can install a fake ticker after {@link #register}, which {@code + * SentryAndroidOptions} cannot supply. + */ + void installTicker(final @NotNull MonotonicTicker ticker) { + this.ticker = ticker; + this.lastMainThreadExecutionNanos = ticker.tickNanos(); + } + @Override public void register(final @NotNull IScopes scopes, final @NotNull SentryOptions options) { this.options = @@ -69,6 +94,7 @@ public void register(final @NotNull IScopes scopes, final @NotNull SentryOptions (options instanceof SentryAndroidOptions) ? (SentryAndroidOptions) options : null, "SentryAndroidOptions is required"); this.logger = options.getLogger(); + installTicker(options.getMonotonicTicker()); this.debugManager = this.options.getDebugManager(); if (this.options.isAnrProfilingEnabled()) { @@ -223,8 +249,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 +283,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 { diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/ANRWatchDogTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/ANRWatchDogTest.kt index 02522f725f1..71f477b24a1 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/ANRWatchDogTest.kt +++ b/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() + val latch = CountDownLatch(1) + whenever(handler.post(any())).then { latch.countDown() } + whenever(handler.thread).thenReturn(mock()) + + // 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() + } + } } diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/anr/AnrProfilingIntegrationTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/anr/AnrProfilingIntegrationTest.kt index 6d78a8f70c8..7747a8a2a1c 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/anr/AnrProfilingIntegrationTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/anr/AnrProfilingIntegrationTest.kt @@ -1,7 +1,7 @@ package io.sentry.android.core.anr -import android.os.SystemClock import androidx.test.ext.junit.runners.AndroidJUnit4 +import com.google.common.truth.Truth.assertThat import io.sentry.ILogger import io.sentry.IScopes import io.sentry.SentryIntegrationPackageStorage @@ -9,6 +9,9 @@ import io.sentry.SentryOptions import io.sentry.android.core.AppState import io.sentry.android.core.SentryAndroidOptions import io.sentry.test.getProperty +import io.sentry.time.TestMonotonicTicker +import java.util.concurrent.TimeUnit.HOURS +import java.util.concurrent.TimeUnit.MILLISECONDS import kotlin.test.AfterTest import kotlin.test.BeforeTest import kotlin.test.Test @@ -30,9 +33,13 @@ class AnrProfilingIntegrationTest { private lateinit var mockScopes: IScopes private lateinit var mockLogger: ILogger private lateinit var options: SentryAndroidOptions + private lateinit var ticker: TestMonotonicTicker @BeforeTest fun setup() { + // A tick origin far from zero, as on any device that has been up a while. Starting at zero + // would let a reading taken against a different origin pass unnoticed. + ticker = TestMonotonicTicker(HOURS.toNanos(30)) mockScopes = mock() mockLogger = mock() options = @@ -163,7 +170,6 @@ class AnrProfilingIntegrationTest { @Test fun `properly walks through state transitions and collects stack traces`() { val mainThread = Thread.currentThread() - SystemClock.setCurrentTimeMillis(1_00) val androidOptions = SentryAndroidOptions().apply { @@ -174,18 +180,19 @@ class AnrProfilingIntegrationTest { val integration = AnrProfilingIntegration() integration.register(mockScopes, androidOptions) + integration.installTicker(ticker) // Drive the state machine synchronously to avoid racing the background polling thread. - SystemClock.setCurrentTimeMillis(1_000) + ticker.advance(900, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.IDLE, integration.state) assertTrue(integration.profileManager.load().stacks.isEmpty()) - SystemClock.setCurrentTimeMillis(3_000) + ticker.advance(2_000, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.SUSPICIOUS, integration.state) - SystemClock.setCurrentTimeMillis(6_000) + ticker.advance(3_000, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.ANR_DETECTED, integration.state) assertEquals(2, integration.profileManager.load().stacks.size) @@ -199,7 +206,6 @@ class AnrProfilingIntegrationTest { @Test fun `debugger pauses are treated as idle`() { val mainThread = Thread.currentThread() - SystemClock.setCurrentTimeMillis(1_000) var debuggerConnected = true val androidOptions = @@ -212,15 +218,16 @@ class AnrProfilingIntegrationTest { val integration = AnrProfilingIntegration() integration.register(mockScopes, androidOptions) + integration.installTicker(ticker) - SystemClock.setCurrentTimeMillis(20_000) + ticker.advance(19_000, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.IDLE, integration.state) assertEquals(0, integration.numCollectedStacks.get()) // the time spent paused must not count towards an ANR once the debugger detaches debuggerConnected = false - SystemClock.setCurrentTimeMillis(20_100) + ticker.advance(100, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.IDLE, integration.state) } @@ -228,7 +235,6 @@ class AnrProfilingIntegrationTest { @Test fun `background foreground transitions don't trigger an ANR`() { val mainThread = Thread.currentThread() - SystemClock.setCurrentTimeMillis(1_000) val androidOptions = SentryAndroidOptions().apply { @@ -239,9 +245,10 @@ class AnrProfilingIntegrationTest { val integration = AnrProfilingIntegration() integration.register(mockScopes, androidOptions) + integration.installTicker(ticker) integration.onBackground() - SystemClock.setCurrentTimeMillis(20_000) + ticker.advance(19_000, MILLISECONDS) integration.onForeground() Thread.sleep(100) @@ -249,6 +256,18 @@ class AnrProfilingIntegrationTest { assertEquals(AnrProfilingIntegration.MainThreadState.IDLE, integration.state) } + @Test + fun `does not report a stall when the ticker origin is far from zero`() { + val integration = AnrProfilingIntegration() + integration.register(mockScopes, options) + integration.installTicker(ticker) + + integration.checkMainThread(Thread.currentThread()) + + assertThat(integration.state).isEqualTo(AnrProfilingIntegration.MainThreadState.IDLE) + assertThat(integration.profileManager.load().stacks).isEmpty() + } + @Test fun `does not register when options is not SentryAndroidOptions`() { val plainOptions = @@ -295,7 +314,6 @@ class AnrProfilingIntegrationTest { @Test fun `does not collect stacks when sample rate is zero`() { val mainThread = Thread.currentThread() - SystemClock.setCurrentTimeMillis(1_00) val androidOptions = SentryAndroidOptions().apply { @@ -306,15 +324,16 @@ class AnrProfilingIntegrationTest { val integration = AnrProfilingIntegration() integration.register(mockScopes, androidOptions) + integration.installTicker(ticker) integration.onForeground() // Transition to suspicious - SystemClock.setCurrentTimeMillis(3_000) + ticker.advance(2_900, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.SUSPICIOUS, integration.state) // Transition to ANR - SystemClock.setCurrentTimeMillis(6_000) + ticker.advance(3_000, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.ANR_DETECTED, integration.state) diff --git a/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicTicker.kt b/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicTicker.kt index 2471a1bc8dd..31944ec22cb 100644 --- a/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicTicker.kt +++ b/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicTicker.kt @@ -8,8 +8,11 @@ import java.util.concurrent.TimeUnit * Advancing by an amount *and a unit* is the point: a stubbed `thenReturn(1001)` against a * nanosecond ticker is off by a factor of a million and still compiles, whereas `advance(1001, * MILLISECONDS)` cannot be. + * + * The tick is volatile so that a test thread can advance the ticker while the code under test reads + * it from another thread. */ -class TestMonotonicTicker(private var nanos: Long = 0) : MonotonicTicker { +class TestMonotonicTicker(@Volatile private var nanos: Long = 0) : MonotonicTicker { override fun tickNanos(): Long = nanos fun advance(amount: Long, unit: TimeUnit) {