Skip to content

Commit 3a15984

Browse files
PriveeteePriveetee
committed
perf: trace SABR startup across services
1 parent 3fc97a1 commit 3a15984

7 files changed

Lines changed: 75 additions & 7 deletions

File tree

‎server-core/src/main/kotlin/dev/typetype/server/PlaybackTraceLog.kt‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
package dev.typetype.server
2+
3+
object PlaybackTraceLog {
4+
private val logger = System.getLogger(PlaybackTraceLog::class.java.name)
5+
6+
fun record(event: String, fields: String = "") {
7+
record(currentPlaybackTraceId(), currentRequestId(), event, fields)
8+
}
9+
10+
fun record(traceId: String?, requestId: String?, event: String, fields: String = "") {
11+
if (traceId == null) return
12+
logger.log(
13+
System.Logger.Level.INFO,
14+
"playback_trace traceId={0} requestId={1} event={2} {3}",
15+
traceId, requestId ?: "unknown", event, fields,
16+
)
17+
}
18+
}

‎server-core/src/main/kotlin/dev/typetype/server/RequestContext.kt‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,13 +1,16 @@
11
package dev.typetype.server
22

3-
import kotlinx.coroutines.ThreadContextElement
43
import kotlinx.coroutines.asContextElement
4+
import kotlin.coroutines.CoroutineContext
55

66
private val requestIdContext = ThreadLocal<String?>()
7+
private val playbackTraceIdContext = ThreadLocal<String?>()
78

89
const val REQUEST_ID_HEADER = "X-Request-ID"
10+
const val PLAYBACK_TRACE_ID_HEADER = "X-Playback-Trace-ID"
911

1012
fun currentRequestId(): String? = requestIdContext.get()
13+
fun currentPlaybackTraceId(): String? = playbackTraceIdContext.get()
1114

12-
fun requestContextElement(requestId: String?): ThreadContextElement<String?> =
13-
requestIdContext.asContextElement(requestId)
15+
fun requestContextElement(requestId: String?, playbackTraceId: String?): CoroutineContext =
16+
requestIdContext.asContextElement(requestId) + playbackTraceIdContext.asContextElement(playbackTraceId)

‎server-http/src/main/kotlin/dev/typetype/server/routes/SabrPlaybackHandler.kt‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@ import dev.typetype.server.services.SabrPlaybackSegmentResult
1212
import dev.typetype.server.services.SabrPlaybackSessionService
1313
import dev.typetype.server.services.SabrPlaybackInfoResolver
1414
import dev.typetype.server.services.SabrSessionHolder
15+
import dev.typetype.server.PlaybackTraceLog
1516
import dev.typetype.server.services.SabrSessionStore
1617
import dev.typetype.server.services.StreamService
1718
import dev.typetype.server.services.markServed
@@ -39,10 +40,13 @@ internal class SabrPlaybackHandler(
3940
if (!validateAccess(call, videoId, access)) return
4041
val request = call.playbackRequest()
4142
val startTimeMs = request.effectiveStartTimeMs()
43+
val infoStartedAt = System.nanoTime()
4244
val prepared = infoResolver.initial(access.userId, videoId, startTimeMs)
43-
?: return call.respond(HttpStatusCode.UnprocessableEntity, ErrorResponse("SABR probe failed"))
45+
PlaybackTraceLog.record("sabr_info", "durationMs=${(System.nanoTime() - infoStartedAt) / 1_000_000} result=${if (prepared == null) "miss" else "ready"} startTimeMs=$startTimeMs")
46+
prepared ?: return call.respond(HttpStatusCode.UnprocessableEntity, ErrorResponse("SABR probe failed"))
4447
val audio = selectAudio(call, prepared, request) ?: return
4548
val video = selectVideo(call, prepared, request) ?: return
49+
val prepareStartedAt = System.nanoTime()
4650
val preparation = playbackService.prepare(
4751
videoId = videoId,
4852
userId = access.userId ?: videoId,
@@ -53,6 +57,7 @@ internal class SabrPlaybackHandler(
5357
audioOnly = request.audioOnly,
5458
isLive = request.isLive,
5559
)
60+
PlaybackTraceLog.record("sabr_session_prepare", "durationMs=${(System.nanoTime() - prepareStartedAt) / 1_000_000} ready=${preparation.ready} startTimeMs=${preparation.startTimeMs}")
5661
preparation.holder.setActiveTracks(videoActive = !request.audioOnly, audioActive = true)
5762
respondPrepared(call, preparation.holder, videoId, preparation.startTimeMs, preparation.ready)
5863
}

‎server-services/src/main/kotlin/dev/typetype/server/AppMetrics.kt‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,8 @@ object AppMetrics {
5151
}
5252

5353
fun metricPath(path: String): String = when {
54+
path.startsWith("/api/sabr/playback/") -> "/api/sabr/playback/{sessionId}"
55+
path.startsWith("/sabr/playback/") -> "/sabr/playback/{sessionId}"
5456
path.startsWith("/downloader/jobs/") && path.endsWith("/events") -> "/downloader/jobs/{id}/events"
5557
path.startsWith("/downloader/jobs/") && path.endsWith("/artifact") -> "/downloader/jobs/{id}/artifact"
5658
path.startsWith("/downloader/jobs/") && path.endsWith("/cancel") -> "/downloader/jobs/{id}/cancel"

‎server-services/src/main/kotlin/dev/typetype/server/RequestObservability.kt‎

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,13 +25,18 @@ fun Application.installRequestObservability() {
2525
intercept(ApplicationCallPipeline.Setup) {
2626
val applicationCall = context
2727
val requestId = resolveRequestId(applicationCall.request.headers[REQUEST_ID_HEADER])
28+
val traceId = resolvePlaybackTraceId(applicationCall.request.headers[PLAYBACK_TRACE_ID_HEADER])
2829
applicationCall.attributes.put(requestIdAttribute, requestId)
2930
applicationCall.attributes.put(requestStartNanosAttribute, System.nanoTime())
3031
applicationCall.response.headers.append(REQUEST_ID_HEADER, requestId, safeOnly = false)
31-
withContext(requestContextElement(requestId)) {
32+
traceId?.let { applicationCall.response.headers.append(PLAYBACK_TRACE_ID_HEADER, it, safeOnly = false) }
33+
withContext(requestContextElement(requestId, traceId)) {
3234
try {
3335
proceed()
3436
} finally {
37+
traceId?.let {
38+
PlaybackTraceLog.record(it, requestId, "http_complete", "method=${applicationCall.request.httpMethod.value} route=${metricPath(applicationCall.request.path())} status=${applicationCall.response.status()?.value ?: 0} durationMs=${applicationCall.requestDurationMs()}")
39+
}
3540
AppMetrics.record(applicationCall)
3641
}
3742
}
@@ -49,5 +54,8 @@ fun requestLogLine(call: ApplicationCall): String = listOf(
4954
private fun resolveRequestId(raw: String?): String =
5055
raw?.takeIf { requestIdRegex.matches(it) } ?: UUID.randomUUID().toString()
5156

57+
private fun resolvePlaybackTraceId(raw: String?): String? =
58+
raw?.takeIf { requestIdRegex.matches(it) }
59+
5260
private fun <T : Any> ApplicationCall.attributeOrNull(key: AttributeKey<T>): T? =
5361
if (attributes.contains(key)) attributes[key] else null

‎server-token-gateway/src/main/kotlin/dev/typetype/server/services/TypetypeTokenSabrTokenClient.kt‎

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,11 @@ import okhttp3.MediaType.Companion.toMediaType
55
import okhttp3.Request
66
import okhttp3.RequestBody.Companion.toRequestBody
77
import org.json.JSONObject
8+
import dev.typetype.server.PLAYBACK_TRACE_ID_HEADER
9+
import dev.typetype.server.REQUEST_ID_HEADER
10+
import dev.typetype.server.PlaybackTraceLog
11+
import dev.typetype.server.currentPlaybackTraceId
12+
import dev.typetype.server.currentRequestId
813
import java.net.URLEncoder
914
import java.nio.charset.StandardCharsets
1015

@@ -34,9 +39,15 @@ class TypetypeTokenSabrTokenClient(
3439
val request = Request.Builder()
3540
.url("${tokenServiceUrl.trimEnd('/')}/potoken/session")
3641
.post(body)
42+
.apply {
43+
currentRequestId()?.let { header(REQUEST_ID_HEADER, it) }
44+
currentPlaybackTraceId()?.let { header(PLAYBACK_TRACE_ID_HEADER, it) }
45+
}
3746
.build()
47+
val startedAt = System.nanoTime()
3848
return try {
3949
client.newCall(request).execute().use { response ->
50+
PlaybackTraceLog.record("token_http", "endpoint=potoken_session status=${response.code} durationMs=${(System.nanoTime() - startedAt) / 1_000_000}")
4051
if (!response.isSuccessful) return null
4152
SabrTokenBundle.fromSessionResponse(videoId, sessionBinding, JSONObject(response.body.string()))
4253
}
@@ -56,8 +67,14 @@ class TypetypeTokenSabrTokenClient(
5667
): SabrTokenBundle? {
5768
val url = buildUrl(binding, forceRefresh, refreshVideo)
5869
val target = if (logIdentifier) " for $binding" else " for session binding"
70+
val startedAt = System.nanoTime()
71+
val request = Request.Builder().url(url).get().apply {
72+
currentRequestId()?.let { header(REQUEST_ID_HEADER, it) }
73+
currentPlaybackTraceId()?.let { header(PLAYBACK_TRACE_ID_HEADER, it) }
74+
}.build()
5975
return try {
60-
client.newCall(Request.Builder().url(url).get().build()).execute().use { resp ->
76+
client.newCall(request).execute().use { resp ->
77+
PlaybackTraceLog.record("token_http", "endpoint=potoken status=${resp.code} durationMs=${(System.nanoTime() - startedAt) / 1_000_000}")
6178
if (!resp.isSuccessful) {
6279
System.err.println("[TypetypeTokenSabrTokenClient] /potoken HTTP ${resp.code}$target")
6380
return null

‎server-token-gateway/src/main/kotlin/dev/typetype/server/services/TypetypeTokenYoutubeSessionClient.kt‎

Lines changed: 16 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,11 @@ import okhttp3.Response
1111
import org.json.JSONObject
1212
import org.schabi.newpipe.extractor.services.youtube.YoutubeParsingHelper
1313
import dev.typetype.server.sabr.SabrAdapter
14+
import dev.typetype.server.PLAYBACK_TRACE_ID_HEADER
15+
import dev.typetype.server.REQUEST_ID_HEADER
16+
import dev.typetype.server.PlaybackTraceLog
17+
import dev.typetype.server.currentPlaybackTraceId
18+
import dev.typetype.server.currentRequestId
1419
import dev.typetype.server.sabr.YoutubeSabrClientProfile
1520
import dev.typetype.server.sabr.YoutubeSabrInfo
1621
import java.io.IOException
@@ -67,17 +72,27 @@ class TypetypeTokenYoutubeSessionClient(
6772
val url = "${tokenServiceUrl.trimEnd('/')}/youtube/sabr/session?videoId=$encodedVideoId&client=MWEB" +
6873
if (isolated) "&isolated=true" else ""
6974
return suspendCancellableCoroutine { continuation ->
70-
val call = client.newCall(Request.Builder().url(url).get().build())
75+
val requestBuilder = Request.Builder().url(url).get()
76+
currentRequestId()?.let { requestBuilder.header(REQUEST_ID_HEADER, it) }
77+
currentPlaybackTraceId()?.let { requestBuilder.header(PLAYBACK_TRACE_ID_HEADER, it) }
78+
val traceId = currentPlaybackTraceId()
79+
val requestId = currentRequestId()
80+
val startedAt = System.nanoTime()
81+
PlaybackTraceLog.record("token_session_start", "operation=youtube_sabr_session isolated=$isolated")
82+
val call = client.newCall(requestBuilder.build())
7183
continuation.invokeOnCancellation { call.cancel() }
7284
call.enqueue(object : Callback {
7385
override fun onFailure(call: Call, e: IOException) {
86+
PlaybackTraceLog.record(traceId, requestId, "token_session_complete", "status=network_error durationMs=${(System.nanoTime() - startedAt) / 1_000_000}")
7487
if (continuation.isActive) continuation.resume(null)
7588
}
7689

7790
override fun onResponse(call: Call, response: Response) {
91+
val status = response.code
7892
val session = response.use {
7993
if (!it.isSuccessful) null else runCatching { JSONObject(it.body.string()) }.getOrNull()
8094
}
95+
PlaybackTraceLog.record(traceId, requestId, "token_session_complete", "status=$status result=${if (session == null) "empty" else "ok"} durationMs=${(System.nanoTime() - startedAt) / 1_000_000}")
8196
if (continuation.isActive) continuation.resume(session)
8297
}
8398
})

0 commit comments

Comments
 (0)