perf(media-http): log phase timings and dispatcher queuing

Adds MediaCallEventListener on the images/videos OkHttpClient. For each
call it records DNS, TCP, TLS, TTFB, total time, connection reuse, and
the dispatcher queue depth at call start.

Release builds log only when a call is slow (>= 1.5s), was queued by
the dispatcher (saturation of maxRequests / maxRequestsPerHost), or
failed. Debug builds log every call.

Purpose: give us signal on whether the new 16/host + 128/total limits
are still the ceiling, and whether remaining latency is DNS, TLS, or
server-side.

https://claude.ai/code/session_01PUbqGyUc6oq6V1MdmLi8sw
This commit is contained in:
Claude
2026-04-18 20:46:53 +00:00
parent 9cca64f6ac
commit 79cb480ea4
2 changed files with 175 additions and 0 deletions
@@ -0,0 +1,174 @@
/*
* Copyright (c) 2025 Vitor Pamplona
*
* Permission is hereby granted, free of charge, to any person obtaining a copy of
* this software and associated documentation files (the "Software"), to deal in
* the Software without restriction, including without limitation the rights to use,
* copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the
* Software, and to permit persons to whom the Software is furnished to do so,
* subject to the following conditions:
*
* The above copyright notice and this permission notice shall be included in all
* copies or substantial portions of the Software.
*
* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
* IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS
* FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
* COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN
* AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
* WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
*/
package com.vitorpamplona.amethyst.service.okhttp
import com.vitorpamplona.amethyst.isDebug
import com.vitorpamplona.quartz.utils.Log
import okhttp3.Call
import okhttp3.ConnectionPool
import okhttp3.Dispatcher
import okhttp3.EventListener
import okhttp3.Handshake
import okhttp3.Protocol
import java.io.IOException
import java.net.InetAddress
import java.net.InetSocketAddress
import java.net.Proxy
/**
* Records phase timings per call so we can see when media loads are slow
* because of DNS, TCP, TLS, first-byte, or because the dispatcher queued
* the call (i.e. we hit maxRequestsPerHost / maxRequests).
*
* Release builds log only slow calls, queued calls, and errors. Debug
* builds log every completed call.
*/
class MediaCallEventListener(
private val dispatcher: Dispatcher,
private val connectionPool: ConnectionPool,
) : EventListener() {
private var callStartNanos = 0L
private var dnsStartNanos = 0L
private var dnsElapsedMs = -1L
private var connectStartNanos = 0L
private var connectElapsedMs = -1L
private var secureStartNanos = 0L
private var secureElapsedMs = -1L
private var responseHeadersNanos = 0L
// stays true unless connectStart fires (a new connection was needed)
private var connectionReused = true
private var queuedAtStart = 0
override fun callStart(call: Call) {
callStartNanos = System.nanoTime()
queuedAtStart = dispatcher.queuedCallsCount()
}
override fun dnsStart(
call: Call,
domainName: String,
) {
dnsStartNanos = System.nanoTime()
}
override fun dnsEnd(
call: Call,
domainName: String,
inetAddressList: List<InetAddress>,
) {
dnsElapsedMs = (System.nanoTime() - dnsStartNanos) / 1_000_000
}
override fun connectStart(
call: Call,
inetSocketAddress: InetSocketAddress,
proxy: Proxy,
) {
connectStartNanos = System.nanoTime()
connectionReused = false
}
override fun connectEnd(
call: Call,
inetSocketAddress: InetSocketAddress,
proxy: Proxy,
protocol: Protocol?,
) {
connectElapsedMs = (System.nanoTime() - connectStartNanos) / 1_000_000
}
override fun secureConnectStart(call: Call) {
secureStartNanos = System.nanoTime()
}
override fun secureConnectEnd(
call: Call,
handshake: Handshake?,
) {
secureElapsedMs = (System.nanoTime() - secureStartNanos) / 1_000_000
}
override fun responseHeadersStart(call: Call) {
responseHeadersNanos = System.nanoTime()
}
override fun callEnd(call: Call) = finish(call, null)
override fun callFailed(
call: Call,
ioe: IOException,
) = finish(call, ioe)
private fun finish(
call: Call,
error: IOException?,
) {
val totalMs = (System.nanoTime() - callStartNanos) / 1_000_000
val isSlow = totalMs >= SLOW_CALL_THRESHOLD_MS
val wasQueued = queuedAtStart > 0
if (error == null && !isSlow && !wasQueued && !isDebug) return
val ttfbMs = if (responseHeadersNanos > 0) (responseHeadersNanos - callStartNanos) / 1_000_000 else -1L
val host = call.request().url.host
val reuseTag = if (connectionReused) "reused" else "new"
val msg =
buildString {
append(host)
append(" total=").append(totalMs).append("ms")
append(" ttfb=").append(ttfbMs).append("ms")
append(" conn=").append(reuseTag)
if (!connectionReused) {
if (dnsElapsedMs >= 0) append(" dns=").append(dnsElapsedMs).append("ms")
if (connectElapsedMs >= 0) append(" tcp=").append(connectElapsedMs).append("ms")
if (secureElapsedMs >= 0) append(" tls=").append(secureElapsedMs).append("ms")
}
if (wasQueued) {
append(" QUEUED(depth=").append(queuedAtStart)
append(" running=").append(dispatcher.runningCallsCount())
append(" pool=").append(connectionPool.connectionCount())
append('/').append(connectionPool.idleConnectionCount())
append(')')
}
if (error != null) append(" error=").append(error.javaClass.simpleName).append(':').append(error.message)
}
when {
error != null -> Log.w(TAG, msg)
isSlow || wasQueued -> Log.i(TAG, msg)
else -> Log.d(TAG, msg)
}
}
companion object {
const val TAG = "MediaHttp"
const val SLOW_CALL_THRESHOLD_MS = 1500L
}
}
class MediaCallEventListenerFactory(
private val dispatcher: Dispatcher,
private val connectionPool: ConnectionPool,
) : EventListener.Factory {
override fun create(call: Call): EventListener = MediaCallEventListener(dispatcher, connectionPool)
}
@@ -63,6 +63,7 @@ class OkHttpClientFactory(
.Builder()
.dispatcher(dispatcher)
.connectionPool(connectionPool)
.eventListenerFactory(MediaCallEventListenerFactory(dispatcher, connectionPool))
.followRedirects(true)
.followSslRedirects(true)
.addInterceptor(DefaultContentTypeInterceptor(userAgent))