Skip to content
4 changes: 4 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This returns EITHER a monotonic clock or a wall clock depending on the platform. This is a bad abstraction.
On android it gives you a monotonic clock which is what we want for this class, but the fact that it has Date in the name but gives you a monotonic clock is quite confusing.

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;
Expand All @@ -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(),
Comment thread
cursor[bot] marked this conversation as resolved.
Resolved
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,
Expand All @@ -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;
Expand All @@ -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);
};

Expand Down Expand Up @@ -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,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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.");
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -62,13 +75,26 @@ 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 installTicker(final @NotNull MonotonicTicker ticker) {

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is probably the only weird design about this PR. Open to other ways of doing this!

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see two other options, none of them is great:

  1. Open up the SentryOptions with a setMonotonicTicker
  2. Static mocks within the tests
val testTicker = TestMonotonicTicker(0)
fun withMockedTicker(closure: () -> Unit) {
  Mockito.mockStatic(AndroidMonotonicTicker::class.java).use { mock ->
    mock
      .`when`<Any> { AndroidMonotonicTicker.getInstance() }
      .thenReturn(testTicker)
    closure()
  }
}

(In the long run replacing the generic SentryOptions with a custom interface , e.g. AnrProfilingIntegrationOptions in this case feels like the right solution).

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree that having a custom interface is the way to go, but I don't want to blow up the scope of this PR.
For now I'll use static mocks in tests since that avoids adding an extra API.

this.ticker = ticker;
this.lastMainThreadExecutionNanos = ticker.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();
installTicker(options.getMonotonicTicker());
this.debugManager = this.options.getDebugManager();

if (this.options.isAnrProfilingEnabled()) {
Expand Down Expand Up @@ -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);

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sleep inflates ANR profiling stalls

Medium Severity

Measuring the stall with elapsedRealtime counts time the device spent asleep. ProcessLifecycleOwner keeps the app started for 700ms of uptime after the screen turns off, so a suspend in that window makes checkMainThread treat the sleep as a main-thread stall and persist a false ANR profile.

Fix in CursorΒ Fix in Web

Reviewed by Cursor Bugbot for commit 4a11cb6. Configure here.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's fine for now, we only ever report the profile if there's an ANR available via ApplicationExitInfo APIs.


if (diff < THRESHOLD_SUSPICION_MS) {
mainThreadState = MainThreadState.IDLE;
Expand Down Expand Up @@ -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 {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -44,7 +45,7 @@ class ANRWatchDogTest {

val sut =
ANRWatchDog(
timeProvider,
ticker,
interval,
1L,
true,
Expand All @@ -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)

Expand Down Expand Up @@ -91,7 +92,7 @@ class ANRWatchDogTest {

val sut =
ANRWatchDog(
timeProvider,
ticker,
interval,
1L,
true,
Expand All @@ -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)

Expand Down Expand Up @@ -143,7 +144,7 @@ class ANRWatchDogTest {

val sut =
ANRWatchDog(
timeProvider,
ticker,
interval,
1L,
true,
Expand All @@ -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)

Expand Down Expand Up @@ -199,7 +200,7 @@ class ANRWatchDogTest {

val sut =
ANRWatchDog(
timeProvider,
ticker,
interval,
1L,
true,
Expand All @@ -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
Expand All @@ -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()
}
}
}
Loading
Loading