diff --git a/android-agent/src/main/kotlin/io/opentelemetry/android/agent/OpenTelemetryRumInitializer.kt b/android-agent/src/main/kotlin/io/opentelemetry/android/agent/OpenTelemetryRumInitializer.kt index 079062f3c..50fdd1fc5 100644 --- a/android-agent/src/main/kotlin/io/opentelemetry/android/agent/OpenTelemetryRumInitializer.kt +++ b/android-agent/src/main/kotlin/io/opentelemetry/android/agent/OpenTelemetryRumInitializer.kt @@ -180,9 +180,9 @@ object OpenTelemetryRumInitializer { } if (slowRenderingDetectionPollInterval != null) { - getInstrumentation()?.setSlowRenderingDetectionPollInterval( - slowRenderingDetectionPollInterval, - ) + val instrumentation = getInstrumentation() + instrumentation?.setSlowRenderingDetectionPollInterval(slowRenderingDetectionPollInterval) + instrumentation?.enableDeprecatedZeroDurationSpan() } } diff --git a/instrumentation/slowrendering/api/slowrendering.api b/instrumentation/slowrendering/api/slowrendering.api index 5555326c5..f398c6c60 100644 --- a/instrumentation/slowrendering/api/slowrendering.api +++ b/instrumentation/slowrendering/api/slowrendering.api @@ -1,5 +1,7 @@ public final class io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation : io/opentelemetry/android/instrumentation/AndroidInstrumentation { public fun ()V + public final fun enableDeprecatedZeroDurationSpan ()Lio/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation; + public final fun enableVerboseDebugLogging ()Lio/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation; public fun getName ()Ljava/lang/String; public fun install (Lio/opentelemetry/android/instrumentation/InstallationContext;)V public final fun setSlowRenderingDetectionPollInterval (Ljava/time/Duration;)Lio/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation; diff --git a/instrumentation/slowrendering/build.gradle.kts b/instrumentation/slowrendering/build.gradle.kts index 040428e6a..e38370aaa 100644 --- a/instrumentation/slowrendering/build.gradle.kts +++ b/instrumentation/slowrendering/build.gradle.kts @@ -11,6 +11,10 @@ android { defaultConfig { consumerProguardFiles("consumer-rules.pro") } + + testOptions { + unitTests.isReturnDefaultValues = true + } } dependencies { @@ -24,5 +28,6 @@ dependencies { implementation(libs.opentelemetry.semconv) implementation(libs.opentelemetry.sdk) implementation(libs.opentelemetry.instrumentation.api) + implementation(libs.opentelemetry.sdk.extension.incubator) testImplementation(libs.robolectric) } diff --git a/instrumentation/slowrendering/config/detekt/baseline.xml b/instrumentation/slowrendering/config/detekt/baseline.xml new file mode 100644 index 000000000..93334d400 --- /dev/null +++ b/instrumentation/slowrendering/config/detekt/baseline.xml @@ -0,0 +1,11 @@ + + + + + EmptyFunctionBlock:JankReporterTest.kt$JankReporterTest.<no name provided>${ } + ForbiddenComment:EventJankReporter.kt$// TODO: Replace with semconv constants + MagicNumber:EventJankReporter.kt$EventJankReporter$1000.0 + MagicNumber:SlowRenderingInstrumentation.kt$SlowRenderingInstrumentation$1000.0 + TooGenericExceptionCaught:SlowRenderListener.kt$SlowRenderListener$e: Exception + + diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/EventJankReporter.kt b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/EventJankReporter.kt new file mode 100644 index 000000000..bc9497ace --- /dev/null +++ b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/EventJankReporter.kt @@ -0,0 +1,60 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import android.util.Log +import io.opentelemetry.android.common.RumConstants +import io.opentelemetry.api.common.AttributeKey +import io.opentelemetry.api.common.Attributes +import io.opentelemetry.api.incubator.logs.ExtendedLogRecordBuilder +import io.opentelemetry.api.logs.Logger + +// TODO: Replace with semconv constants +internal val FRAME_COUNT: AttributeKey = AttributeKey.longKey("app.jank.frame_count") +internal val PERIOD: AttributeKey = AttributeKey.doubleKey("app.jank.period") +internal val THRESHOLD: AttributeKey = AttributeKey.doubleKey("app.jank.threshold") + +internal class EventJankReporter( + private val eventLogger: Logger, + private val threshold: Double, + private val debugVerbose: Boolean = false, +) : JankReporter { + override fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) { + var frameCount: Long = 0 + for (entry in durationToCountHistogram) { + val durationMillis = entry.key + if ((durationMillis / 1000.0) > threshold) { + val count = entry.value + if (debugVerbose) { + Log.d( + RumConstants.OTEL_RUM_LOG_TAG, + "* Slow render detected: $durationMillis ms. $count times", + ) + } + frameCount += count + } + } + + if (frameCount > 0) { + val eventBuilder = eventLogger.logRecordBuilder() as ExtendedLogRecordBuilder + val attributes = + Attributes + .builder() + .put(FRAME_COUNT, frameCount) + .put(PERIOD, periodSeconds) + .put(THRESHOLD, threshold) + .build() + eventBuilder + .setEventName("app.jank") + .setAllAttributes(attributes) + .emit() + } + } +} diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/JankReporter.kt b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/JankReporter.kt new file mode 100644 index 000000000..33fb24881 --- /dev/null +++ b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/JankReporter.kt @@ -0,0 +1,37 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +/** + * Responsible for sending telemetry. This is a temporary class that we can remove + * after the jank semconv becomes more stable. + */ +internal fun interface JankReporter { + fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) + + /** + * Creates a combined JankReporter that will first report slow for this + * instance and then delegate to another JankReporter instance. + */ + fun combine(jankReporter: JankReporter): JankReporter { + require(jankReporter != this) { "cannot combine with self" } + val exec = this::reportSlow + return object : JankReporter { + override fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) { + exec(durationToCountHistogram, periodSeconds, activityName) + jankReporter.reportSlow(durationToCountHistogram, periodSeconds, activityName) + } + } + } +} diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/PerActivityListener.kt b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/PerActivityListener.kt new file mode 100644 index 000000000..04ec4ff5c --- /dev/null +++ b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/PerActivityListener.kt @@ -0,0 +1,62 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import android.app.Activity +import android.os.Build +import android.view.FrameMetrics +import android.view.Window +import android.view.Window.OnFrameMetricsAvailableListener +import androidx.annotation.GuardedBy +import androidx.annotation.RequiresApi +import java.util.concurrent.TimeUnit + +private val NANOS_PER_MS = TimeUnit.MILLISECONDS.toNanos(1).toInt() + +// rounding value adds half a millisecond, for rounding to nearest ms +private val NANOS_ROUNDING_VALUE: Int = NANOS_PER_MS / 2 + +@RequiresApi(api = Build.VERSION_CODES.N) +internal class PerActivityListener( + private val activity: Activity, +) : OnFrameMetricsAvailableListener { + private val lock = Any() + + @GuardedBy("lock") + private var drawDurationHistogram: MutableMap = HashMap() + + fun getActivityName(): String = activity.componentName.flattenToShortString() + + override fun onFrameMetricsAvailable( + window: Window?, + frameMetrics: FrameMetrics, + dropCountSinceLastInvocation: Int, + ) { + val firstDrawFrame = frameMetrics.getMetric(FrameMetrics.FIRST_DRAW_FRAME) + if (firstDrawFrame == 1L) { + return + } + + val drawDurationsNs = frameMetrics.getMetric(FrameMetrics.DRAW_DURATION) + // ignore values < 0; something must have gone wrong + if (drawDurationsNs >= 0) { + synchronized(lock) { + // calculation copied from FrameMetricsAggregator + val durationMs = ((drawDurationsNs + NANOS_ROUNDING_VALUE) / NANOS_PER_MS).toInt() + val oldValue: Int = drawDurationHistogram.getOrDefault(durationMs, 0) + drawDurationHistogram[durationMs] = (oldValue + 1) + } + } + } + + fun resetMetrics(): Map { + synchronized(lock) { + val metrics = HashMap(drawDurationHistogram) + drawDurationHistogram = HashMap() + return metrics + } + } +} diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListener.java b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListener.java deleted file mode 100644 index ac0fbe283..000000000 --- a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListener.java +++ /dev/null @@ -1,225 +0,0 @@ -/* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ - -package io.opentelemetry.android.instrumentation.slowrendering; - -import static android.view.FrameMetrics.DRAW_DURATION; -import static android.view.FrameMetrics.FIRST_DRAW_FRAME; - -import android.app.Activity; -import android.os.Build; -import android.os.Handler; -import android.os.HandlerThread; -import android.os.Looper; -import android.util.Log; -import android.util.SparseIntArray; -import android.view.FrameMetrics; -import android.view.Window; -import androidx.annotation.GuardedBy; -import androidx.annotation.NonNull; -import androidx.annotation.RequiresApi; -import io.opentelemetry.android.common.RumConstants; -import io.opentelemetry.android.internal.services.visiblescreen.activities.DefaultingActivityLifecycleCallbacks; -import io.opentelemetry.api.trace.Span; -import io.opentelemetry.api.trace.Tracer; -import java.time.Duration; -import java.time.Instant; -import java.util.Map; -import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.ConcurrentMap; -import java.util.concurrent.Executors; -import java.util.concurrent.ScheduledExecutorService; -import java.util.concurrent.TimeUnit; - -@RequiresApi(api = Build.VERSION_CODES.N) -class SlowRenderListener implements DefaultingActivityLifecycleCallbacks { - - static final int SLOW_THRESHOLD_MS = 16; - static final int FROZEN_THRESHOLD_MS = 700; - - private static final int NANOS_PER_MS = (int) TimeUnit.MILLISECONDS.toNanos(1); - // rounding value adds half a millisecond, for rounding to nearest ms - private static final int NANOS_ROUNDING_VALUE = NANOS_PER_MS / 2; - - private static final HandlerThread frameMetricsThread = - new HandlerThread("FrameMetricsCollector"); - - private final Tracer tracer; - private final ScheduledExecutorService executorService; - private final Handler frameMetricsHandler; - private final Duration pollInterval; - - private final ConcurrentMap activities = - new ConcurrentHashMap<>(); - - SlowRenderListener(Tracer tracer, Duration pollInterval) { - this( - tracer, - Executors.newScheduledThreadPool(1), - new Handler(startFrameMetricsLoop()), - pollInterval); - } - - // Exists for testing - SlowRenderListener( - Tracer tracer, - ScheduledExecutorService executorService, - Handler frameMetricsHandler, - Duration pollInterval) { - this.tracer = tracer; - this.executorService = executorService; - this.frameMetricsHandler = frameMetricsHandler; - this.pollInterval = pollInterval; - } - - private static Looper startFrameMetricsLoop() { - // just a precaution: this is supposed to be called only once, and the thread should always - // be not started here - if (!frameMetricsThread.isAlive()) { - frameMetricsThread.start(); - } - return frameMetricsThread.getLooper(); - } - - // the returned future is very unlikely to fail - @SuppressWarnings("FutureReturnValueIgnored") - void start() { - executorService.scheduleWithFixedDelay( - this::reportSlowRenders, - pollInterval.toMillis(), - pollInterval.toMillis(), - TimeUnit.MILLISECONDS); - } - - public void shutdown() { - executorService.shutdownNow(); - for (Map.Entry entry : activities.entrySet()) { - Activity activity = entry.getKey(); - PerActivityListener listener = entry.getValue(); - activity.getWindow().removeOnFrameMetricsAvailableListener(listener); - } - activities.clear(); - } - - @Override - public void onActivityResumed(@NonNull Activity activity) { - if (executorService.isShutdown()) { - return; - } - PerActivityListener listener = new PerActivityListener(activity); - PerActivityListener existing = activities.putIfAbsent(activity, listener); - if (existing == null) { - activity.getWindow().addOnFrameMetricsAvailableListener(listener, frameMetricsHandler); - } - } - - @Override - public void onActivityPaused(@NonNull Activity activity) { - if (executorService.isShutdown()) { - return; - } - PerActivityListener listener = activities.remove(activity); - if (listener != null) { - activity.getWindow().removeOnFrameMetricsAvailableListener(listener); - reportSlow(listener); - } - } - - @RequiresApi(api = Build.VERSION_CODES.N) - static class PerActivityListener implements Window.OnFrameMetricsAvailableListener { - - private final Activity activity; - private final Object lock = new Object(); - - @GuardedBy("lock") - private SparseIntArray drawDurationHistogram = new SparseIntArray(); - - PerActivityListener(Activity activity) { - this.activity = activity; - } - - @Override - public void onFrameMetricsAvailable( - Window window, FrameMetrics frameMetrics, int dropCountSinceLastInvocation) { - - long firstDrawFrame = frameMetrics.getMetric(FIRST_DRAW_FRAME); - if (firstDrawFrame == 1) { - return; - } - - long drawDurationsNs = frameMetrics.getMetric(DRAW_DURATION); - // ignore values < 0; something must have gone wrong - if (drawDurationsNs >= 0) { - synchronized (lock) { - // calculation copied from FrameMetricsAggregator - int durationMs = - (int) ((drawDurationsNs + NANOS_ROUNDING_VALUE) / NANOS_PER_MS); - int oldValue = drawDurationHistogram.get(durationMs); - drawDurationHistogram.put(durationMs, (oldValue + 1)); - } - } - } - - SparseIntArray resetMetrics() { - synchronized (lock) { - SparseIntArray metrics = drawDurationHistogram; - drawDurationHistogram = new SparseIntArray(); - return metrics; - } - } - - public String getActivityName() { - return activity.getComponentName().flattenToShortString(); - } - } - - private void reportSlowRenders() { - try { - activities.forEach((activity, listener) -> reportSlow(listener)); - } catch (Exception e) { - Log.w(RumConstants.OTEL_RUM_LOG_TAG, "Exception while processing frame metrics", e); - } - } - - private void reportSlow(PerActivityListener listener) { - int slowCount = 0; - int frozenCount = 0; - SparseIntArray durationToCountHistogram = listener.resetMetrics(); - for (int i = 0; i < durationToCountHistogram.size(); i++) { - int duration = durationToCountHistogram.keyAt(i); - int count = durationToCountHistogram.get(duration); - if (duration > FROZEN_THRESHOLD_MS) { - Log.d( - RumConstants.OTEL_RUM_LOG_TAG, - "* FROZEN RENDER DETECTED: " + duration + " ms." + count + " times"); - frozenCount += count; - } else if (duration > SLOW_THRESHOLD_MS) { - Log.d( - RumConstants.OTEL_RUM_LOG_TAG, - "* Slow render detected: " + duration + " ms. " + count + " times"); - slowCount += count; - } - } - - Instant now = Instant.now(); - if (slowCount > 0) { - makeSpan("slowRenders", listener.getActivityName(), slowCount, now); - } - if (frozenCount > 0) { - makeSpan("frozenRenders", listener.getActivityName(), frozenCount, now); - } - } - - private void makeSpan(String spanName, String activityName, int slowCount, Instant now) { - // TODO: Use an event rather than a zero-duration span - Span span = - tracer.spanBuilder(spanName) - .setAttribute("count", slowCount) - .setAttribute("activity.name", activityName) - .setStartTimestamp(now) - .startSpan(); - span.end(now); - } -} diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListener.kt b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListener.kt new file mode 100644 index 000000000..64f187270 --- /dev/null +++ b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListener.kt @@ -0,0 +1,106 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import android.app.Activity +import android.os.Build +import android.os.Handler +import android.os.HandlerThread +import android.os.Looper +import android.util.Log +import androidx.annotation.RequiresApi +import io.opentelemetry.android.common.RumConstants +import io.opentelemetry.android.internal.services.visiblescreen.activities.DefaultingActivityLifecycleCallbacks +import java.time.Duration +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.ConcurrentMap +import java.util.concurrent.Executors +import java.util.concurrent.ScheduledExecutorService +import java.util.concurrent.TimeUnit + +@RequiresApi(api = Build.VERSION_CODES.N) +internal class SlowRenderListener( + private val jankReporter: JankReporter, + private val executorService: ScheduledExecutorService, + private val frameMetricsHandler: Handler, + private val pollInterval: Duration, +) : DefaultingActivityLifecycleCallbacks { + private val activities: ConcurrentMap = ConcurrentHashMap() + + constructor(jankReporter: JankReporter, pollInterval: Duration) : this( + jankReporter, + Executors.newScheduledThreadPool(1), + Handler(startFrameMetricsLoop()), + pollInterval, + ) + + // the returned future is very unlikely to fail + fun start() { + executorService.scheduleWithFixedDelay( + { this.reportSlowRenders() }, + pollInterval.toMillis(), + pollInterval.toMillis(), + TimeUnit.MILLISECONDS, + ) + } + + fun shutdown() { + executorService.shutdownNow() + for (entry in activities.entries) { + val activity: Activity = entry.key!! + val listener = entry.value + activity.window.removeOnFrameMetricsAvailableListener(listener) + } + activities.clear() + } + + override fun onActivityResumed(activity: Activity) { + if (executorService.isShutdown) { + return + } + val listener = PerActivityListener(activity) + val existing = activities.putIfAbsent(activity, listener) + if (existing == null) { + activity.window.addOnFrameMetricsAvailableListener(listener, frameMetricsHandler) + } + } + + override fun onActivityPaused(activity: Activity) { + if (executorService.isShutdown) { + return + } + val listener = activities.remove(activity) + if (listener != null) { + activity.window.removeOnFrameMetricsAvailableListener(listener) + val durationToCountHistogram = listener.resetMetrics() + jankReporter.reportSlow(durationToCountHistogram, pollInterval.toSeconds().toDouble(), listener.getActivityName()) + } + } + + private fun reportSlowRenders() { + try { + activities.forEach { (_: Activity?, listener: PerActivityListener) -> + val durationToCountHistogram = listener.resetMetrics() + jankReporter.reportSlow(durationToCountHistogram, pollInterval.toSeconds().toDouble(), listener.getActivityName()) + } + } catch (e: Exception) { + Log.w(RumConstants.OTEL_RUM_LOG_TAG, "Exception while processing frame metrics", e) + } + } + + companion object { + private val frameMetricsThread = HandlerThread("FrameMetricsCollector") + + private fun startFrameMetricsLoop(): Looper { + // just a precaution: this is supposed to be called only once, and the thread should always + // be not started here + if (!frameMetricsThread.isAlive) { + frameMetricsThread.start() + } + return frameMetricsThread.looper + } + } +} diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation.kt b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation.kt index 6794186a7..573d37d17 100644 --- a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation.kt +++ b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentation.kt @@ -18,6 +18,8 @@ import java.time.Duration */ @AutoService(AndroidInstrumentation::class) class SlowRenderingInstrumentation : AndroidInstrumentation { + internal var useDeprecatedSpan: Boolean = false + internal var debugVerbose: Boolean = false internal var slowRenderingDetectionPollInterval: Duration = Duration.ofSeconds(1) @Volatile @@ -45,6 +47,23 @@ class SlowRenderingInstrumentation : AndroidInstrumentation { return this } + /** + * Call this to enable verbose debug logging when slow renders are detected. + */ + fun enableVerboseDebugLogging(): SlowRenderingInstrumentation { + debugVerbose = true + return this + } + + /** + * Reports jank by using a zero-duration span. + */ + @Deprecated("Use the default event to report jank") + fun enableDeprecatedZeroDurationSpan(): SlowRenderingInstrumentation { + useDeprecatedSpan = true + return this + } + override fun install(ctx: InstallationContext) { if (Build.VERSION.SDK_INT < Build.VERSION_CODES.N) { Log.w( @@ -61,14 +80,19 @@ class SlowRenderingInstrumentation : AndroidInstrumentation { return } - detector = - SlowRenderListener( - ctx.openTelemetry.getTracer("io.opentelemetry.slow-rendering"), - slowRenderingDetectionPollInterval, - ) + val logger = ctx.openTelemetry.logsBridge.get("app.jank") + var jankReporter: JankReporter = EventJankReporter(logger, SLOW_THRESHOLD_MS / 1000.0, debugVerbose) + jankReporter = jankReporter.combine(EventJankReporter(logger, FROZEN_THRESHOLD_MS / 1000.0, debugVerbose)) + + if (useDeprecatedSpan) { + val tracer = ctx.openTelemetry.getTracer("io.opentelemetry.slow-rendering") + jankReporter = jankReporter.combine(SpanBasedJankReporter(tracer)) + } + + detector = SlowRenderListener(jankReporter, slowRenderingDetectionPollInterval) ctx.application.registerActivityLifecycleCallbacks(detector) - detector?.start() + detector!!.start() } override fun uninstall(ctx: InstallationContext) { diff --git a/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SpanBasedJankReporter.kt b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SpanBasedJankReporter.kt new file mode 100644 index 000000000..0712ab068 --- /dev/null +++ b/instrumentation/slowrendering/src/main/java/io/opentelemetry/android/instrumentation/slowrendering/SpanBasedJankReporter.kt @@ -0,0 +1,69 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import android.util.Log +import io.opentelemetry.android.common.RumConstants +import io.opentelemetry.api.trace.Span +import io.opentelemetry.api.trace.Tracer +import java.time.Instant + +internal const val SLOW_THRESHOLD_MS = 16 +internal const val FROZEN_THRESHOLD_MS = 700 + +internal class SpanBasedJankReporter( + private val tracer: Tracer, +) : JankReporter { + override fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) { + var slowCount = 0 + var frozenCount = 0 + for (entry in durationToCountHistogram) { + val duration = entry.key + val count = entry.value + if (duration > FROZEN_THRESHOLD_MS) { + Log.d( + RumConstants.OTEL_RUM_LOG_TAG, + "* FROZEN RENDER DETECTED: $duration ms.$count times", + ) + frozenCount += count + } else if (duration > SLOW_THRESHOLD_MS) { + Log.d( + RumConstants.OTEL_RUM_LOG_TAG, + "* Slow render detected: $duration ms. $count times", + ) + slowCount += count + } + } + + val now = Instant.now() + if (slowCount > 0) { + makeSpan("slowRenders", activityName, slowCount, now) + } + if (frozenCount > 0) { + makeSpan("frozenRenders", activityName, frozenCount, now) + } + } + + private fun makeSpan( + spanName: String, + activityName: String, + slowCount: Int, + now: Instant, + ) { + val span: Span = + tracer + .spanBuilder(spanName) + .setAttribute("count", slowCount.toLong()) + .setAttribute("activity.name", activityName) + .setStartTimestamp(now) + .startSpan() + span.end(now) + } +} diff --git a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/EventJankReporterTest.kt b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/EventJankReporterTest.kt new file mode 100644 index 000000000..5e0f25355 --- /dev/null +++ b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/EventJankReporterTest.kt @@ -0,0 +1,40 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import android.util.Log +import io.mockk.every +import io.mockk.mockkStatic +import io.opentelemetry.sdk.testing.junit4.OpenTelemetryRule +import org.assertj.core.api.Assertions.assertThat +import org.junit.Rule +import org.junit.jupiter.api.Test + +class EventJankReporterTest { + @Rule + var otelTesting: OpenTelemetryRule = OpenTelemetryRule.create() + + @Test + fun `event is generated`() { + val eventLogger = otelTesting.openTelemetry.logsBridge.get("JANK!") + val jankReporter = EventJankReporter(eventLogger, 0.600) + val histogramData = HashMap() + histogramData[17] = 3 + histogramData[701] = 1 + + mockkStatic(Log::class) + every { Log.d(any(), any()) } returns 0 + + jankReporter.reportSlow(histogramData, 10.5, "io.otel/Komponent") + + assertThat(otelTesting.logRecords.size).isEqualTo(1) + val log = otelTesting.logRecords.get(0) + assertThat(log.eventName).isEqualTo("app.jank") + assertThat(log.attributes.get(FRAME_COUNT)).isEqualTo(1) + assertThat(log.attributes.get(PERIOD)).isEqualTo(10.5) + assertThat(log.attributes.get(THRESHOLD)).isEqualTo(0.6) + } +} diff --git a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/JankReporterTest.kt b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/JankReporterTest.kt new file mode 100644 index 000000000..f613de5b5 --- /dev/null +++ b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/JankReporterTest.kt @@ -0,0 +1,73 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import org.assertj.core.api.Assertions.assertThat +import org.assertj.core.api.Assertions.assertThatExceptionOfType +import org.junit.Test + +class JankReporterTest { + @Test + fun combine() { + val state = StringBuilder("") + val inner = + object : JankReporter { + override fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) { + state + .append(".inner.") + .append(durationToCountHistogram) + .append(".") + .append(periodSeconds) + .append(".") + .append(activityName) + } + } + val outer = + object : JankReporter { + override fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) { + state + .append(".outer.") + .append(durationToCountHistogram) + .append(".") + .append(periodSeconds) + .append(".") + .append(activityName) + } + } + + val both = inner.combine(outer) + + val histogram = HashMap() + histogram[99] = 37 + both.reportSlow(histogram, 6.9, "four.something") + val expected = ".inner.{99=37}.6.9.four.something.outer.{99=37}.6.9.four.something" + assertThat(state.toString()).isEqualTo(expected) + } + + @Test + fun `combine with self fails`() { + val reporter = + object : JankReporter { + override fun reportSlow( + durationToCountHistogram: Map, + periodSeconds: Double, + activityName: String, + ) { + } + } + assertThatExceptionOfType(IllegalArgumentException::class.java) + .isThrownBy { reporter.combine(reporter) } + .withMessage("cannot combine with self") + } +} diff --git a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListenerTest.java b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListenerTest.java index ec1605fd1..9d63b6ac8 100644 --- a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListenerTest.java +++ b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderListenerTest.java @@ -64,14 +64,13 @@ public class SlowRenderListenerTest { Activity activity; @Mock FrameMetrics frameMetrics; - Tracer tracer; + @Mock JankReporter jankReporter; ScheduledExecutorService executorService; - @Captor ArgumentCaptor activityListenerCaptor; + @Captor ArgumentCaptor activityListenerCaptor; @Before public void setup() { - tracer = otelTesting.getOpenTelemetry().getTracer("testTracer"); executorService = Executors.newSingleThreadScheduledExecutor(); ComponentName componentName = new ComponentName("io.otel", "Komponent"); when(activity.getComponentName()).thenReturn(componentName); @@ -80,7 +79,8 @@ public void setup() { @Test public void add() { SlowRenderListener testInstance = - new SlowRenderListener(tracer, executorService, frameMetricsHandler, Duration.ZERO); + new SlowRenderListener( + jankReporter, executorService, frameMetricsHandler, Duration.ZERO); testInstance.onActivityResumed(activity); @@ -93,7 +93,8 @@ public void add() { @Test public void removeBeforeAddOk() { SlowRenderListener testInstance = - new SlowRenderListener(tracer, executorService, frameMetricsHandler, Duration.ZERO); + new SlowRenderListener( + jankReporter, executorService, frameMetricsHandler, Duration.ZERO); testInstance.onActivityPaused(activity); @@ -104,7 +105,8 @@ public void removeBeforeAddOk() { @Test public void addAndRemove() { SlowRenderListener testInstance = - new SlowRenderListener(tracer, executorService, frameMetricsHandler, Duration.ZERO); + new SlowRenderListener( + jankReporter, executorService, frameMetricsHandler, Duration.ZERO); testInstance.onActivityResumed(activity); testInstance.onActivityPaused(activity); @@ -120,14 +122,17 @@ public void addAndRemove() { @Test public void removeWithMetrics() { + Tracer tracer = otelTesting.getOpenTelemetry().getTracer("testTracer"); + jankReporter = new SpanBasedJankReporter(tracer); SlowRenderListener testInstance = - new SlowRenderListener(tracer, executorService, frameMetricsHandler, Duration.ZERO); + new SlowRenderListener( + jankReporter, executorService, frameMetricsHandler, Duration.ZERO); testInstance.onActivityResumed(activity); verify(activity.getWindow()) .addOnFrameMetricsAvailableListener(activityListenerCaptor.capture(), any()); - SlowRenderListener.PerActivityListener listener = activityListenerCaptor.getValue(); + PerActivityListener listener = activityListenerCaptor.getValue(); for (long duration : makeSomeDurations()) { when(frameMetrics.getMetric(DRAW_DURATION)).thenReturn(duration); listener.onFrameMetricsAvailable(null, frameMetrics, 0); @@ -152,14 +157,17 @@ public void start() { .when(exec) .scheduleWithFixedDelay(any(), eq(1001L), eq(1001L), eq(TimeUnit.MILLISECONDS)); + Tracer tracer = otelTesting.getOpenTelemetry().getTracer("testTracer"); + jankReporter = new SpanBasedJankReporter(tracer); SlowRenderListener testInstance = - new SlowRenderListener(tracer, exec, frameMetricsHandler, Duration.ofMillis(1001)); + new SlowRenderListener( + jankReporter, exec, frameMetricsHandler, Duration.ofMillis(1001)); testInstance.onActivityResumed(activity); verify(activity.getWindow()) .addOnFrameMetricsAvailableListener(activityListenerCaptor.capture(), any()); - SlowRenderListener.PerActivityListener listener = activityListenerCaptor.getValue(); + PerActivityListener listener = activityListenerCaptor.getValue(); for (long duration : makeSomeDurations()) { when(frameMetrics.getMetric(DRAW_DURATION)).thenReturn(duration); listener.onFrameMetricsAvailable(null, frameMetrics, 0); @@ -173,8 +181,7 @@ public void start() { @Test public void activityListenerSkipsFirstFrame() { - SlowRenderListener.PerActivityListener listener = - new SlowRenderListener.PerActivityListener(null); + PerActivityListener listener = new PerActivityListener(activity); when(frameMetrics.getMetric(FIRST_DRAW_FRAME)).thenReturn(1L); listener.onFrameMetricsAvailable(null, frameMetrics, 99); verify(frameMetrics, never()).getMetric(DRAW_DURATION); diff --git a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentationTest.kt b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentationTest.kt index 973b3880a..4dda30238 100644 --- a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentationTest.kt +++ b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SlowRenderingInstrumentationTest.kt @@ -8,13 +8,17 @@ package io.opentelemetry.android.instrumentation.slowrendering import android.app.Application import androidx.test.ext.junit.runners.AndroidJUnit4 import io.mockk.Called +import io.mockk.MockKAnnotations import io.mockk.Runs import io.mockk.every +import io.mockk.impl.annotations.MockK import io.mockk.just import io.mockk.mockk import io.mockk.slot import io.mockk.verify import io.opentelemetry.android.instrumentation.InstallationContext +import io.opentelemetry.api.logs.Logger +import io.opentelemetry.api.logs.LoggerProvider import io.opentelemetry.sdk.OpenTelemetrySdk import org.assertj.core.api.Assertions.assertThat import org.junit.Before @@ -26,14 +30,23 @@ import java.time.Duration @RunWith(AndroidJUnit4::class) class SlowRenderingInstrumentationTest { private lateinit var slowRenderingInstrumentation: SlowRenderingInstrumentation + + @MockK private lateinit var application: Application + + @MockK private lateinit var openTelemetry: OpenTelemetrySdk + @MockK + private lateinit var logger: Logger + @Before fun setUp() { - application = mockk() - openTelemetry = mockk() + MockKAnnotations.init(this) + val logsBridge: LoggerProvider = mockk() slowRenderingInstrumentation = SlowRenderingInstrumentation() + every { openTelemetry.logsBridge } returns logsBridge + every { logsBridge.get("app.jank") } returns logger } @Test @@ -84,6 +97,18 @@ class SlowRenderingInstrumentationTest { val ctx = InstallationContext(application, openTelemetry, mockk()) slowRenderingInstrumentation.install(ctx) + verify { application.registerActivityLifecycleCallbacks(capture(capturedListener)) } + } + + @Config(sdk = [24, 25]) + @Test + fun `can use legacy span`() { + val capturedListener = slot() + every { openTelemetry.getTracer(any()) }.returns(mockk()) + every { application.registerActivityLifecycleCallbacks(any()) } just Runs + val ctx = InstallationContext(application, openTelemetry, mockk()) + slowRenderingInstrumentation.enableDeprecatedZeroDurationSpan().install(ctx) + verify { openTelemetry.getTracer("io.opentelemetry.slow-rendering") } verify { application.registerActivityLifecycleCallbacks(capture(capturedListener)) } } diff --git a/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SpanBasedJankReporterTest.kt b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SpanBasedJankReporterTest.kt new file mode 100644 index 000000000..94336b07b --- /dev/null +++ b/instrumentation/slowrendering/src/test/java/io/opentelemetry/android/instrumentation/slowrendering/SpanBasedJankReporterTest.kt @@ -0,0 +1,91 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.android.instrumentation.slowrendering + +import android.util.Log +import io.mockk.every +import io.mockk.mockkStatic +import io.opentelemetry.api.common.AttributeKey +import io.opentelemetry.api.trace.Tracer +import io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions +import io.opentelemetry.sdk.testing.junit4.OpenTelemetryRule +import io.opentelemetry.sdk.trace.data.SpanData +import org.assertj.core.api.Assertions.assertThat +import org.assertj.core.api.ThrowingConsumer +import org.junit.Rule +import org.junit.jupiter.api.BeforeEach +import org.junit.jupiter.api.Test + +private val COUNT_KEY = AttributeKey.longKey("count") + +class SpanBasedJankReporterTest { + private lateinit var tracer: Tracer + + @Rule + var otelTesting: OpenTelemetryRule = OpenTelemetryRule.create() + + @BeforeEach + fun setup() { + tracer = otelTesting.openTelemetry.getTracer("testTracer") + } + + @Test + fun `spans are generated`() { + val jankReporter = SpanBasedJankReporter(tracer) + val histogramData = HashMap() + histogramData[17] = 3 + histogramData[701] = 1 + mockkStatic(Log::class) + every { Log.d(any(), any()) } returns 0 + + jankReporter.reportSlow(histogramData, 0.1, "io.otel/Komponent") + + assertSpanContent(otelTesting.spans) + } + + @Test + fun `no spans created when no slow frames`() { + val jankReporter = SpanBasedJankReporter(tracer) + val histogramData = HashMap() + histogramData[3] = 3 + histogramData[8] = 1 + mockkStatic(Log::class) + every { Log.d(any(), any()) } returns 0 + + jankReporter.reportSlow(histogramData, 0.1, "") + + assertThat(otelTesting.spans.size).isZero + } + + private fun assertSpanContent(spans: MutableList?) { + assertThat(spans) + .hasSize(2) + .satisfiesExactly( + ThrowingConsumer { span: SpanData? -> + OpenTelemetryAssertions + .assertThat(span) + .hasName("slowRenders") + .endsAt(span!!.getStartEpochNanos()) + .hasAttribute(COUNT_KEY, 3L) + .hasAttribute( + AttributeKey.stringKey("activity.name"), + "io.otel/Komponent", + ) + }, + ThrowingConsumer { span: SpanData? -> + OpenTelemetryAssertions + .assertThat(span) + .hasName("frozenRenders") + .endsAt(span!!.getStartEpochNanos()) + .hasAttribute(COUNT_KEY, 1L) + .hasAttribute( + AttributeKey.stringKey("activity.name"), + "io.otel/Komponent", + ) + }, + ) + } +}