diff --git a/CHANGELOG.md b/CHANGELOG.md index 84e85b5dac..b929e7c4a1 100644 --- a/CHANGELOG.md +++ b/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 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 b726dd0c88..279098119b 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 @@ -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,7 +48,7 @@ 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; @@ -54,7 +56,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; @@ -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,7 +96,7 @@ final class ANRWatchDog extends Thread { super("|ANR-WatchDog|"); - this.timeProvider = timeProvider; + this.clock = clock; this.timeoutIntervalMillis = timeoutIntervalMillis; this.pollingIntervalMs = pollingIntervalMillis; this.reportInDebug = reportInDebug; @@ -102,9 +104,10 @@ final class ANRWatchDog extends Thread { 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, 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 3cb0bea4b0..51cde910b5 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.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 { 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 2f3b6791c5..2c1549bc47 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.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() + 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(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() + } + } } 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 2ae48fb325..3dd0de4578 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,6 +1,5 @@ package io.sentry.android.core.anr -import android.os.SystemClock import androidx.test.ext.junit.runners.AndroidJUnit4 import io.sentry.ILogger import io.sentry.IScopes @@ -9,6 +8,8 @@ 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.TestMonotonicClock +import java.util.concurrent.TimeUnit.MILLISECONDS import kotlin.test.AfterTest import kotlin.test.BeforeTest import kotlin.test.Test @@ -30,9 +31,11 @@ class AnrProfilingIntegrationTest { private lateinit var mockScopes: IScopes private lateinit var mockLogger: ILogger private lateinit var options: SentryAndroidOptions + private lateinit var clock: TestMonotonicClock @BeforeTest fun setup() { + clock = TestMonotonicClock() mockScopes = mock() mockLogger = mock() options = @@ -163,7 +166,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 { @@ -172,20 +174,20 @@ class AnrProfilingIntegrationTest { anrProfilingSampleRate = 1.0 } - val integration = AnrProfilingIntegration() + val integration = AnrProfilingIntegration(clock) integration.register(mockScopes, androidOptions) // Drive the state machine synchronously to avoid racing the background polling thread. - SystemClock.setCurrentTimeMillis(1_000) + clock.advance(900, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.IDLE, integration.state) assertTrue(integration.profileManager.load().stacks.isEmpty()) - SystemClock.setCurrentTimeMillis(3_000) + clock.advance(2_000, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.SUSPICIOUS, integration.state) - SystemClock.setCurrentTimeMillis(6_000) + clock.advance(3_000, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.ANR_DETECTED, integration.state) assertEquals(2, integration.profileManager.load().stacks.size) @@ -199,7 +201,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 { @@ -208,11 +209,11 @@ class AnrProfilingIntegrationTest { anrProfilingSampleRate = 1.0 } - val integration = AnrProfilingIntegration() + val integration = AnrProfilingIntegration(clock) integration.register(mockScopes, androidOptions) integration.onBackground() - SystemClock.setCurrentTimeMillis(20_000) + clock.advance(19_000, MILLISECONDS) integration.onForeground() Thread.sleep(100) @@ -266,7 +267,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 { @@ -275,17 +275,17 @@ class AnrProfilingIntegrationTest { anrProfilingSampleRate = 0.0 } - val integration = AnrProfilingIntegration() + val integration = AnrProfilingIntegration(clock) integration.register(mockScopes, androidOptions) integration.onForeground() // Transition to suspicious - SystemClock.setCurrentTimeMillis(3_000) + clock.advance(2_900, MILLISECONDS) integration.checkMainThread(mainThread) assertEquals(AnrProfilingIntegration.MainThreadState.SUSPICIOUS, integration.state) // Transition to ANR - SystemClock.setCurrentTimeMillis(6_000) + clock.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/TestMonotonicClock.kt b/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicClock.kt index e478e7b9bd..4039dc578b 100644 --- a/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicClock.kt +++ b/sentry-test-support/src/main/kotlin/io/sentry/time/TestMonotonicClock.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 clock 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 clock while the code under test reads + * it from another thread. */ -class TestMonotonicClock(private var nanos: Long = 0) : MonotonicClock { +class TestMonotonicClock(@Volatile private var nanos: Long = 0) : MonotonicClock { override fun tickNanos(): Long = nanos fun advance(amount: Long, unit: TimeUnit) {