Skip to content

Commit

Permalink
Add additional metadata to startup traces (#839)
Browse files Browse the repository at this point in the history
## Goal

Adding debugging metadata to app startup traces
  • Loading branch information
bidetofevil committed May 13, 2024
2 parents 303d49b + 91640f2 commit 3ddac16
Show file tree
Hide file tree
Showing 6 changed files with 121 additions and 13 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -87,6 +87,12 @@ internal class AppStartupTraceEmitter(
@Volatile
private var firstFrameRenderedMs: Long? = null

@Volatile
private var sdkInitThreadName: String? = null

@Volatile
private var sdkInitEndedInForeground: Boolean? = null

private val startupRecorded = AtomicBoolean(false)
private val endWithFrameDraw: Boolean = versionChecker.isAtLeast(VERSION_CODES.Q)

Expand Down Expand Up @@ -174,6 +180,9 @@ internal class AppStartupTraceEmitter(
startupActivityResumedMs
}

sdkInitEndedInForeground = startupService.endedInForeground()
sdkInitThreadName = startupService.getInitThreadName()

if (processStartTimeMs != null && traceEndTimeMs != null) {
val gap = applicationActivityCreationGap() ?: duration(sdkInitEndMs, startupActivityInitStartMs)
if (gap != null) {
Expand Down Expand Up @@ -376,6 +385,14 @@ internal class AppStartupTraceEmitter(
startupActivityPostCreatedMs?.let { timeMs ->
addAttribute("startup-activity-post-created-ms", timeMs.toString())
}

sdkInitEndedInForeground?.let { inForeground ->
addAttribute("embrace-init-in-foreground", inForeground.toString())
}

sdkInitThreadName?.let { threadName ->
addAttribute("embrace-init-thread-name", threadName)
}
}

private data class TrackedInterval(
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,12 @@ internal interface StartupService {
/**
* Sets the SDK startup info. This is called when the SDK is initialized.
*/
fun setSdkStartupInfo(startTimeMs: Long, endTimeMs: Long, endedInForeground: Boolean, threadName: String?)
fun setSdkStartupInfo(
startTimeMs: Long,
endTimeMs: Long,
endedInForeground: Boolean,
threadName: String
)

/**
* Returns the SDK startup duration. This is called when the session ends.
Expand All @@ -24,4 +29,14 @@ internal interface StartupService {
* The epoch time in milliseconds of when the SDK startup finished
*/
fun getSdkInitEndMs(): Long?

/**
* Returns true if the SDK init ended when the app is in the foreground, false if in the background, null if startup info not recorded
*/
fun endedInForeground(): Boolean?

/**
* Returns the name of the thread on which the SDK init was run. Returns null if startup info was not recorded yet.
*/
fun getInitThreadName(): String?
}
Original file line number Diff line number Diff line change
Expand Up @@ -15,13 +15,24 @@ internal class StartupServiceImpl(
@Volatile
private var sdkInitEndMs: Long? = null

@Volatile
private var endedInForeground: Boolean? = null

@Volatile
private var threadName: String = "unknown"

/**
* SDK startup time. Only set for cold start sessions.
*/
@Volatile
private var sdkStartupDurationMs: Long? = null

override fun setSdkStartupInfo(startTimeMs: Long, endTimeMs: Long, endedInForeground: Boolean, threadName: String?) {
override fun setSdkStartupInfo(
startTimeMs: Long,
endTimeMs: Long,
endedInForeground: Boolean,
threadName: String
) {
if (sdkStartupDurationMs == null) {
spanService.recordCompletedSpan(
name = "sdk-init",
Expand All @@ -36,6 +47,8 @@ internal class StartupServiceImpl(
}
sdkInitStartMs = startTimeMs
sdkInitEndMs = endTimeMs
this.endedInForeground = endedInForeground
this.threadName = threadName
sdkStartupDurationMs = endTimeMs - startTimeMs
}

Expand All @@ -47,4 +60,8 @@ internal class StartupServiceImpl(
override fun getSdkInitStartMs(): Long? = sdkInitStartMs

override fun getSdkInitEndMs(): Long? = sdkInitEndMs

override fun endedInForeground(): Boolean? = endedInForeground

override fun getInitThreadName(): String? = threadName
}
Original file line number Diff line number Diff line change
Expand Up @@ -206,7 +206,12 @@ internal class AppStartupTraceEmitterTest {
appStartupTraceEmitter.applicationInitEnd()
val applicationInitEnd = clock.now()
clock.tick(50L)
checkNotNull(startupService).setSdkStartupInfo(sdkInitStart, sdkInitEnd, false, "main")
checkNotNull(startupService).setSdkStartupInfo(
startTimeMs = sdkInitStart,
endTimeMs = sdkInitEnd,
endedInForeground = false,
threadName = "main"
)
appStartupTraceEmitter.startupActivityPreCreated()
val startupActivityPreCreated = clock.now()
clock.tick()
Expand Down Expand Up @@ -256,7 +261,12 @@ internal class AppStartupTraceEmitterTest {
clock.tick(30L)
val sdkInitEnd = clock.now()
clock.tick(400L)
checkNotNull(startupService).setSdkStartupInfo(sdkInitStart, sdkInitEnd, false, "main")
checkNotNull(startupService).setSdkStartupInfo(
startTimeMs = sdkInitStart,
endTimeMs = sdkInitEnd,
endedInForeground = false,
threadName = "main"
)
appStartupTraceEmitter.startupActivityPreCreated()
val startupActivityPreCreated = clock.now()
clock.tick()
Expand Down Expand Up @@ -311,7 +321,12 @@ internal class AppStartupTraceEmitterTest {
appStartupTraceEmitter.applicationInitEnd()
val applicationInitEnd = clock.now()
clock.tick(50L)
checkNotNull(startupService).setSdkStartupInfo(sdkInitStart, sdkInitEnd, false, "main")
checkNotNull(startupService).setSdkStartupInfo(
startTimeMs = sdkInitStart,
endTimeMs = sdkInitEnd,
endedInForeground = false,
threadName = "main"
)
appStartupTraceEmitter.startupActivityInitStart()
val startupActivityStart = clock.now()
clock.tick(180L)
Expand Down Expand Up @@ -356,7 +371,12 @@ internal class AppStartupTraceEmitterTest {
clock.tick(30L)
val sdkInitEnd = clock.now()
clock.tick(400L)
checkNotNull(startupService).setSdkStartupInfo(sdkInitStart, sdkInitEnd, false, "main")
checkNotNull(startupService).setSdkStartupInfo(
startTimeMs = sdkInitStart,
endTimeMs = sdkInitEnd,
endedInForeground = false,
threadName = "main"
)
appStartupTraceEmitter.startupActivityInitStart()
val startupActivityStart = clock.now()
clock.tick(180L)
Expand Down Expand Up @@ -398,7 +418,12 @@ internal class AppStartupTraceEmitterTest {
val sdkInitStart = clock.now()
clock.tick(30L)
val sdkInitEnd = clock.now()
checkNotNull(startupService).setSdkStartupInfo(sdkInitStart, sdkInitEnd, false, "main")
checkNotNull(startupService).setSdkStartupInfo(
startTimeMs = sdkInitStart,
endTimeMs = sdkInitEnd,
endedInForeground = false,
threadName = "main"
)
clock.tick(60001L)
appStartupTraceEmitter.startupActivityPreCreated()
val startupActivityPreCreated = clock.now()
Expand Down Expand Up @@ -446,7 +471,12 @@ internal class AppStartupTraceEmitterTest {
val sdkInitStart = clock.now()
clock.tick(30L)
val sdkInitEnd = clock.now()
checkNotNull(startupService).setSdkStartupInfo(sdkInitStart, sdkInitEnd, false, "main")
checkNotNull(startupService).setSdkStartupInfo(
startTimeMs = sdkInitStart,
endTimeMs = sdkInitEnd,
endedInForeground = false,
threadName = "main"
)
clock.tick(60001L)
appStartupTraceEmitter.startupActivityInitStart()
val startupActivityStart = clock.now()
Expand Down Expand Up @@ -493,6 +523,8 @@ internal class AppStartupTraceEmitterTest {
assertEquals(expectedProcessCreateDelayMs?.toString(), trace.attributes["process-create-delay-ms"])
assertEquals(expectedActivityPreCreatedMs?.toString(), trace.attributes["startup-activity-pre-created-ms"])
assertEquals(expectedActivityPostCreatedMs?.toString(), trace.attributes["startup-activity-post-created-ms"])
assertEquals("false", trace.attributes["embrace-init-in-foreground"])
assertEquals("main", trace.attributes["embrace-init-thread-name"])
}

private fun assertChildSpan(span: EmbraceSpanData, expectedStartTimeNanos: Long, expectedEndTimeNanos: Long) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,12 @@ internal class StartupServiceImplTest {
clock.tick(10L)
val endTimeMillis = clock.now()
spanService.initializeService(startTimeMillis)
startupService.setSdkStartupInfo(startTimeMillis, endTimeMillis, false, "main")
startupService.setSdkStartupInfo(
startTimeMs = startTimeMillis,
endTimeMs = endTimeMillis,
endedInForeground = false,
threadName = "main"
)
val currentSpans = spanSink.completedSpans()
assertEquals(1, currentSpans.size)
with(currentSpans[0]) {
Expand All @@ -61,10 +66,23 @@ internal class StartupServiceImplTest {
@Test
fun `second sdk startup span will not be recorded if you try to set the startup info twice`() {
spanService.initializeService(10)
startupService.setSdkStartupInfo(10, 20, false, "main")
startupService.run {
setSdkStartupInfo(
startTimeMs = 10,
endTimeMs = 20,
endedInForeground = false,
threadName = "main"
)
}
assertEquals(1, spanSink.completedSpans().size)
startupService.setSdkStartupInfo(10, 20, false, "main")
startupService.setSdkStartupInfo(10, 20, false, "main")
startupService.run {
setSdkStartupInfo(
startTimeMs = 10,
endTimeMs = 20,
endedInForeground = false,
threadName = "main"
)
}
assertEquals(1, spanSink.completedSpans().size)
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,12 @@ internal class FakeStartupService : StartupService {
var endedInForeground: Boolean? = null
var threadName: String? = null

override fun setSdkStartupInfo(startTimeMs: Long, endTimeMs: Long, endedInForeground: Boolean, threadName: String?) {
override fun setSdkStartupInfo(
startTimeMs: Long,
endTimeMs: Long,
endedInForeground: Boolean,
threadName: String
) {
sdkStartupDuration = endTimeMs - startTimeMs
this.endedInForeground = endedInForeground
this.threadName = threadName
Expand All @@ -25,4 +30,8 @@ internal class FakeStartupService : StartupService {
override fun getSdkInitEndMs(): Long? {
TODO("Not yet implemented")
}

override fun endedInForeground(): Boolean? = endedInForeground

override fun getInitThreadName(): String? = threadName
}

0 comments on commit 3ddac16

Please sign in to comment.