From 79cb480ea4e87a0a75c4d0fd243d2fef40a51e74 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 18 Apr 2026 20:46:53 +0000 Subject: [PATCH] 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 --- .../service/okhttp/MediaCallEventListener.kt | 174 ++++++++++++++++++ .../service/okhttp/OkHttpClientFactory.kt | 1 + 2 files changed, 175 insertions(+) create mode 100644 amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/MediaCallEventListener.kt diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/MediaCallEventListener.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/MediaCallEventListener.kt new file mode 100644 index 0000000000..18875d661a --- /dev/null +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/MediaCallEventListener.kt @@ -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, + ) { + 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) +} diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/OkHttpClientFactory.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/OkHttpClientFactory.kt index e409c6c5e6..61f3255f62 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/OkHttpClientFactory.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/okhttp/OkHttpClientFactory.kt @@ -63,6 +63,7 @@ class OkHttpClientFactory( .Builder() .dispatcher(dispatcher) .connectionPool(connectionPool) + .eventListenerFactory(MediaCallEventListenerFactory(dispatcher, connectionPool)) .followRedirects(true) .followSslRedirects(true) .addInterceptor(DefaultContentTypeInterceptor(userAgent))