Ktorでスローレスポンスを検知する

前提

ktor: 2.3.9

動機

SQLでは、スロークエリというものがあって、検知する仕組みがあったりしますが（JDBCだと、net.ttddyy:datasource-proxyとか）、WebServerとしてのレスポンスが遅い場合を検知する仕組みは、Webフレームワーク毎に実装しないといけませんね。
ボトルネックがDBではない場合に、問題に気づくために、スローレスポンスを検知する仕組みを作りました。
今回は、Ktorで実装してみました。

作り方

もし、仮に、１時間かかるリクエストの場合、１時間後に遅いということが分かるのはダメで、スローレスポンスと判定した時点で、アラートを出すようにしたいですね。
なので、launchで（非同期処理の結果が欲しいわけではないためasyncは使わない）、delayを使って、スローレスポンスの閾値を超えたら、アラートを出すようにしました。
CallIdを使って、リクエストを特定します。CallIdは、MDCなどでログに出力するようにしてください。このスローレスポンスと紐付けができるようにするためです。

CallId | Ktor

で、実装例です。以下のように実装しました。

import io.ktor.server.application.createApplicationPlugin
import io.ktor.server.application.hooks.CallSetup
import io.ktor.server.application.hooks.ResponseSent
import io.ktor.server.plugins.callid.callId
import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.delay
import kotlinx.coroutines.launch
import java.util.concurrent.ConcurrentSkipListSet

/**
 * SlowResponseLogPlugin.
 * dependent to [io.ktor.server.plugins.callid.callId]
 */
val SlowResponseLogPlugin = createApplicationPlugin(name = "SlowResponseLogPlugin") {
    val log = org.slf4j.LoggerFactory.getLogger("SlowResponseLogPlugin")
    val callIdSet = ConcurrentSkipListSet<String>()

    val slowResponseThresholdTime = 5_000L

    on(CallSetup) { call ->
        log.trace("CallSetup")
        val callId = requireNotNull(call.callId)
        callIdSet.add(callId)

        CoroutineScope(Dispatchers.Default).launch {
            delay(slowResponseThresholdTime)
            log.trace("completed delay")
            if(callIdSet.contains(callId)) {
                log.warn("Slow response: callId: $callId")
                callIdSet.remove(callId)
            }
        }
    }
    on(ResponseSent) { call ->
        log.trace("ResponseSent callId: ${call.callId}")
        call.callId?.let { callId ->
            callIdSet.remove(callId)
        }
    }
}