From 8cebf9012bbdfdbad6b833effc545ff5b8b8e48b Mon Sep 17 00:00:00 2001 From: Yuri Schimke Date: Tue, 5 May 2020 18:25:06 +0100 Subject: [PATCH] Cache Events (#6015) Provide EventListener methods to understand the impact of caching. --- .../src/main/kotlin/okhttp3/CallEvent.kt | 20 +++ .../kotlin/okhttp3/ClientRuleEventListener.kt | 24 +++ .../kotlin/okhttp3/RecordingEventListener.kt | 21 +++ .../src/main/kotlin/okhttp3/EventListener.kt | 35 +++++ .../internal/cache/CacheInterceptor.kt | 29 +++- .../okhttp3/internal/connection/RealCall.kt | 2 +- .../test/java/okhttp3/EventListenerTest.java | 143 ++++++++++++++++++ 7 files changed, 269 insertions(+), 5 deletions(-) diff --git a/okhttp-testing-support/src/main/kotlin/okhttp3/CallEvent.kt b/okhttp-testing-support/src/main/kotlin/okhttp3/CallEvent.kt index b3c29ff98..b9abc4f84 100644 --- a/okhttp-testing-support/src/main/kotlin/okhttp3/CallEvent.kt +++ b/okhttp-testing-support/src/main/kotlin/okhttp3/CallEvent.kt @@ -204,4 +204,24 @@ sealed class CallEvent { override val call: Call, val ioe: IOException ) : CallEvent() + + data class SatisfactionFailure( + override val timestampNs: Long, + override val call: Call + ) : CallEvent() + + data class CacheHit( + override val timestampNs: Long, + override val call: Call + ) : CallEvent() + + data class CacheMiss( + override val timestampNs: Long, + override val call: Call + ) : CallEvent() + + data class CacheConditionalHit( + override val timestampNs: Long, + override val call: Call + ) : CallEvent() } diff --git a/okhttp-testing-support/src/main/kotlin/okhttp3/ClientRuleEventListener.kt b/okhttp-testing-support/src/main/kotlin/okhttp3/ClientRuleEventListener.kt index 5dad5faaf..cf5a1038f 100644 --- a/okhttp-testing-support/src/main/kotlin/okhttp3/ClientRuleEventListener.kt +++ b/okhttp-testing-support/src/main/kotlin/okhttp3/ClientRuleEventListener.kt @@ -241,6 +241,30 @@ class ClientRuleEventListener( delegate.canceled(call) } + override fun satisfactionFailure(call: Call, response: Response) { + logWithTime("satisfactionFailure") + + delegate.satisfactionFailure(call, response) + } + + override fun cacheMiss(call: Call) { + logWithTime("cacheMiss") + + delegate.cacheMiss(call) + } + + override fun cacheHit(call: Call, response: Response) { + logWithTime("cacheHit") + + delegate.cacheHit(call, response) + } + + override fun cacheConditionalHit(call: Call, cachedResponse: Response) { + logWithTime("cacheConditionalHit") + + delegate.cacheConditionalHit(call, cachedResponse) + } + private fun logWithTime(message: String) { val timeMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs) logger.invoke("[$timeMs ms] $message") diff --git a/okhttp-testing-support/src/main/kotlin/okhttp3/RecordingEventListener.kt b/okhttp-testing-support/src/main/kotlin/okhttp3/RecordingEventListener.kt index 48ea178e0..922e796e0 100644 --- a/okhttp-testing-support/src/main/kotlin/okhttp3/RecordingEventListener.kt +++ b/okhttp-testing-support/src/main/kotlin/okhttp3/RecordingEventListener.kt @@ -22,6 +22,9 @@ import java.net.Proxy import java.util.Deque import java.util.concurrent.ConcurrentLinkedDeque import java.util.concurrent.TimeUnit +import okhttp3.CallEvent.CacheConditionalHit +import okhttp3.CallEvent.CacheHit +import okhttp3.CallEvent.CacheMiss import okhttp3.CallEvent.CallEnd import okhttp3.CallEvent.CallFailed import okhttp3.CallEvent.CallStart @@ -45,6 +48,7 @@ import okhttp3.CallEvent.ResponseBodyStart import okhttp3.CallEvent.ResponseFailed import okhttp3.CallEvent.ResponseHeadersEnd import okhttp3.CallEvent.ResponseHeadersStart +import okhttp3.CallEvent.SatisfactionFailure import okhttp3.CallEvent.SecureConnectEnd import okhttp3.CallEvent.SecureConnectStart import org.assertj.core.api.Assertions.assertThat @@ -260,4 +264,21 @@ open class RecordingEventListener : EventListener() { override fun canceled( call: Call ) = logEvent(Canceled(System.nanoTime(), call)) + + override fun satisfactionFailure( + call: Call, + response: Response + ) = logEvent(SatisfactionFailure(System.nanoTime(), call)) + + override fun cacheMiss( + call: Call + ) = logEvent(CacheMiss(System.nanoTime(), call)) + + override fun cacheHit( + call: Call, + response: Response + ) = logEvent(CacheHit(System.nanoTime(), call)) + + override fun cacheConditionalHit(call: Call, cachedResponse: Response) = + logEvent(CacheConditionalHit(System.nanoTime(), call)) } diff --git a/okhttp/src/main/kotlin/okhttp3/EventListener.kt b/okhttp/src/main/kotlin/okhttp3/EventListener.kt index f89485916..ea0b6eb45 100644 --- a/okhttp/src/main/kotlin/okhttp3/EventListener.kt +++ b/okhttp/src/main/kotlin/okhttp3/EventListener.kt @@ -422,6 +422,41 @@ abstract class EventListener { ) { } + /** + * Invoked when a call fails due to cache rules. + * For example, we're forbidden from using the network and the cache is insufficient + */ + open fun satisfactionFailure(call: Call, response: Response) { + } + + /** + * Invoked when a result is served from the cache. The Response provided is the top level + * Response and normal event sequences will not be received. + * + * This event will only be received when a Cache is configured for the client. + */ + open fun cacheHit(call: Call, response: Response) { + } + + /** + * Invoked when a response will be served from the network. The Response will be + * available from normal event sequences. + * + * This event will only be received when a Cache is configured for the client. + */ + open fun cacheMiss(call: Call) { + } + + /** + * Invoked when a response will be served from the cache or network based on validating the + * cached Response freshness. Will be followed by cacheHit or cacheMiss after the network + * Response is available. + * + * This event will only be received when a Cache is configured for the client. + */ + open fun cacheConditionalHit(call: Call, cachedResponse: Response) { + } + interface Factory { /** * Creates an instance of the [EventListener] for a particular [Call]. The returned diff --git a/okhttp/src/main/kotlin/okhttp3/internal/cache/CacheInterceptor.kt b/okhttp/src/main/kotlin/okhttp3/internal/cache/CacheInterceptor.kt index cc8370270..1d54cdb12 100644 --- a/okhttp/src/main/kotlin/okhttp3/internal/cache/CacheInterceptor.kt +++ b/okhttp/src/main/kotlin/okhttp3/internal/cache/CacheInterceptor.kt @@ -21,12 +21,14 @@ import java.net.HttpURLConnection.HTTP_GATEWAY_TIMEOUT import java.net.HttpURLConnection.HTTP_NOT_MODIFIED import java.util.concurrent.TimeUnit.MILLISECONDS import okhttp3.Cache +import okhttp3.EventListener import okhttp3.Headers import okhttp3.Interceptor import okhttp3.Protocol import okhttp3.Response import okhttp3.internal.EMPTY_RESPONSE import okhttp3.internal.closeQuietly +import okhttp3.internal.connection.RealCall import okhttp3.internal.discard import okhttp3.internal.http.ExchangeCodec import okhttp3.internal.http.HttpMethod @@ -42,6 +44,7 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor { @Throws(IOException::class) override fun intercept(chain: Interceptor.Chain): Response { + val call = chain.call() val cacheCandidate = cache?.get(chain.request()) val now = System.currentTimeMillis() @@ -51,6 +54,7 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor { val cacheResponse = strategy.cacheResponse cache?.trackResponse(strategy) + val listener = (call as? RealCall)?.eventListener ?: EventListener.NONE if (cacheCandidate != null && cacheResponse == null) { // The cache candidate wasn't applicable. Close it. @@ -67,14 +71,24 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor { .body(EMPTY_RESPONSE) .sentRequestAtMillis(-1L) .receivedResponseAtMillis(System.currentTimeMillis()) - .build() + .build().also { + listener.satisfactionFailure(call, it) + } } // If we don't need the network, we're done. if (networkRequest == null) { return cacheResponse!!.newBuilder() .cacheResponse(stripBody(cacheResponse)) - .build() + .build().also { + listener.cacheHit(call, it) + } + } + + if (cacheResponse != null) { + listener.cacheConditionalHit(call, cacheResponse) + } else if (cache != null) { + listener.cacheMiss(call) } var networkResponse: Response? = null @@ -104,7 +118,9 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor { // Content-Encoding header (as performed by initContentStream()). cache!!.trackConditionalCacheHit() cache.update(cacheResponse, response) - return response + return response.also { + listener.cacheHit(call, it) + } } else { cacheResponse.body?.closeQuietly() } @@ -119,7 +135,12 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor { if (response.promisesBody() && CacheStrategy.isCacheable(response, networkRequest)) { // Offer this request to the cache. val cacheRequest = cache.put(response) - return cacheWritingResponse(cacheRequest, response) + return cacheWritingResponse(cacheRequest, response).also { + if (cacheResponse != null) { + // This will log a conditional cache miss only. + listener.cacheMiss(call) + } + } } if (HttpMethod.invalidatesCache(networkRequest.method)) { diff --git a/okhttp/src/main/kotlin/okhttp3/internal/connection/RealCall.kt b/okhttp/src/main/kotlin/okhttp3/internal/connection/RealCall.kt index f89d225fa..d4e01ac99 100644 --- a/okhttp/src/main/kotlin/okhttp3/internal/connection/RealCall.kt +++ b/okhttp/src/main/kotlin/okhttp3/internal/connection/RealCall.kt @@ -65,7 +65,7 @@ class RealCall( ) : Call { private val connectionPool: RealConnectionPool = client.connectionPool.delegate - private val eventListener: EventListener = client.eventListenerFactory.create(this) + internal val eventListener: EventListener = client.eventListenerFactory.create(this) private val timeout = object : AsyncTimeout() { override fun timedOut() { diff --git a/okhttp/src/test/java/okhttp3/EventListenerTest.java b/okhttp/src/test/java/okhttp3/EventListenerTest.java index 03edc18b3..4e893f184 100644 --- a/okhttp/src/test/java/okhttp3/EventListenerTest.java +++ b/okhttp/src/test/java/okhttp3/EventListenerTest.java @@ -15,6 +15,7 @@ */ package okhttp3; +import java.io.File; import java.io.IOException; import java.io.InterruptedIOException; import java.net.HttpURLConnection; @@ -77,6 +78,7 @@ import static okhttp3.tls.internal.TlsUtil.localhost; import static org.assertj.core.api.Assertions.assertThat; import static org.hamcrest.CoreMatchers.any; import static org.hamcrest.CoreMatchers.equalTo; +import static org.junit.Assert.assertNotNull; import static org.junit.Assert.fail; import static org.junit.Assume.assumeThat; @@ -96,6 +98,7 @@ public final class EventListenerTest { .eventListenerFactory(clientTestRule.wrap(listener)) .build(); private SocksProxy socksProxy; + private Cache cache = null; @Before public void setUp() { platform.assumeNotOpenJSSE(); @@ -109,6 +112,9 @@ public final class EventListenerTest { if (socksProxy != null) { socksProxy.shutdown(); } + if (cache != null) { + cache.delete(); + } } @Test public void successfulCallEventSequence() throws IOException { @@ -1443,4 +1449,141 @@ public final class EventListenerTest { listener.takeEvent(RequestBodyEnd.class, 0L); listener.takeEvent(ResponseHeadersEnd.class, responseHeadersStartDelay); } + + @Test public void cacheMiss() throws IOException { + enableCache(); + + server.enqueue(new MockResponse() + .setBody("abc")); + + Call call = client.newCall(new Request.Builder() + .url(server.url("/")) + .build()); + Response response = call.execute(); + assertThat(response.code()).isEqualTo(200); + assertThat(response.body().string()).isEqualTo("abc"); + response.close(); + + assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheMiss", + "ProxySelectStart", "ProxySelectEnd", "DnsStart", "DnsEnd", + "ConnectStart", "ConnectEnd", "ConnectionAcquired", "RequestHeadersStart", + "RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd", + "ResponseBodyStart", "ResponseBodyEnd", "ConnectionReleased", "CallEnd"); + } + + @Test public void conditionalCache() throws IOException { + enableCache(); + + server.enqueue(new MockResponse() + .addHeader("ETag: v1") + .setBody("abc")); + server.enqueue(new MockResponse() + .setResponseCode(HttpURLConnection.HTTP_NOT_MODIFIED)); + + Call call = client.newCall(new Request.Builder() + .url(server.url("/")) + .build()); + + Response response = call.execute(); + assertThat(response.code()).isEqualTo(200); + response.close(); + + listener.clearAllEvents(); + + call = call.clone(); + + response = call.execute(); + assertThat(response.code()).isEqualTo(200); + assertThat(response.body().string()).isEqualTo("abc"); + response.close(); + + assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheConditionalHit", + "ConnectionAcquired", "RequestHeadersStart", + "RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd", + "ResponseBodyStart", "ResponseBodyEnd", "CacheHit", "ConnectionReleased", "CallEnd"); + } + + @Test public void conditionalCacheMiss() throws IOException { + enableCache(); + + server.enqueue(new MockResponse() + .addHeader("ETag: v1") + .setBody("abc")); + server.enqueue(new MockResponse() + .setResponseCode(HttpURLConnection.HTTP_OK) + .addHeader("ETag: v2") + .setBody("abd")); + + Call call = client.newCall(new Request.Builder() + .url(server.url("/")) + .build()); + + Response response = call.execute(); + assertThat(response.code()).isEqualTo(200); + response.close(); + + listener.clearAllEvents(); + + call = call.clone(); + + response = call.execute(); + assertThat(response.code()).isEqualTo(200); + assertThat(response.body().string()).isEqualTo("abd"); + response.close(); + + assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheConditionalHit", + "ConnectionAcquired", "RequestHeadersStart", + "RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd", "CacheMiss", + "ResponseBodyStart", "ResponseBodyEnd", "ConnectionReleased", "CallEnd"); + } + + @Test public void satisfactionFailure() throws IOException { + enableCache(); + + Call call = client.newCall(new Request.Builder() + .url(server.url("/")) + .cacheControl(CacheControl.FORCE_CACHE) + .build()); + Response response = call.execute(); + assertThat(response.code()).isEqualTo(504); + response.close(); + + assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "SatisfactionFailure", "CallEnd"); + } + + @Test public void cacheHit() throws IOException { + enableCache(); + + server.enqueue(new MockResponse().setBody("abc").addHeader("cache-control: public, max-age=300")); + + Call call = client.newCall(new Request.Builder() + .url(server.url("/")) + .build()); + Response response = call.execute(); + assertThat(response.code()).isEqualTo(200); + assertThat(response.body().string()).isEqualTo("abc"); + response.close(); + + listener.clearAllEvents(); + + call = call.clone(); + response = call.execute(); + assertThat(response.code()).isEqualTo(200); + assertThat(response.body().string()).isEqualTo("abc"); + response.close(); + + assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheHit", "CallEnd"); + } + + private Cache enableCache() throws IOException { + cache = makeCache(); + client = client.newBuilder().cache(cache).build(); + return cache; + } + + private Cache makeCache() throws IOException { + File cacheDir = File.createTempFile("cache-", ".dir"); + cacheDir.delete(); + return new Cache(cacheDir, 1024 * 1024); + } }