Skip to content

Commit 41de460

Browse files
authored
[server][test] Fix record-level metric transition timing and test thread leak (linkedin#2553)
[server][test] Fix record-level metric transition timing and test thread leak - StoreIngestionTask: invoke `mayResumeRecordLevelMetricsForCurrentVersion()` inside `processConsumerRecord()` when a partition transitions to complete. Previously this logic ran only on the SIT `run()` thread, while record processing occurs on the StoreBufferDrainer thread. After EOP marked a partition complete, the drainer could process subsequent records before the SIT loop updated `recordLevelMetricEnabled`. The flag is now updated on the drainer thread immediately after the ready-to-serve check so post-EOP records in the same batch emit full metrics. Guarded by `!recordLevelMetricEnabled.get() && !wasComplete && partitionConsumptionState.isComplete()` to trigger only on actual transitions and avoid repeated partition-state scans. - KafkaConsumerServiceDelegatorTest: fix thread leak and misleading assertion in `testKafkaConsumerServiceResubscriptionConcurrency`. Resubscription threads are now always interrupted and joined before assertions to prevent leaks and ensure the real race-condition failure is not masked by thread-state checks. Root cause: - `testRecordLevelMetricForCurrentVersion`: resume logic executed only on the SIT `run()` loop thread. Because record processing flows through `ConsumptionTask → StorePartitionDataReceiver → StoreBufferService → StoreBufferDrainer`, the drainer could process post-EOP records before the SIT loop set `recordLevelMetricEnabled = true`, causing `recordTotalBytesConsumed` to be invoked fewer times than expected. - `testKafkaConsumerServiceResubscriptionConcurrency`: a resubscription thread could terminate after throwing an exception and count down the latch. The thread-state assertion then failed (TERMINATED vs RUNNABLE/WAITING), obscuring the real race assertion and leaking other running threads.
1 parent 1dfec26 commit 41de460

3 files changed

Lines changed: 12 additions & 16 deletions

File tree

clients/da-vinci-client/src/main/java/com/linkedin/davinci/kafka/consumer/StoreIngestionTask.java

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2909,7 +2909,15 @@ public void processConsumerRecord(
29092909
long syncBytesInterval = getSyncBytesInterval(partitionConsumptionState);
29102910
boolean recordsProcessedAboveSyncIntervalThreshold = (syncBytesInterval > 0
29112911
&& (partitionConsumptionState.getProcessedRecordSizeSinceLastSync() >= syncBytesInterval));
2912+
// Capture completion state before the ready-to-serve check so we can detect a transition.
2913+
boolean wasComplete = partitionConsumptionState.isComplete();
29122914
getDefaultReadyToServeChecker().apply(partitionConsumptionState, recordsProcessedAboveSyncIntervalThreshold);
2915+
// Re-evaluate record-level metrics only when the current partition just transitioned to complete, so that records
2916+
// in the same batch as EOP get full metrics without waiting for the next loop cycle. The guard avoids repeatedly
2917+
// scanning all partition states on every record while metrics are still disabled.
2918+
if (!recordLevelMetricEnabled.get() && !wasComplete && partitionConsumptionState.isComplete()) {
2919+
mayResumeRecordLevelMetricsForCurrentVersion();
2920+
}
29132921

29142922
/**
29152923
* Syncing offset checking in syncOffset() should be the very last step for processing a record.

clients/da-vinci-client/src/test/java/com/linkedin/davinci/kafka/consumer/KafkaConsumerServiceDelegatorTest.java

Lines changed: 3 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,6 @@
1010
import static org.mockito.Mockito.reset;
1111
import static org.mockito.Mockito.verify;
1212
import static org.mockito.Mockito.when;
13-
import static org.testng.Assert.assertEquals;
1413
import static org.testng.Assert.assertTrue;
1514

1615
import com.linkedin.davinci.config.VeniceServerConfig;
@@ -358,22 +357,17 @@ public void testKafkaConsumerServiceResubscriptionConcurrency() throws Exception
358357
});
359358
}
360359
long currentTime = System.currentTimeMillis();
361-
Boolean raceConditionFound = countDownLatch.await(30, TimeUnit.SECONDS);
360+
boolean raceConditionFound = countDownLatch.await(30, TimeUnit.SECONDS);
362361
long elapsedTime = System.currentTimeMillis() - currentTime;
362+
// Always clean up threads before asserting so leaked threads don't affect subsequent tests.
363363
for (Thread infiniteSubUnSubThread: infiniteSubUnSubThreads) {
364-
assertTrue(
365-
infiniteSubUnSubThread.getState().equals(Thread.State.WAITING)
366-
|| infiniteSubUnSubThread.getState().equals(Thread.State.TIMED_WAITING)
367-
|| infiniteSubUnSubThread.getState().equals(Thread.State.BLOCKED)
368-
|| infiniteSubUnSubThread.getState().equals(Thread.State.RUNNABLE));
369364
infiniteSubUnSubThread.interrupt();
370365
infiniteSubUnSubThread.join();
371-
assertEquals(Thread.State.TERMINATED, infiniteSubUnSubThread.getState());
372366
}
367+
delegator.close();
373368
Assert.assertFalse(
374369
raceConditionFound,
375370
"Found race condition in KafkaConsumerService with time passed in milliseconds: " + elapsedTime);
376-
delegator.close();
377371
}
378372

379373
private Runnable getResubscriptionRunnableFor(

clients/da-vinci-client/src/test/java/com/linkedin/davinci/kafka/consumer/StoreIngestionTaskTest.java

Lines changed: 1 addition & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1623,13 +1623,7 @@ public void testRecordLevelMetricForCurrentVersion(boolean enableRecordLevelMetr
16231623
StoreIngestionTaskTestConfig config = new StoreIngestionTaskTestConfig(Utils.setOf(PARTITION_FOO), () -> {
16241624
verify(mockAbstractStorageEngine, timeout(TEST_TIMEOUT_MS))
16251625
.put(PARTITION_FOO, putKeyFoo2, ByteBuffer.wrap(ValueRecord.create(SCHEMA_ID, putValue).serialize()));
1626-
/**
1627-
* Verify host-level metrics
1628-
*
1629-
* N.B.: the below verification for {@link HostLevelIngestionStats#recordTotalBytesConsumed(long)} is flaky, and
1630-
* sometimes comes up with 1 fewer invocation than desired (in both branches of the if). The retries mask
1631-
* the issue as the rate of flakiness is low. But there does seem to be something going on here...
1632-
*/
1626+
// Verify host-level metrics
16331627
if (enableRecordLevelMetricForCurrentVersionBootstrapping) {
16341628
verify(mockStoreIngestionStats, timeout(TEST_TIMEOUT_MS).times(3)).recordTotalBytesConsumed(anyLong());
16351629
} else {

0 commit comments

Comments
 (0)