From f6cfce817c5920de2150e6865d753f2483caa773 Mon Sep 17 00:00:00 2001 From: Timur Valeev Date: Thu, 20 Aug 2026 14:04:57 +0100 Subject: [PATCH] RUM-18174: Fix duration computation --- detekt_custom_safe_calls_third_party.yml | 1 + .../MainLooperLongTaskStrategy.kt | 151 +++++++--- .../MainLooperLongTaskStrategyTest.kt | 275 +++++++++++++++++- 3 files changed, 378 insertions(+), 49 deletions(-) diff --git a/detekt_custom_safe_calls_third_party.yml b/detekt_custom_safe_calls_third_party.yml index a48a4e71c3..6130dfac72 100644 --- a/detekt_custom_safe_calls_third_party.yml +++ b/detekt_custom_safe_calls_third_party.yml @@ -440,6 +440,7 @@ datadog: - "kotlin.Array.firstOrNull(kotlin.Function1)" - "kotlin.Array.forEach(kotlin.Function1)" - "kotlin.Array.forEachIndexed(kotlin.Function2)" + - "kotlin.Array.isEmpty()" - "kotlin.Array.isNotEmpty()" - "kotlin.Array.joinToString(kotlin.CharSequence, kotlin.CharSequence, kotlin.CharSequence, kotlin.Int, kotlin.CharSequence, kotlin.Function1?)" - "kotlin.Array.map(kotlin.Function1)" diff --git a/features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategy.kt b/features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategy.kt index 4c6ff14635..947c7b47f8 100644 --- a/features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategy.kt +++ b/features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategy.kt @@ -9,44 +9,55 @@ package com.datadog.android.rum.internal.instrumentation import android.content.Context import android.os.Looper import android.util.Printer +import androidx.annotation.AnyThread +import androidx.annotation.MainThread import com.datadog.android.api.SdkCore import com.datadog.android.api.feature.FeatureSdkCore import com.datadog.android.rum.GlobalRumMonitor +import com.datadog.android.rum.internal.instrumentation.MainLooperLongTaskStrategy.CompositePrinter.addPrinter +import com.datadog.android.rum.internal.instrumentation.MainLooperLongTaskStrategy.CompositePrinter.printers +import com.datadog.android.rum.internal.instrumentation.MainLooperLongTaskStrategy.CompositePrinter.println +import com.datadog.android.rum.internal.instrumentation.MainLooperLongTaskStrategy.CompositePrinter.removePrinter import com.datadog.android.rum.internal.monitor.AdvancedRumMonitor import com.datadog.android.rum.tracking.TrackingStrategy -import java.util.concurrent.CopyOnWriteArraySet import java.util.concurrent.TimeUnit -import java.util.concurrent.atomic.AtomicBoolean internal class MainLooperLongTaskStrategy(internal val thresholdMs: Long) : Printer, TrackingStrategy { - private val thresholdNS = TimeUnit.MILLISECONDS.toNanos(thresholdMs) - private var startUptimeNs: Long = 0L - private var target: String = "" private lateinit var sdkCore: SdkCore + private val thresholdNs = TimeUnit.MILLISECONDS.toNanos(thresholdMs) - // region TrackingStrategy + @Volatile + private var state = DispatcherState(thresholdNs) + // region TrackingStrategy + @AnyThread override fun register(sdkCore: SdkCore, context: Context) { this.sdkCore = sdkCore - if (CompositePrinter.isRegistered.compareAndSet(false, true)) { - // not in the class constructor to make setup easier for tests - Looper.getMainLooper().setMessageLogging(CompositePrinter) - } - CompositePrinter.registeredPrinters.add(this) + state = DispatcherState(thresholdNs) + addPrinter(this) } + @AnyThread override fun unregister(context: Context?) { - CompositePrinter.registeredPrinters.remove(this) + removePrinter(this) } // endregion // region Printer - - override fun println(x: String?) { - if (x != null) { - detectLongTask(x) + @MainThread + override fun println(message: String?) { + if (message == null || !this::sdkCore.isInitialized) return + val now = sdkCore.getDeviceElapsedTimeNanos() ?: return + when { + message.startsWith(PREFIX_START) -> state.onStart(message, now) + message.startsWith(PREFIX_END) -> state.onFinish(now)?.let { longTask -> + (GlobalRumMonitor.get(sdkCore) as? AdvancedRumMonitor)?.addLongTask( + longTask.durationNs, + longTask.target + ) + } } } @@ -60,51 +71,97 @@ internal class MainLooperLongTaskStrategy(internal val thresholdMs: Long) : Prin other as MainLooperLongTaskStrategy - if (thresholdMs != other.thresholdMs) return false - - return true - } - - override fun hashCode(): Int { - return thresholdMs.hashCode() + return thresholdMs == other.thresholdMs } - override fun toString(): String { - return "MainLooperLongTaskStrategy($thresholdMs)" - } - - // endregion + override fun hashCode(): Int = thresholdMs.hashCode() - // region Internal - - private fun detectLongTask(message: String) { - val now = (sdkCore as FeatureSdkCore).timeProvider.getDeviceElapsedTimeNanos() - if (message.startsWith(PREFIX_START)) { - @Suppress("UnsafeThirdPartyFunctionCall") // substring can't throw IndexOutOfBounds - target = message.substring(PREFIX_START_LENGTH) - startUptimeNs = now - } else if (message.startsWith(PREFIX_END)) { - val durationNs = now - startUptimeNs - if (durationNs > thresholdNS && this::sdkCore.isInitialized) { - (GlobalRumMonitor.get(sdkCore) as? AdvancedRumMonitor)?.addLongTask(durationNs, target) - } - } - } + override fun toString(): String = "MainLooperLongTaskStrategy($thresholdMs)" // endregion companion object { private const val PREFIX_START = ">>>>> Dispatching to " private const val PREFIX_END = "<<<<< Finished to " - private const val PREFIX_START_LENGTH = PREFIX_START.length + + // a start that has not happened yet sits infinitely far in the future, so any duration + // measured against it comes out negative instead of relying on signed overflow + private const val NOT_STARTED = Long.MAX_VALUE + + private fun SdkCore.getDeviceElapsedTimeNanos(): Long? = + (this as? FeatureSdkCore)?.timeProvider?.getDeviceElapsedTimeNanos() } + /** + * Holds the dispatch currently in flight. A fresh instance is published on every [register], so + * these fields are only ever written and read from the main thread (the [Looper] printer) and + * need no synchronization of their own. + */ + private class DispatcherState(private val thresholdNS: Long) { + private var message: String = "" + private var startUptimeNs: Long = NOT_STARTED + + @MainThread + fun onStart(message: String, nowNs: Long) { + this.message = message + startUptimeNs = nowNs + } + + @MainThread + @Suppress("ReturnCount") + fun onFinish(nowNs: Long): LongTaskParameters? { + if (startUptimeNs == NOT_STARTED) return null + val durationNs = nowNs - startUptimeNs + startUptimeNs = NOT_STARTED + if (durationNs <= thresholdNS) return null + + return LongTaskParameters(durationNs, target = message.removePrefix(PREFIX_START)) + } + + data class LongTaskParameters(val durationNs: Long, val target: String) + } + + /** + * The main [Looper] holds a single message-logging [Printer], so all the strategies in the + * process have to share one, which multiplexes to them. [printers] being empty is what tracks + * whether that printer is installed: [addPrinter] and [removePrinter] are serialized so the + * array and the [Looper] can never disagree. + * + * Registration is keyed on identity, not [Any.equals]: two strategies configured with the same + * threshold are equal but belong to different SDK instances, and both must be notified. + * + * The array is swapped wholesale under the lock and read without one, so [println] neither + * blocks the main thread nor allocates for a message the [Looper] is about to dispatch. + */ internal object CompositePrinter : Printer { - val isRegistered = AtomicBoolean(false) - val registeredPrinters = CopyOnWriteArraySet() + @Volatile + private var printers: Array = emptyArray() + + internal val registeredPrinters: List + get() = printers.toList() + + @AnyThread + fun addPrinter(printer: Printer) = synchronized(this) { + if (printers.any { it === printer }) return + printers += printer + if (printers.size == 1) { + Looper.getMainLooper().setMessageLogging(this) + } + } + + @AnyThread + fun removePrinter(printer: Printer) = synchronized(this) { + printers = printers.filter { it !== printer }.toTypedArray() + if (printers.isEmpty()) { + Looper.getMainLooper().setMessageLogging(null) + } + } + + @MainThread override fun println(x: String?) { - registeredPrinters.forEach { it.println(x) } + val snapshot = printers + for (i in snapshot.indices) snapshot[i].println(x) } } } diff --git a/features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategyTest.kt b/features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategyTest.kt index 48840adcf0..9aab28f1d0 100644 --- a/features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategyTest.kt +++ b/features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/instrumentation/MainLooperLongTaskStrategyTest.kt @@ -6,6 +6,7 @@ package com.datadog.android.rum.internal.instrumentation +import android.content.Context import android.os.Looper import com.datadog.android.internal.tests.stub.StubTimeProvider import com.datadog.android.rum.internal.monitor.AdvancedRumMonitor @@ -32,13 +33,21 @@ import org.junit.jupiter.api.extension.Extensions import org.mockito.Mock import org.mockito.junit.jupiter.MockitoExtension import org.mockito.junit.jupiter.MockitoSettings +import org.mockito.kotlin.argumentCaptor +import org.mockito.kotlin.atLeastOnce import org.mockito.kotlin.doReturn +import org.mockito.kotlin.eq import org.mockito.kotlin.isA import org.mockito.kotlin.mock +import org.mockito.kotlin.never import org.mockito.kotlin.verify import org.mockito.kotlin.verifyNoInteractions +import org.mockito.kotlin.verifyNoMoreInteractions import org.mockito.kotlin.whenever import org.mockito.quality.Strictness +import java.util.concurrent.CompletableFuture +import java.util.concurrent.Executors +import java.util.concurrent.TimeUnit @Extensions( ExtendWith(MockitoExtension::class), @@ -72,8 +81,8 @@ internal class MainLooperLongTaskStrategyTest : ObjectTest>("sThreadLocal").set(null) } @@ -109,6 +118,32 @@ internal class MainLooperLongTaskStrategyTest : ObjectTest>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + stubTimeProvider.elapsedTimeNs += TEST_THRESHOLD_NS + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verifyNoInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M do not report long task W println() {finished without dispatch}`( + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String + ) { + // Given + stubTimeProvider.elapsedTimeNs = DEVICE_UPTIME_NS + + // When + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verifyNoInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M do not report long task W println() {finished without dispatch, negative clock origin}`( + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String + ) { + // Given: System.nanoTime() counts from an arbitrary origin and is documented as possibly + // negative. Subtracting the NOT_STARTED sentinel from a negative clock overflows into a + // huge *positive* duration, so the sentinel must be checked before the duration is judged. + // This test fails if that check is dropped or moved after the threshold comparison. + stubTimeProvider.elapsedTimeNs = NEGATIVE_CLOCK_ORIGIN_NS + + // When + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verifyNoInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M report long task W println() {dispatch starts at zero}`( + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // Given + stubTimeProvider.elapsedTimeNs = 0L + + // When + testedPrinter.println(">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + stubTimeProvider.elapsedTimeNs = LONG_TASK_DURATION_NS + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verify(rumMonitor.mockInstance as AdvancedRumMonitor) + .addLongTask(LONG_TASK_DURATION_NS, "$fakeTarget $fakeCallback: $fakeWhat") + } + + @Test + fun `M do not report long task W unregister()+register()+println() {strategy replaced during dispatch}`( + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // Given + stubTimeProvider.elapsedTimeNs = DEVICE_UPTIME_NS + MainLooperLongTaskStrategy.CompositePrinter.println(">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + val testedReplacementPrinter = MainLooperLongTaskStrategy(TEST_THRESHOLD_MS) + + // When + testedPrinter.unregister(mock()) + testedReplacementPrinter.register(rumMonitor.mockSdkCore, mock()) + stubTimeProvider.elapsedTimeNs += LONG_TASK_DURATION_NS + MainLooperLongTaskStrategy.CompositePrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verifyNoInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M clear pending dispatch W unregister()+register()+println()`( + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // Given + stubTimeProvider.elapsedTimeNs = DEVICE_UPTIME_NS + testedPrinter.println(">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + + // When + testedPrinter.unregister(mock()) + testedPrinter.register(rumMonitor.mockSdkCore, mock()) + stubTimeProvider.elapsedTimeNs += LONG_TASK_DURATION_NS + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verifyNoInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M report long task once W println() {finished twice}`( + @LongForgery(min = TEST_THRESHOLD_NS + 1) fakeDurationNs: Long, + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // When + testedPrinter.println(">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + stubTimeProvider.elapsedTimeNs += fakeDurationNs + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + stubTimeProvider.elapsedTimeNs += SHORT_TASK_DURATION_NS + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verify(rumMonitor.mockInstance as AdvancedRumMonitor) + .addLongTask(fakeDurationNs, "$fakeTarget $fakeCallback: $fakeWhat") + verifyNoMoreInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M clear state W println() {short task finished, then orphan finished}`( + @LongForgery(min = 0, max = TEST_THRESHOLD_NS) fakeShortDurationNs: Long, + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // Given: a short task completes (duration <= threshold) — must clear pending state + testedPrinter.println(">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + stubTimeProvider.elapsedTimeNs += fakeShortDurationNs + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // When: an orphan Finished (no new Dispatching) arrives after enough time has + // passed that reusing the stale startUptimeNs would look like a long task + stubTimeProvider.elapsedTimeNs += LONG_TASK_DURATION_NS + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verifyNoInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M clear state W println() {long task reported, then orphan finished}`( + @LongForgery(min = TEST_THRESHOLD_NS + 1) fakeDurationNs: Long, + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // Given: a long task is reported — must clear pending state afterwards + testedPrinter.println(">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat") + stubTimeProvider.elapsedTimeNs += fakeDurationNs + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // When: an orphan Finished (no new Dispatching) arrives after more time passes + stubTimeProvider.elapsedTimeNs += LONG_TASK_DURATION_NS + testedPrinter.println("<<<<< Finished to $fakeTarget $fakeCallback") + + // Then + verify(rumMonitor.mockInstance as AdvancedRumMonitor) + .addLongTask(fakeDurationNs, "$fakeTarget $fakeCallback: $fakeWhat") + verifyNoMoreInteractions(rumMonitor.mockInstance) + } + + @Test + fun `M not crash nor report bogus duration W concurrent println() and unregister()+register()`( + @StringForgery fakeTarget: String, + @StringForgery fakeCallback: String, + @IntForgery fakeWhat: Int + ) { + // Given: a device that has been up for a while, so a start timestamp that leaked across a + // register() would surface as a duration orders of magnitude above the simulated one + val dispatchMessage = ">>>>> Dispatching to $fakeTarget $fakeCallback: $fakeWhat" + val finishMessage = "<<<<< Finished to $fakeTarget $fakeCallback" + val fakeContext = mock() + stubTimeProvider.elapsedTimeNs = DEVICE_UPTIME_NS + + val executor = Executors.newFixedThreadPool(2) + + // When + try { + val dispatcherFuture = CompletableFuture.runAsync( + { + repeat(RACE_ITERATIONS) { + testedPrinter.println(dispatchMessage) + stubTimeProvider.elapsedTimeNs += LONG_TASK_DURATION_NS + testedPrinter.println(finishMessage) + } + }, + executor + ) + val lifecycleFuture = CompletableFuture.runAsync( + { + repeat(RACE_ITERATIONS) { + testedPrinter.unregister(fakeContext) + testedPrinter.register(rumMonitor.mockSdkCore, fakeContext) + } + }, + executor + ) + CompletableFuture + .allOf(dispatcherFuture, lifecycleFuture) + .get(RACE_TIMEOUT_SECONDS, TimeUnit.SECONDS) + } finally { + executor.shutdownNow() + } + + // Then: both threads are done, so one clean dispatch reports deterministically and keeps + // the assertion below from passing on an empty capture + testedPrinter.println(dispatchMessage) + stubTimeProvider.elapsedTimeNs += LONG_TASK_DURATION_NS + testedPrinter.println(finishMessage) + + // a register() landing mid-dispatch may legitimately drop a long task, but every task + // that is reported must carry the duration we actually simulated + val durationCaptor = argumentCaptor() + verify(rumMonitor.mockInstance as AdvancedRumMonitor, atLeastOnce()) + .addLongTask(durationCaptor.capture(), eq("$fakeTarget $fakeCallback: $fakeWhat")) + assertThat(durationCaptor.allValues).allMatch { it == LONG_TASK_DURATION_NS } + } + override fun createInstance(forge: Forge): MainLooperLongTaskStrategy { return MainLooperLongTaskStrategy(forge.aLong(0, 65536L)) } @@ -163,6 +426,14 @@ internal class MainLooperLongTaskStrategyTest : ObjectTest