aliehsaeedii commented on code in PR #22975:
URL: https://github.com/apache/kafka/pull/22975#discussion_r3730260293
##########
streams/src/test/java/org/apache/kafka/streams/state/internals/MeteredTimestampedKeyValueStoreWithHeadersTest.java:
##########
@@ -629,6 +629,50 @@ public void shouldTimeIteratorDuration() {
assertEquals(3.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
}
+ // The above shouldTimeIteratorDuration goes through metered.all() -> the
KeyValueIterator sibling.
+ // This pins the same close()-path recording for the
ReadOnlyRecordIterator that backs
+ // TimestampedRangeWithHeadersQuery, whose close() records both the
operation sensor (get) and the
+ // iterator-duration sensor. All three Metered*WithHeaders
ReadOnlyRecordIterators now share that
+ // close() via AbstractMeteredIterator, so this also guards the shared
lifecycle.
+ @SuppressWarnings("unchecked")
+ @Test
+ public void
shouldTimeIteratorDurationForTimestampedRangeWithHeadersQuery() {
+ setUp();
+ when(inner.query(any(), any(PositionBound.class),
any(QueryConfig.class)))
+ .thenReturn(
+ (QueryResult)
QueryResult.forResult(KeyValueIterators.emptyIterator()),
+ (QueryResult)
QueryResult.forResult(KeyValueIterators.emptyIterator()));
+ init();
+
+ final KafkaMetric iteratorDurationAvgMetric =
metric("iterator-duration-avg");
+ final KafkaMetric iteratorDurationMaxMetric =
metric("iterator-duration-max");
+ final KafkaMetric getLatencyAvgMetric = metric("get-latency-avg");
+ assertNotNull(iteratorDurationAvgMetric);
+ assertNotNull(iteratorDurationMaxMetric);
+ assertNotNull(getLatencyAvgMetric);
+ assertEquals(Double.NaN, (Double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(Double.NaN, (Double)
iteratorDurationMaxMetric.metricValue());
+
+ // Two samples (2ms then 3ms) so avg (2.5ms) and max (3ms) differ --
one sample would leave them
+ // identical and not actually pin avg. Mirrors the sibling
shouldTimeIteratorDuration above.
+ try (ReadOnlyRecordIterator<String, String> iterator = metered.query(
+ TimestampedRangeWithHeadersQuery.<String,
String>withNoBounds(), PositionBound.unbounded(), new
QueryConfig(false)).getResult()) {
+ mockTime.sleep(2);
+ }
+
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
+
+ try (ReadOnlyRecordIterator<String, String> iterator = metered.query(
+ TimestampedRangeWithHeadersQuery.<String,
String>withNoBounds(), PositionBound.unbounded(), new
QueryConfig(false)).getResult()) {
+ mockTime.sleep(3);
+ }
+
+ assertEquals(2.5 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(3.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
+ assertTrue((double) getLatencyAvgMetric.metricValue() > 0.0);
Review Comment:
`getSensor` is only recorded from the iterator's `close()` on this path, so
`get-latency-avg` is exactly 2.5ms. Assert that instead of `> 0.0`.
##########
streams/src/main/java/org/apache/kafka/streams/state/internals/AbstractMeteredIterator.java:
##########
@@ -0,0 +1,100 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.kafka.streams.state.internals;
+
+import org.apache.kafka.common.metrics.Sensor;
+import org.apache.kafka.common.utils.Time;
+import org.apache.kafka.streams.state.KeyValueIterator;
+
+import java.util.Set;
+import java.util.concurrent.atomic.LongAdder;
+
+/**
+ * Shared metering lifecycle for the metered iterators of the {@code
Metered*WithHeaders} stores,
+ * whatever result type they yield: the {@code KeyValueIterator}s returned by
the store's own range/
+ * fetch/find methods and the {@code ReadOnlyRecordIterator}s that back the
headers-aware IQv2
+ * range/window/session query types.
+ *
+ * <p>Every such iterator opens over a raw {@code KeyValueIterator<RawKey,
byte[]>} and needs the
+ * same bookkeeping: stamp the open time (for the {@code
oldest-iterator-open-since-ms} metric),
+ * register in {@code numOpenIterators}/{@code openIterators}, and on {@link
#close()} record the
+ * operation and iterator-duration sensors and deregister. This base is
deliberately result-type
+ * agnostic -- it implements only {@link MeteredIterator} and does not bind
the yielded key/value
+ * types -- so each subclass declares its own result interface (a {@code
KeyValueIterator} or a
+ * {@code ReadOnlyRecordIterator}) and implements just the parts that
genuinely differ: the
+ * deserializing {@code next()} (and, for the {@code KeyValueIterator}s, a
peeking {@code hasNext()}
+ * and {@code peekNextKey()}).
+ *
+ * @param <RawKey> the raw iterator's key type
+ */
+abstract class AbstractMeteredIterator<RawKey> implements MeteredIterator {
+
+ final KeyValueIterator<RawKey, byte[]> iter;
+ private final Sensor operationSensor;
+ private final Sensor iteratorSensor;
+ private final Time time;
+ private final LongAdder numOpenIterators;
+ private final Set<MeteredIterator> openIterators;
+ private final long startNs;
+ private final long startTimestampMs;
+
+ AbstractMeteredIterator(final KeyValueIterator<RawKey, byte[]> iter,
+ final Sensor operationSensor,
+ final Sensor iteratorSensor,
+ final Time time,
+ final LongAdder numOpenIterators,
+ final Set<MeteredIterator> openIterators) {
+ this.iter = iter;
+ this.operationSensor = operationSensor;
+ this.iteratorSensor = iteratorSensor;
+ this.time = time;
+ this.numOpenIterators = numOpenIterators;
+ this.openIterators = openIterators;
+ this.startNs = time.nanoseconds();
+ this.startTimestampMs = time.milliseconds();
+ numOpenIterators.increment();
+ openIterators.add(this);
+ }
+
+ // Final: the constructor's openIterators.add(this) sorts through this via
the set's
+ // startTimestamp comparator, i.e. on a not-yet-fully-constructed object.
Keeping it final stops a
+ // subclass from overriding it with something that reads its own
not-yet-assigned state.
+ @Override
+ public final long startTimestamp() {
+ return startTimestampMs;
+ }
+
+ /**
+ * Delegates to the raw iterator. Subclasses that buffer a peeked element
(the
+ * {@code KeyValueIterator}s) override this to also account for the
buffered element.
+ */
+ public boolean hasNext() {
+ return iter.hasNext();
+ }
+
+ public void close() {
+ try {
+ iter.close();
+ } finally {
+ final long duration = time.nanoseconds() - startNs;
+ operationSensor.record(duration);
+ iteratorSensor.record(duration);
+ numOpenIterators.decrement();
+ openIterators.remove(this);
Review Comment:
`openIterators` is a `ConcurrentSkipListSet` keyed only by
`startTimestamp()`, so two iterators opened in the same millisecond collide:
the second `add` is silently dropped and this `remove` can evict the other,
still-open one. Not this PR's to fix, but worth a ticket.
##########
streams/src/test/java/org/apache/kafka/streams/state/internals/MeteredTimestampedWindowStoreWithHeadersTest.java:
##########
@@ -619,6 +622,82 @@ public void
shouldDecrementOpenIteratorsTwiceWhenClosedTwiceForTimestampedWindow
assertEquals(-1L, (Long) openIterators.metricValue());
}
+ // The window store previously had no iterator-duration coverage at all.
This mirrors the
+ // session/KV shouldTimeIteratorDuration: it goes through store.all() ->
the KeyValueIterator
+ // sibling, whose close() records the operation (fetch) and
iterator-duration sensors via the
+ // shared AbstractMeteredIterator lifecycle.
+ @Test
+ public void shouldTimeIteratorDuration() {
+ setUp();
+ store.init(context, store);
+ when(innerStoreMock.all()).thenReturn(windowRangeIterator(List.of()),
windowRangeIterator(List.of()));
+
+ final KafkaMetric iteratorDurationAvg =
metric("iterator-duration-avg");
+ final KafkaMetric iteratorDurationMax =
metric("iterator-duration-max");
+ assertEquals(Double.NaN, (Double) iteratorDurationAvg.metricValue());
+ assertEquals(Double.NaN, (Double) iteratorDurationMax.metricValue());
+
+ // Two samples (2ms then 3ms) so avg (2.5ms) and max (3ms) differ --
one sample would leave them
+ // identical and not actually pin avg.
+ try (KeyValueIterator<Windowed<String>, ValueTimestampHeaders<String>>
iterator = store.all()) {
+ mockTime.sleep(2);
+ }
+
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvg.metricValue());
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMax.metricValue());
+
+ try (KeyValueIterator<Windowed<String>, ValueTimestampHeaders<String>>
iterator = store.all()) {
+ mockTime.sleep(3);
+ }
+
+ assertEquals(2.5 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvg.metricValue());
+ assertEquals(3.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMax.metricValue());
+ }
+
+ // The above shouldTimeIteratorDuration goes through store.all() -> the
KeyValueIterator sibling.
+ // This pins the same close()-path recording for the
ReadOnlyRecordIterator that backs
+ // TimestampedWindowKeyWithHeadersQuery, whose close() records both the
operation sensor (fetch)
+ // and the iterator-duration sensor via the shared AbstractMeteredIterator
lifecycle.
+ @SuppressWarnings({"unchecked", "rawtypes"})
+ @Test
+ public void
shouldTimeIteratorDurationForTimestampedWindowKeyWithHeadersQuery() {
+ setUp();
+ store.init(context, store);
+ when(innerStoreMock.query(any(), any(PositionBound.class),
any(QueryConfig.class)))
+ .thenReturn(
+ (QueryResult)
QueryResult.forResult(windowKeyIterator(List.of())),
+ (QueryResult)
QueryResult.forResult(windowKeyIterator(List.of())));
+
+ final KafkaMetric iteratorDurationAvg =
metric("iterator-duration-avg");
+ final KafkaMetric iteratorDurationMax =
metric("iterator-duration-max");
+ final KafkaMetric fetchLatencyAvg = metric("fetch-latency-avg");
+ assertEquals(Double.NaN, (Double) iteratorDurationAvg.metricValue());
+ assertEquals(Double.NaN, (Double) iteratorDurationMax.metricValue());
+
+ // Two samples (2ms then 3ms) so avg (2.5ms) and max (3ms) differ --
one sample would leave them
+ // identical and not actually pin avg. Mirrors the sibling
shouldTimeIteratorDuration above.
+ try (ReadOnlyRecordIterator<Windowed<String>, String> iterator =
store.query(
+ TimestampedWindowKeyWithHeadersQuery.<String,
String>withKeyAndWindowStartRange(
+ KEY, Instant.ofEpochMilli(5), Instant.ofEpochMilli(100)),
+ PositionBound.unbounded(), new
QueryConfig(false)).getResult()) {
+ mockTime.sleep(2);
+ }
+
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvg.metricValue());
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMax.metricValue());
+
+ try (ReadOnlyRecordIterator<Windowed<String>, String> iterator =
store.query(
+ TimestampedWindowKeyWithHeadersQuery.<String,
String>withKeyAndWindowStartRange(
+ KEY, Instant.ofEpochMilli(5), Instant.ofEpochMilli(100)),
+ PositionBound.unbounded(), new
QueryConfig(false)).getResult()) {
+ mockTime.sleep(3);
+ }
+
+ assertEquals(2.5 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvg.metricValue());
+ assertEquals(3.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMax.metricValue());
+ assertTrue((double) fetchLatencyAvg.metricValue() > 0.0);
Review Comment:
`fetchSensor` is only recorded from the iterator's `close()` on this path,
so `fetch-latency-avg` is exactly 2.5ms. Assert that instead of `> 0.0`.
##########
streams/src/test/java/org/apache/kafka/streams/state/internals/MeteredSessionStoreWithHeadersTest.java:
##########
@@ -646,25 +647,76 @@ public void shouldTimeIteratorDuration() {
setUp();
init();
- final Headers headers = new RecordHeaders();
- headers.add("key1", "value1".getBytes());
- final AggregationWithHeaders<String> valueAndHeaders =
AggregationWithHeaders.make(VALUE, headers);
+ when(innerStore.fetch(KEY_BYTES))
+ .thenReturn(
+ new
KeyValueIteratorStub<>(Collections.<KeyValue<Windowed<Bytes>,
byte[]>>emptyList().iterator()),
+ new
KeyValueIteratorStub<>(Collections.<KeyValue<Windowed<Bytes>,
byte[]>>emptyList().iterator()));
+
+ final KafkaMetric iteratorDurationAvgMetric =
metric("iterator-duration-avg");
+ final KafkaMetric iteratorDurationMaxMetric =
metric("iterator-duration-max");
+ assertEquals(Double.NaN, (Double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(Double.NaN, (Double)
iteratorDurationMaxMetric.metricValue());
+
+ // Two samples (2ms then 3ms) so avg (2.5ms) and max (3ms) differ --
one sample would leave them
+ // identical and not actually pin avg. Mirrors the KV sibling
shouldTimeIteratorDuration.
+ try (KeyValueIterator<Windowed<String>,
AggregationWithHeaders<String>> iterator = store.fetch(KEY)) {
+ mockTime.sleep(2);
+ }
- final AggregationWithHeadersSerializer<String> serializer = new
AggregationWithHeadersSerializer<>(Serdes.String().serializer());
- final byte[] serializedValue = serializer.serialize(CHANGELOG_TOPIC,
valueAndHeaders);
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
- when(innerStore.fetch(KEY_BYTES))
- .thenReturn(new KeyValueIteratorStub<>(
- Collections.singleton(KeyValue.pair(WINDOWED_KEY_BYTES,
serializedValue)).iterator()));
+ try (KeyValueIterator<Windowed<String>,
AggregationWithHeaders<String>> iterator = store.fetch(KEY)) {
+ mockTime.sleep(3);
+ }
- final KeyValueIterator<Windowed<String>,
AggregationWithHeaders<String>> iterator = store.fetch(KEY);
+ assertEquals(2.5 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(3.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
+ }
- mockTime.sleep(100L);
+ // The above shouldTimeIteratorDuration goes through store.fetch() -> the
KeyValueIterator sibling.
+ // This pins the same close()-path recording for the
ReadOnlyRecordIterator that backs
+ // TimestampedWindowRangeWithHeadersQuery.withKey, whose close() records
both the operation sensor
+ // (fetch) and the iterator-duration sensor via the shared
AbstractMeteredIterator lifecycle.
+ @SuppressWarnings({"unchecked", "rawtypes"})
+ @Test
+ public void
shouldTimeIteratorDurationForTimestampedWindowRangeWithHeadersQuery() {
+ setUp();
+ init();
- iterator.close();
+ when(innerStore.query(any(), any(PositionBound.class),
any(QueryConfig.class)))
+ .thenReturn(
+ (QueryResult) QueryResult.forResult(new KeyValueIteratorStub<>(
+ Collections.<KeyValue<Windowed<Bytes>,
byte[]>>emptyList().iterator())),
+ (QueryResult) QueryResult.forResult(new KeyValueIteratorStub<>(
+ Collections.<KeyValue<Windowed<Bytes>,
byte[]>>emptyList().iterator())));
+
+ final KafkaMetric iteratorDurationAvgMetric =
metric("iterator-duration-avg");
+ final KafkaMetric iteratorDurationMaxMetric =
metric("iterator-duration-max");
+ final KafkaMetric fetchLatencyMetric = metric("fetch-latency-avg");
+ assertEquals(Double.NaN, (Double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(Double.NaN, (Double)
iteratorDurationMaxMetric.metricValue());
+
+ // Two samples (2ms then 3ms), deterministic under mockTime, so avg
(2.5ms) and max (3ms) differ
+ // and are pinned exactly -- one sample would leave avg == max.
+ try (ReadOnlyRecordIterator<Windowed<String>, String> iterator =
store.query(
+ TimestampedWindowRangeWithHeadersQuery.<String,
String>withKey(KEY),
+ PositionBound.unbounded(), new
QueryConfig(false)).getResult()) {
+ mockTime.sleep(2);
+ }
+
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(2.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
+
+ try (ReadOnlyRecordIterator<Windowed<String>, String> iterator =
store.query(
+ TimestampedWindowRangeWithHeadersQuery.<String,
String>withKey(KEY),
+ PositionBound.unbounded(), new
QueryConfig(false)).getResult()) {
+ mockTime.sleep(3);
+ }
- final KafkaMetric iteratorDurationMetric =
metric("iterator-duration-avg");
- assertTrue((Double) iteratorDurationMetric.metricValue() > 0.0);
+ assertEquals(2.5 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationAvgMetric.metricValue());
+ assertEquals(3.0 * TimeUnit.MILLISECONDS.toNanos(1), (double)
iteratorDurationMaxMetric.metricValue());
+ assertTrue((double) fetchLatencyMetric.metricValue() > 0.0);
Review Comment:
`fetchSensor` is only recorded from the iterator's `close()` on this path,
so `fetch-latency-avg` is exactly 2.5ms here. Pin it like the duration metrics
instead of `> 0.0`.
##########
streams/src/main/java/org/apache/kafka/streams/state/internals/AbstractMeteredIterator.java:
##########
@@ -0,0 +1,100 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.kafka.streams.state.internals;
+
+import org.apache.kafka.common.metrics.Sensor;
+import org.apache.kafka.common.utils.Time;
+import org.apache.kafka.streams.state.KeyValueIterator;
+
+import java.util.Set;
+import java.util.concurrent.atomic.LongAdder;
+
+/**
+ * Shared metering lifecycle for the metered iterators of the {@code
Metered*WithHeaders} stores,
+ * whatever result type they yield: the {@code KeyValueIterator}s returned by
the store's own range/
+ * fetch/find methods and the {@code ReadOnlyRecordIterator}s that back the
headers-aware IQv2
+ * range/window/session query types.
+ *
+ * <p>Every such iterator opens over a raw {@code KeyValueIterator<RawKey,
byte[]>} and needs the
+ * same bookkeeping: stamp the open time (for the {@code
oldest-iterator-open-since-ms} metric),
+ * register in {@code numOpenIterators}/{@code openIterators}, and on {@link
#close()} record the
+ * operation and iterator-duration sensors and deregister. This base is
deliberately result-type
+ * agnostic -- it implements only {@link MeteredIterator} and does not bind
the yielded key/value
+ * types -- so each subclass declares its own result interface (a {@code
KeyValueIterator} or a
+ * {@code ReadOnlyRecordIterator}) and implements just the parts that
genuinely differ: the
+ * deserializing {@code next()} (and, for the {@code KeyValueIterator}s, a
peeking {@code hasNext()}
+ * and {@code peekNextKey()}).
+ *
+ * @param <RawKey> the raw iterator's key type
+ */
+abstract class AbstractMeteredIterator<RawKey> implements MeteredIterator {
+
+ final KeyValueIterator<RawKey, byte[]> iter;
+ private final Sensor operationSensor;
+ private final Sensor iteratorSensor;
+ private final Time time;
+ private final LongAdder numOpenIterators;
+ private final Set<MeteredIterator> openIterators;
+ private final long startNs;
+ private final long startTimestampMs;
+
+ AbstractMeteredIterator(final KeyValueIterator<RawKey, byte[]> iter,
+ final Sensor operationSensor,
+ final Sensor iteratorSensor,
+ final Time time,
+ final LongAdder numOpenIterators,
+ final Set<MeteredIterator> openIterators) {
+ this.iter = iter;
+ this.operationSensor = operationSensor;
+ this.iteratorSensor = iteratorSensor;
+ this.time = time;
+ this.numOpenIterators = numOpenIterators;
+ this.openIterators = openIterators;
+ this.startNs = time.nanoseconds();
+ this.startTimestampMs = time.milliseconds();
+ numOpenIterators.increment();
+ openIterators.add(this);
+ }
+
+ // Final: the constructor's openIterators.add(this) sorts through this via
the set's
+ // startTimestamp comparator, i.e. on a not-yet-fully-constructed object.
Keeping it final stops a
+ // subclass from overriding it with something that reads its own
not-yet-assigned state.
+ @Override
+ public final long startTimestamp() {
+ return startTimestampMs;
+ }
+
+ /**
+ * Delegates to the raw iterator. Subclasses that buffer a peeked element
(the
+ * {@code KeyValueIterator}s) override this to also account for the
buffered element.
+ */
+ public boolean hasNext() {
+ return iter.hasNext();
+ }
+
+ public void close() {
Review Comment:
Make this `final` too, for the same reason as `startTimestamp()`. No
subclass overrides it today, and one that did and forgot `super.close()` would
silently drop the decrement and the deregistration.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
