Skip to content

Commit 0049941

Browse files
committed
[SPARK-59928] Fix kubernetes.client.http.response.latency.nanos always recording near zero
1 parent ad397f3 commit 0049941

4 files changed

Lines changed: 171 additions & 7 deletions

File tree

‎docs/configuration.md‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -259,6 +259,11 @@ has a retry left for it, even if it does not retry it, e.g. on a request timeout
259259
a client which never retries, i.e. a Kubernetes event write or the recording of the Kueue
260260
`PodsReady` condition, is not counted there when it gets no response.
261261

262+
`kubernetes.client.http.response.latency.nanos` ends when the response headers arrive, so it does
263+
not include reading the body. A request re-sent after a `401` is measured from the `401`, whose
264+
latency can include the token refresh. WebSocket upgrades, e.g. of a watch, are not recorded, and
265+
a rejected one can be counted more than once in `kubernetes.client.http.response`.
266+
262267
### Latency for State Transition
263268

264269
Spark Operator also measures the latency between each state transition for apps, in the format of

‎docs/migration_guide.md‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -90,6 +90,10 @@ affect building the project, CI, tests or examples.
9090
`0.5` and `0.999` quantiles of the `operator_sdk_*` histograms are the median and the 99.9th
9191
percentile instead of the mean and the 99th percentile. A histogram or timer of a custom metrics
9292
source has no `_sum` unless it is a `SummingHistogram` or a `SummingTimer` ([SPARK-59935](https://issues.apache.org/jira/browse/SPARK-59935)).
93+
- Since 1.1.0, `kubernetes.client.http.response.latency.nanos` records the time from sending each
94+
HTTP request until its response headers arrive. 1.0 recorded nearly zero regardless of the
95+
latency. It no longer records a WebSocket upgrade response, e.g. of a watch, so its count can be
96+
lower than that of `kubernetes.client.http.response` ([SPARK-59928](https://issues.apache.org/jira/browse/SPARK-59928)).
9397

9498
### SparkApplication
9599

‎spark-operator/src/main/java/org/apache/spark/k8s/operator/metrics/source/KubernetesMetricsInterceptor.java‎

Lines changed: 54 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929
import java.util.Optional;
3030
import java.util.concurrent.CompletableFuture;
3131
import java.util.concurrent.ConcurrentHashMap;
32+
import java.util.concurrent.atomic.AtomicLong;
3233

3334
import com.codahale.metrics.Histogram;
3435
import com.codahale.metrics.Meter;
@@ -90,6 +91,25 @@ public KubernetesMetricsInterceptor() {
9091
}
9192
}
9293

94+
/**
95+
* Called before a request is sent, to allow wrapping the consumer of the response body.
96+
*
97+
* <p>Wraps the consumer to carry the request start time, which {@link #after(HttpRequest,
98+
* HttpResponse, AsyncBody.Consumer)} finds with {@link AsyncBody.Consumer#unwrap(Class)}. fabric8
99+
* passes to it the outermost consumer after all interceptors have wrapped it, so an interceptor
100+
* which wraps the consumer after this one must delegate {@code unwrap(...)}, or no latency is
101+
* recorded.
102+
*
103+
* @param consumer the consumer of the response body
104+
* @param request the request about to be sent
105+
* @return the consumer carrying the request start time
106+
*/
107+
@Override
108+
public AsyncBody.Consumer<List<ByteBuffer>> consumer(
109+
AsyncBody.Consumer<List<ByteBuffer>> consumer, HttpRequest request) {
110+
return new TimedConsumer(consumer, new AtomicLong(System.nanoTime()));
111+
}
112+
93113
/**
94114
* Called before a request to allow for the manipulation of the request
95115
*
@@ -102,21 +122,30 @@ public void before(BasicBuilder builder, HttpRequest request, RequestTags tags)
102122
}
103123

104124
/**
105-
* Called after a non-WebSocket HTTP response is received. The body might or might not be already
106-
* consumed.
125+
* Called after an HTTP response is received. The body might or might not be already consumed.
107126
*
108127
* <p>Should be used to analyze response codes and headers, original response shouldn't be
109128
* altered.
110129
*
130+
* <p>fabric8 also calls this for a WebSocket upgrade response with a {@code null} consumer, and
131+
* again for an HTTP request re-sent after {@link #afterFailure(BasicBuilder, HttpResponse,
132+
* RequestTags)}. The latency of a re-sent response is measured from the previous response.
133+
*
111134
* @param request the original request sent to the server.
112135
* @param response the response received from the server.
136+
* @param consumer the consumer of the response body, or {@code null} for a WebSocket upgrade.
113137
*/
114138
@Override
115139
public void after(
116140
HttpRequest request,
117141
HttpResponse<?> response,
118142
AsyncBody.Consumer<List<ByteBuffer>> consumer) {
119-
updateResponseMetrics(response, System.nanoTime());
143+
TimedConsumer timedConsumer = consumer == null ? null : consumer.unwrap(TimedConsumer.class);
144+
if (timedConsumer != null) {
145+
long now = System.nanoTime();
146+
responseLatency.update(now - timedConsumer.startTimeNanos().getAndSet(now));
147+
}
148+
updateResponseMetrics(response);
120149
}
121150

122151
/**
@@ -139,7 +168,8 @@ public CompletableFuture<Boolean> afterFailure(
139168
/**
140169
* Called after a connection attempt fails.
141170
*
142-
* <p>This method will be invoked on each failed connection attempt.
171+
* <p>fabric8 invokes this method only for a failed connection attempt which has a retry left, not
172+
* for the last attempt.
143173
*
144174
* @param request the HTTP request.
145175
* @param failure the Java exception that caused the failure.
@@ -183,11 +213,9 @@ private void updateRequestMetrics(HttpRequest request) {
183213
});
184214
}
185215

186-
private void updateResponseMetrics(HttpResponse response, long startTimeNanos) {
216+
private void updateResponseMetrics(HttpResponse response) {
187217
Objects.requireNonNull(response);
188-
final long latency = System.nanoTime() - startTimeNanos;
189218
responseRateMeter.mark();
190-
responseLatency.update(latency);
191219
getMeterByResponseCode(response.code()).mark();
192220
if (KUBERNETES_CLIENT_METRICS_GROUP_BY_RESPONSE_CODE_GROUP_ENABLED.getValue()) {
193221
responseCodeGroupMeters.get(response.code() / 100 - 1).mark();
@@ -229,4 +257,23 @@ public Optional<Pair<String, String>> parseNamespaceScopedResource(String path)
229257
return Optional.empty();
230258
}
231259
}
260+
261+
/**
262+
* Consumer of a response body which carries the start time of its request, restarted at each
263+
* response so that a re-sent request is measured from the previous response.
264+
*/
265+
private record TimedConsumer(
266+
AsyncBody.Consumer<List<ByteBuffer>> delegate, AtomicLong startTimeNanos)
267+
implements AsyncBody.Consumer<List<ByteBuffer>> {
268+
@Override
269+
public void consume(List<ByteBuffer> value, AsyncBody asyncBody) throws Exception {
270+
delegate.consume(value, asyncBody);
271+
}
272+
273+
@Override
274+
public <U> U unwrap(Class<U> target) {
275+
U self = AsyncBody.Consumer.super.unwrap(target);
276+
return self != null ? self : delegate.unwrap(target);
277+
}
278+
}
232279
}

‎spark-operator/src/test/java/org/apache/spark/k8s/operator/metrics/source/KubernetesMetricsInterceptorTest.java‎

Lines changed: 108 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,19 +19,27 @@
1919

2020
package org.apache.spark.k8s.operator.metrics.source;
2121

22+
import static java.net.HttpURLConnection.HTTP_UNAUTHORIZED;
23+
import static org.awaitility.Awaitility.await;
2224
import static org.junit.jupiter.api.Assertions.assertThrows;
2325

26+
import java.nio.ByteBuffer;
2427
import java.util.Arrays;
2528
import java.util.HashMap;
2629
import java.util.List;
2730
import java.util.Map;
2831

32+
import com.codahale.metrics.Histogram;
2933
import com.codahale.metrics.Meter;
3034
import com.codahale.metrics.Metric;
3135
import io.fabric8.kubernetes.api.model.ConfigMap;
3236
import io.fabric8.kubernetes.api.model.ObjectMeta;
37+
import io.fabric8.kubernetes.client.Config;
38+
import io.fabric8.kubernetes.client.ConfigBuilder;
3339
import io.fabric8.kubernetes.client.KubernetesClient;
40+
import io.fabric8.kubernetes.client.http.AsyncBody;
3441
import io.fabric8.kubernetes.client.http.Interceptor;
42+
import io.fabric8.kubernetes.client.informers.SharedIndexInformer;
3543
import io.fabric8.kubernetes.client.server.mock.EnableKubernetesMockClient;
3644
import io.fabric8.kubernetes.client.server.mock.KubernetesMockServer;
3745
import org.junit.jupiter.api.AfterEach;
@@ -50,6 +58,9 @@
5058
@TestMethodOrder(MethodOrderer.OrderAnnotation.class)
5159
class KubernetesMetricsInterceptorTest {
5260

61+
private static final String CONFIG_MAP_PATH =
62+
"/api/v1/namespaces/spark-system/configmaps/spark-job-operator-configuration";
63+
5364
private KubernetesMockServer mockServer;
5465
private KubernetesClient kubernetesClient;
5566

@@ -125,6 +136,103 @@ void testWhenKubernetesServerNotWorking() {
125136
}
126137
}
127138

139+
@Test
140+
@Order(3)
141+
void testResponseLatency() {
142+
KubernetesMetricsInterceptor metricsInterceptor = new KubernetesMetricsInterceptor();
143+
List<Interceptor> interceptors = List.of(metricsInterceptor);
144+
try (KubernetesClient client =
145+
KubernetesClientFactory.buildKubernetesClient(
146+
interceptors, kubernetesClient.getConfiguration())) {
147+
ConfigMap configMap = createConfigMap();
148+
mockServer
149+
.expect()
150+
.get()
151+
.delay(50)
152+
.withPath(CONFIG_MAP_PATH)
153+
.andReturn(200, configMap)
154+
.once();
155+
client.resource(configMap).get();
156+
157+
Map<String, Metric> map = metricsInterceptor.metricRegistry().getMetrics();
158+
Histogram latency = (Histogram) map.get("http.response.latency.nanos");
159+
Assertions.assertEquals(1, latency.getCount());
160+
Assertions.assertTrue(latency.getSnapshot().getMax() >= 50_000_000L);
161+
Assertions.assertTrue(latency.getSnapshot().getMax() < 30_000_000_000L);
162+
}
163+
}
164+
165+
@Test
166+
@Order(4)
167+
void testResponseLatencyOfResentRequest() {
168+
KubernetesMetricsInterceptor metricsInterceptor = new KubernetesMetricsInterceptor();
169+
List<Interceptor> interceptors = List.of(metricsInterceptor);
170+
Config config =
171+
new ConfigBuilder(kubernetesClient.getConfiguration())
172+
.withOauthTokenProvider(() -> "token")
173+
.build();
174+
try (KubernetesClient client =
175+
KubernetesClientFactory.buildKubernetesClient(interceptors, config)) {
176+
ConfigMap configMap = createConfigMap();
177+
mockServer
178+
.expect()
179+
.get()
180+
.delay(200)
181+
.withPath(CONFIG_MAP_PATH)
182+
.andReturn(HTTP_UNAUTHORIZED, null)
183+
.once();
184+
mockServer.expect().get().withPath(CONFIG_MAP_PATH).andReturn(200, configMap).once();
185+
client.resource(configMap).get();
186+
187+
Assertions.assertEquals(2, meterCount(metricsInterceptor, "http.response"));
188+
Assertions.assertEquals(1, meterCount(metricsInterceptor, "http.response.401"));
189+
Assertions.assertEquals(0, meterCount(metricsInterceptor, "failed"));
190+
Map<String, Metric> map = metricsInterceptor.metricRegistry().getMetrics();
191+
Histogram latency = (Histogram) map.get("http.response.latency.nanos");
192+
Assertions.assertEquals(2, latency.getCount());
193+
Assertions.assertTrue(latency.getSnapshot().getMax() >= 200_000_000L);
194+
Assertions.assertTrue(latency.getSnapshot().getMin() < 200_000_000L);
195+
}
196+
}
197+
198+
@Test
199+
@Order(5)
200+
void testResponseLatencyOfWebSocketUpgrade() {
201+
KubernetesMetricsInterceptor metricsInterceptor = new KubernetesMetricsInterceptor();
202+
List<Interceptor> interceptors = List.of(metricsInterceptor);
203+
try (KubernetesClient client =
204+
KubernetesClientFactory.buildKubernetesClient(
205+
interceptors, kubernetesClient.getConfiguration());
206+
SharedIndexInformer<ConfigMap> informer =
207+
client.configMaps().inNamespace("spark-system").inform()) {
208+
Map<String, Metric> map = metricsInterceptor.metricRegistry().getMetrics();
209+
await()
210+
.untilAsserted(
211+
() -> {
212+
Assertions.assertEquals(2, meterCount(metricsInterceptor, "http.response"));
213+
Assertions.assertEquals(1, meterCount(metricsInterceptor, "http.response.101"));
214+
Assertions.assertEquals(
215+
1, ((Histogram) map.get("http.response.latency.nanos")).getCount());
216+
});
217+
Assertions.assertTrue(informer.isWatching());
218+
}
219+
}
220+
221+
@Test
222+
@Order(6)
223+
void testConsumerUnwrapsDelegate() {
224+
AsyncBody.Consumer<List<ByteBuffer>> delegate = (value, asyncBody) -> {};
225+
AsyncBody.Consumer<List<ByteBuffer>> consumer =
226+
new KubernetesMetricsInterceptor().consumer(delegate, null);
227+
Assertions.assertSame(delegate, consumer.unwrap(delegate.getClass()));
228+
}
229+
230+
private static long meterCount(KubernetesMetricsInterceptor interceptor, String name) {
231+
Meter meter = interceptor.metricRegistry().getMeters().get(name);
232+
Assertions.assertNotNull(meter, name);
233+
return meter.getCount();
234+
}
235+
128236
private static SparkApplication createSparkApplication() {
129237
ObjectMeta meta = new ObjectMeta();
130238
meta.setName("sample-spark-application");

0 commit comments

Comments
 (0)