diff --git a/embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/testcases/TracingApiTest.kt b/embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/testcases/TracingApiTest.kt index 35e71b7845..2a0189f980 100644 --- a/embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/testcases/TracingApiTest.kt +++ b/embrace-android-sdk/src/integrationTest/kotlin/io/embrace/android/embracesdk/testcases/TracingApiTest.kt @@ -15,7 +15,6 @@ import io.embrace.android.embracesdk.spans.EmbraceSpanEvent import io.embrace.android.embracesdk.spans.ErrorCode import io.opentelemetry.api.trace.SpanId import io.opentelemetry.api.trace.StatusCode -import org.junit.Assert.assertEquals import org.junit.Assert.assertSame import org.junit.Assert.assertTrue import org.junit.Before @@ -116,9 +115,7 @@ internal class TracingApiTest { embrace.endAppStartup() } results.add("\nSpans exported after session ends: ${spanExporter.exportedSpans.toList().map { it.name }}") - assertTrue("Timed out waiting for the expected spans: $results", spanExporter.awaitSpanExport(9)) val sessionEndTime = harness.fakeClock.now() - assertEquals(2, harness.fakeDeliveryModule.deliveryService.lastSentSessions.size) val allSpans = getSdkInitSpanFromBackgroundActivity() + checkNotNull(sessionMessage?.spans) + checkNotNull(harness.openTelemetryModule.spanSink.completedSpans()) diff --git a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/AppStartupTraceEmitter.kt b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/AppStartupTraceEmitter.kt index 3febd1ae72..55be74e8f7 100644 --- a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/AppStartupTraceEmitter.kt +++ b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/capture/startup/AppStartupTraceEmitter.kt @@ -8,8 +8,10 @@ import io.embrace.android.embracesdk.internal.spans.toEmbraceAttributeName import io.embrace.android.embracesdk.internal.utils.Provider import io.embrace.android.embracesdk.internal.utils.VersionChecker import io.embrace.android.embracesdk.logging.InternalEmbraceLogger +import io.embrace.android.embracesdk.spans.EmbraceSpan import io.embrace.android.embracesdk.worker.BackgroundWorker import io.opentelemetry.sdk.common.Clock +import java.util.concurrent.ConcurrentLinkedQueue import java.util.concurrent.atomic.AtomicBoolean /** @@ -42,6 +44,7 @@ internal class AppStartupTraceEmitter( ) { private val processCreateRequestedMs: Long? private val processCreatedMs: Long? + private val additionalTrackedIntervals = ConcurrentLinkedQueue() init { val timestampAtDeviceStart = nowMs() - clock.nanoTime().nanosToMillis() @@ -110,6 +113,12 @@ internal class AppStartupTraceEmitter( } } + fun addTrackedInterval(name: String, startTimeMs: Long, endTimeMs: Long) { + additionalTrackedIntervals.add( + TrackedInterval(name = name, startTimeMs = startTimeMs, endTimeMs = endTimeMs) + ) + } + private fun dataCollectionComplete() { if (!startupRecorded.get()) { synchronized(startupRecorded) { @@ -147,8 +156,9 @@ internal class AppStartupTraceEmitter( if (processStartTimeMs != null && traceEndTimeMs != null) { val gap = applicationActivityCreationGap() ?: duration(sdkInitEndMs, startupActivityInitStartMs) if (gap != null) { - if (!spanService.initialized()) { + val startupTrace: EmbraceSpan? = if (!spanService.initialized()) { logger.logWarning("Startup trace not recorded because the spans service is not initialized") + null } else if (gap <= SDK_AND_ACTIVITY_INIT_GAP) { recordColdTtid( traceStartTimeMs = processStartTimeMs, @@ -172,10 +182,27 @@ internal class AppStartupTraceEmitter( ) } } + + if (startupTrace != null) { + recordAdditionalIntervals(startupTrace) + } } } } + private fun recordAdditionalIntervals(startupTrace: EmbraceSpan) { + do { + additionalTrackedIntervals.poll()?.let { trackedInterval -> + spanService.recordCompletedSpan( + name = trackedInterval.name, + parent = startupTrace, + startTimeMs = trackedInterval.startTimeMs, + endTimeMs = trackedInterval.endTimeMs, + ) + } + } while (additionalTrackedIntervals.isNotEmpty()) + } + @Suppress("CyclomaticComplexMethod", "ComplexMethod") private fun recordColdTtid( traceStartTimeMs: Long, @@ -186,12 +213,12 @@ internal class AppStartupTraceEmitter( activityInitEndMs: Long?, traceEndTimeMs: Long, processCreateDelay: Long?, - ) { - if (!startupRecorded.get()) { + ): EmbraceSpan? { + return if (!startupRecorded.get()) { spanService.startSpan( name = "cold-time-to-initial-display", startTimeMs = traceStartTimeMs, - )?.run { + )?.apply { processCreateDelay?.let { delay -> addAttribute("process-create-delay-ms".toEmbraceAttributeName(), delay.toString()) } @@ -246,6 +273,8 @@ internal class AppStartupTraceEmitter( ) } } + } else { + null } } @@ -256,12 +285,12 @@ internal class AppStartupTraceEmitter( processCreateDelay: Long?, processToActivityCreateGap: Long?, sdkStartupDuration: Long?, - ) { - if (!startupRecorded.get()) { + ): EmbraceSpan? { + return if (!startupRecorded.get()) { spanService.startSpan( name = "warm-time-to-initial-display", startTimeMs = traceStartTimeMs, - )?.run { + )?.apply { processCreateDelay?.let { delay -> addAttribute("process-create-delay-ms".toEmbraceAttributeName(), delay.toString()) } @@ -294,6 +323,8 @@ internal class AppStartupTraceEmitter( ) } } + } else { + null } } @@ -303,6 +334,12 @@ internal class AppStartupTraceEmitter( private fun nowMs(): Long = clock.now().nanosToMillis() + private data class TrackedInterval( + val name: String, + val startTimeMs: Long, + val endTimeMs: Long, + ) + companion object { /** * The gap between the end of the Embrace SDK initialization to when the first activity loaded after startup happens. diff --git a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/behavior/SdkModeBehavior.kt b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/behavior/SdkModeBehavior.kt index 3c030a5c58..698e6ac1f8 100644 --- a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/behavior/SdkModeBehavior.kt +++ b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/behavior/SdkModeBehavior.kt @@ -29,6 +29,12 @@ internal class SdkModeBehavior( */ private const val DEFAULT_BETA_FEATURES_PCT = 1.0f + /** + * The percentage of devices that defer some expensive service initialization to a background + * thread to improve startup performance in exchange for delayed enablement of some features of the SDK + */ + private const val DEFAULT_DEFER_SERVICE_INIT_PCT = 0.0f + /** * The default percentage of devices for which the SDK is enabled. */ @@ -58,6 +64,14 @@ internal class SdkModeBehavior( return thresholdCheck.isBehaviorEnabled(pct) } + /** + * Checks if an expanded list of services' initialization during startup will be done on a background thread + */ + fun isServiceInitDeferred(): Boolean { + val pct = remote?.pctDeferServiceInitEnabled ?: DEFAULT_DEFER_SERVICE_INIT_PCT + return thresholdCheck.isBehaviorEnabled(pct) + } + /** * The Embrace app ID. This is used to identify the app within the database. */ diff --git a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/remote/RemoteConfig.kt b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/remote/RemoteConfig.kt index 74bef0938a..0bf004c729 100644 --- a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/remote/RemoteConfig.kt +++ b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/config/remote/RemoteConfig.kt @@ -108,5 +108,12 @@ internal data class RemoteConfig( * Web view vitals settings */ @Json(name = "webview_vitals_beta") - val webViewVitals: WebViewVitals? = null + val webViewVitals: WebViewVitals? = null, + + /** + * Enable deferral of initialization of some services to a background thread during startup. + * Currently, the only feature that uses this is native crash capture + */ + @Json(name = "pct_defer_service_init") + val pctDeferServiceInitEnabled: Float? = null, ) diff --git a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/injection/ModuleInitBootstrapper.kt b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/injection/ModuleInitBootstrapper.kt index 1d4e76daf0..54340d0c16 100644 --- a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/injection/ModuleInitBootstrapper.kt +++ b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/injection/ModuleInitBootstrapper.kt @@ -38,6 +38,7 @@ import java.util.Locale import java.util.concurrent.Future import java.util.concurrent.TimeUnit import java.util.concurrent.atomic.AtomicReference +import kotlin.math.max import kotlin.reflect.KClass /** @@ -117,6 +118,12 @@ internal class ModuleInitBootstrapper( private val asyncInitTask = AtomicReference?>(null) + @Volatile + private var synchronousInitCompletionMs: Long = -1L + + @Volatile + private var asyncInitCompletionMs: Long = -1L + /** * Returns true when the call has triggered an initialization, false if initialization is already in progress or is complete. */ @@ -146,6 +153,7 @@ internal class ModuleInitBootstrapper( Systrace.traceSynchronous("span-service-init") { openTelemetryModule.spanService.initializeService(sdkStartTimeMs) } + asyncInitCompletionMs = initModule.clock.now() } } @@ -320,8 +328,18 @@ internal class ModuleInitBootstrapper( } postInit(NativeModule::class) { + val ndkService = nativeModule.ndkService + val initWorkerTaskQueueTime = initModule.clock.now() + workerThreadModule.backgroundWorker(WorkerName.SERVICE_INIT).submit { + val taskRuntimeMs = initModule.clock.now() + dataCaptureServiceModule.appStartupTraceEmitter.addTrackedInterval( + name = "init-worker-schedule-delay", + startTimeMs = initWorkerTaskQueueTime, + endTimeMs = taskRuntimeMs + ) + } serviceRegistry.registerServices( - nativeModule.ndkService, + ndkService, nativeModule.nativeThreadSamplerService ) @@ -449,6 +467,7 @@ internal class ModuleInitBootstrapper( serviceRegistry.registerActivityLifecycleListeners(essentialServiceModule.activityLifecycleTracker) asyncInitTask.set(initTask) + synchronousInitCompletionMs = initModule.clock.now() true } else { false @@ -464,11 +483,26 @@ internal class ModuleInitBootstrapper( * [Future] if there is a timeout or if this failed for other reasons. */ @JvmOverloads - fun waitForAsyncInit(timeout: Long = 5L, unit: TimeUnit = TimeUnit.SECONDS) = + fun waitForAsyncInit(timeout: Long = 5L, unit: TimeUnit = TimeUnit.SECONDS) { Systrace.traceSynchronous("async-init-wait") { asyncInitTask.get()?.get(timeout, unit) } + Systrace.traceSynchronous("record-delay") { + // If async init finished after synchronous init, there's a delay so record that delay + // Otherwise, record a 0-duration span to signify there was no significant wait + val delayStartMs = synchronousInitCompletionMs + val delayEndMs = max(synchronousInitCompletionMs, asyncInitCompletionMs) + if (delayStartMs > 0) { + dataCaptureServiceModule.appStartupTraceEmitter.addTrackedInterval( + name = "async-init-delay", + startTimeMs = delayStartMs, + endTimeMs = delayEndMs + ) + } + } + } + fun stopServices() { if (isInitialized()) { return diff --git a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/ndk/EmbraceNdkService.kt b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/ndk/EmbraceNdkService.kt index c6d4152be8..26d6e95364 100644 --- a/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/ndk/EmbraceNdkService.kt +++ b/embrace-android-sdk/src/main/java/io/embrace/android/embracesdk/ndk/EmbraceNdkService.kt @@ -92,15 +92,12 @@ internal class EmbraceNdkService( // thread doing this when the native ANR monitoring tries to load this // Remove this once the native ANR initialization is done on the background thread too. sharedObjectLoader.loadEmbraceNative() - highPriorityWorker.submit { - Systrace.traceSynchronous("init-ndk-service") { - processStateService.addListener(this) - if (appFramework == AppFramework.UNITY) { - unityCrashId = getEmbUuid() - } - startNativeCrashMonitoring() - cleanOldCrashFiles() + if (configService.sdkModeBehavior.isServiceInitDeferred()) { + highPriorityWorker.submit { + initializeService(processStateService, appFramework) } + } else { + initializeService(processStateService, appFramework) } } } @@ -388,6 +385,20 @@ internal class EmbraceNdkService( return symbolsForArch.value } + private fun initializeService( + processStateService: ProcessStateService, + appFramework: AppFramework + ) { + Systrace.traceSynchronous("init-ndk-service") { + processStateService.addListener(this) + if (appFramework == AppFramework.UNITY) { + unityCrashId = getEmbUuid() + } + startNativeCrashMonitoring() + cleanOldCrashFiles() + } + } + @SuppressLint("DiscouragedApi") private fun getNativeSymbols(): NativeSymbols? { val resources = context.resources