Repository navigation
gax-java: Flaky BatcherImplTest.testThrottlingBlocking - Zero interactions with this mock #1193
Description
Activity
There's been many attempts to fix it with no luck: googleapis/gax-java#1615.
@burkedavison How often did you see this? I haven't seen it in a while, like Mike mentioned, there has been some attempts and it should be less frequent now. If this still happens pretty often, we should prioritize it again.
So far, it's happened only once.
Noticed a different flaky tests in
ScheduledRetryingExecutorTest.testCancelOuterFutureBeforeStartError: Tests run: 30, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 4.38 s <<< FAILURE! - in com.google.api.gax.retrying.ScheduledRetryingExecutorTest Error: com.google.api.gax.retrying.ScheduledRetryingExecutorTest.testCancelOuterFutureBeforeStart[Custom retry settings: false] Time elapsed: 0.023 s <<< FAILURE! org.mockito.exceptions.verification.NoInteractionsWanted: No interactions wanted here: -> at com.google.api.gax.retrying.AbstractRetryingExecutorTest.testCancelOuterFutureBeforeStart(AbstractRetryingExecutorTest.java:247) But found this interaction on mock 'tracer': -> at com.google.api.gax.retrying.FailingCallable.call(FailingCallable.java:85) Actually, above is the only interaction with this mock. at com.google.api.gax.retrying.AbstractRetryingExecutorTest.testCancelOuterFutureBeforeStart(AbstractRetryingExecutorTest.java:247)See the exact log here
Noticed another occurrence of this flaky test.
Another, different flaky test in
HttpJsonDirectServerStreamingCallableTest.testServerStreamingError: com.google.api.gax.httpjson.HttpJsonDirectServerStreamingCallableTest.testServerStreaming Time elapsed: 10.068 s <<< FAILURE! value of: await(...) expected to be true at com.google.api.gax.httpjson.HttpJsonDirectServerStreamingCallableTest.testServerStreaming(HttpJsonDirectServerStreamingCallableTest.java:211)Noticed another occurrence of this flaky test.
Another, different flaky test in
AbstractRetryingExecutorTest.testCancelOuterFutureBeforeStartError: Failures: Error: ScheduledRetryingExecutorTest>AbstractRetryingExecutorTest.testCancelOuterFutureBeforeStart:247 No interactions wanted here: -> at com.google.api.gax.retrying.AbstractRetryingExecutorTest.testCancelOuterFutureBeforeStart(AbstractRetryingExecutorTest.java:247) But found this interaction on mock 'tracer': -> at com.google.api.gax.retrying.FailingCallable.call(FailingCallable.java:85) Actually, above is the only interaction with this mock.Flaked last night on Mac
Flaked on nightly Ubuntu
7 remaining items
https://github.com/googleapis/gapic-generator-java/actions/runs/4727585757/jobs/8388342665
Error: Tests run: 25, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 36.4 s <<< FAILURE! - in com.google.api.gax.batching.BatcherImplTest Error: com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking Time elapsed: 0.136 s <<< FAILURE! adding elements to batcher should be blocked by FlowControlled at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:885)https://github.com/googleapis/sdk-platform-java/actions/runs/4986876999/jobs/8928104258
Error: com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking Time elapsed: 0.083 s <<< FAILURE! expected to be at least: 50 but was : 47 at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:902)I spent a little time when I first got it to try and replicate it using the steps from googleapis/gax-java#1775 but unfortunately wasn't able to replicate it. I chatted with @burkedavison about whether increasing the timeout was worth doing but ultimately since this happens infrequently, I didn't implement anything and haven't looked at it in a while. I'm going to unassign myself and bump down to a P3 as it currently is not a priority.
Failed on Java8 for Windows:
Error: Failures: Error: BatcherImplTest.testThrottlingBlocking:899 apiCallContext.withOption( <Capturing argument>, <Capturing argument> ); Wanted 1 time: -> at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:899) But was 0 times.Failed on Java8 for Windows:
Error: Failures: Error: BatcherImplTest.testThrottlingBlocking:899 apiCallContext.withOption( <Capturing argument>, <Capturing argument> ); Wanted 1 time: -> at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:899) But was 0 times. [INFO] Error: Tests run: 552, Failures: 1, Errors: 0, Skipped: 0#1957
Failed on Java 11 for Windows:Error: Failures: Error: BatcherImplTest.testThrottlingBlocking:899 Wanted but not invoked: apiCallContext.withOption( <Capturing argument>, <Capturing argument> ); -> at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:899) Actually, there were zero interactions with this mock.#1955
Fialed on Java 8 for Windows:Error: Failures: Error: BatcherImplTest.testThrottlingBlocking:899 apiCallContext.withOption( <Capturing argument>, <Capturing argument> ); Wanted 1 time: -> at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:899) But was 0 times.- changed the title
[-]gax-java: Flaky BatcherImplTest.testThrottlingBlocking[/-][+]gax-java: Flaky BatcherImplTest.testThrottlingBlocking - Zero interactions with this mock[/+]on Sep 7, 2023 Reproduce the issue
Install the required modules locally
~/sdk-platform-java $ mvn -am -pl gax-java/gax installIntelliJ's repeat test N times (This didn't work)
I tried to run the test 100 times and it failed at 2nd run.
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@497486b3[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@736caf7a[Wrapped task = com.google.api.gax.batching.BatcherImpl$PushCurrentBatchRunnable@4ce7fffa]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@63f8276e[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 74] at java.base/java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) at java.base/java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:340) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.scheduleWithFixedDelay(ScheduledThreadPoolExecutor.java:680) at java.base/java.util.concurrent.Executors$DelegatedScheduledExecutorService.scheduleWithFixedDelay(Executors.java:788) at com.google.api.gax.batching.BatcherImpl.<init>(BatcherImpl.java:206) at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking(BatcherImplTest.java:855)Maybe the test method is not meant to run twice on the same instance.
Repeat 100 times with shell script (It didn't work)
at sdk-platform-java repository clone directory:
$ repeat 100 mvn -pl gax-java/gax test -Dtest="BatcherImplTest#testThrottlingBlocking" -Dfmt.skipIt all succeeded, unfortunately. I think the sequential execution nature does not work to reproduce the issue.
Run the tests concurrently (It worked)
I created a project to run the test concurrently.
https://github.com/suztomo/gax-batcher-impl-test-reproducer/blob/main/README.md
I'm now able to reproduce the problem.
Understand the test
Next step: read the test code.
- Batcher: "Represents a batching context where individual elements will be accumulated and flushed in a large batch request at some point in the future. The buffered elements can be flushed manually or when triggered by an internal threshold. This is intended to be used for high throughput scenarios at the cost of latency. Batcher instances are not thread safe. To use across different threads, create a new Batcher instance per thread."
new BatcherImpl<>( SQUARER_BATCHING_DESC_V2, callLabeledIntSquarer, labeledIntList, settings, EXECUTOR, flowController, callContext) - FlowController: "Provides flow control capability."
FlowController flowController = new FlowController( FlowControlSettings.newBuilder() .setLimitExceededBehavior(LimitExceededBehavior.Block) .setMaxOutstandingElementCount(1L) .build());
Next step: Where should
callContext.withOption(key, value)be supposed to be called?It seems within
BatcherImpl.sendOutstanding().BatcherImpl$PushCurrentBatchRunnable'srun()method callssendOutstanding().PushCurrentBatchRunnableis submitted in BatcherImpl's constructor:scheduledFuture = executor.scheduleWithFixedDelay(runnable, delay, delay, TimeUnit.MILLISECONDS);With debug logging, logback, and jul-to-slf4j bridge (776eb1e), I got the following logging output (a normal successful invocation):
09:51:52.154 [main] INFO c.g.api.gax.batching.BatcherImplTest -- Starting testThrottlingBlocking 09:51:53.089 [pool-2-thread-1] DEBUG c.g.api.gax.batching.BatcherImplTest -- calling batcher.add(1) 09:51:53.113 [main] DEBUG c.g.api.gax.batching.BatcherImplTest -- Caught TimeoutException as expected 09:51:53.113 [main] DEBUG c.g.api.gax.batching.BatcherImplTest -- calling future.get(3, TimeUnit.SECONDS) 09:51:53.152 [pool-2-thread-2] DEBUG c.g.api.gax.batching.BatcherImplTest -- calling flowController.release() 09:51:53.153 [pool-2-thread-2] DEBUG c.g.api.gax.batching.BatcherImplTest -- finished flowController.release() 09:51:53.175 [pool-2-thread-1] DEBUG c.g.api.gax.batching.BatcherImplTest -- batcher.add(1) finished 09:51:53.176 [main] DEBUG c.g.api.gax.batching.BatcherImplTest -- finished future.get(3, TimeUnit.SECONDS) 09:51:53.186 [pool-1-thread-1] DEBUG c.g.api.gax.batching.BatcherImpl -- callContext.withOption called 09:51:53.193 [main] DEBUG c.g.api.gax.batching.BatcherImplTest -- Mockito.verify(callContext, ...) succeeded 09:51:53.215 [main] INFO c.g.api.gax.batching.BatcherImplTest -- Finishing testThrottlingBlockingThere are three threads: main, pool-1-thread-1, pool-2-thread-1, and pool-2-thread-2.
BatcherImpl$PushCurrentBatchRunnable uses pool-1-thread-1. While it tries to check the need of
callContext.withOptionevery 1 millisecond, there's no guarantee that the event on the pool-1-thread-1 thread runs before main thread'sMockito.verify(callContext, Mockito.timeout..operation.Simply increasing the timeout value in Mockito.verify(callContext, Mockito.timeout...) from 100 to 1000 resulted in another error:
[ERROR] Failures: [ERROR] BatcherImplTest.testThrottlingBlocking:903 expected to be at least: 50 but was : 48What does that
callContext.withOptions(total_throttled_time, 48)mean?The Javadoc tells it's "for tracking batch total throttled time".
It's how much FlowController blocked.
While it got 10 milliseconds lag, there's no guarantee that
batcher.addis called beforeThread.sleep(throttledTime).
02:49:56.358 [gax-test06][main] INFO c.g.api.gax.batching.BatcherImplTest -- Starting testThrottlingBlocking 02:49:59.283 [gax-test06][pool-3-thread-1] DEBUG c.g.api.gax.batching.BatcherImplTest -- calling batcher.add(1) 02:49:59.287 [gax-test06][pool-3-thread-2] DEBUG c.g.api.gax.batching.BatcherImplTest -- start sleeping 50 ms 02:49:59.293 [gax-test06][pool-3-thread-1] DEBUG c.g.api.gax.batching.BatcherImpl -- stopwatch started 02:49:59.297 [gax-test06][main] DEBUG c.g.api.gax.batching.BatcherImplTest -- Caught TimeoutException as expected 02:49:59.297 [gax-test06][main] DEBUG c.g.api.gax.batching.BatcherImplTest -- calling future.get(3, TimeUnit.SECONDS) 02:49:59.337 [gax-test06][pool-3-thread-2] DEBUG c.g.api.gax.batching.BatcherImplTest -- Sleep finished. Calling flowController.release() 02:49:59.338 [gax-test06][pool-3-thread-2] DEBUG c.g.api.gax.batching.BatcherImplTest -- finished flowController.release() 02:49:59.340 [gax-test06][pool-3-thread-1] DEBUG c.g.api.gax.batching.BatcherImpl -- stopwatch.elapsed (throttledTimeMs): 48 02:49:59.355 [gax-test06][pool-3-thread-1] DEBUG c.g.api.gax.batching.BatcherImpl -- add() called with throttledTimeMs= 48 (now totalThrottledTimeMs: 48) 02:49:59.364 [gax-test06][pool-2-thread-1] DEBUG c.g.api.gax.batching.BatcherImpl -- callContext.withOption called 02:49:59.371 [gax-test06][pool-3-thread-1] DEBUG c.g.api.gax.batching.BatcherImplTest -- batcher.add(1) finished 02:49:59.376 [gax-test06][main] DEBUG c.g.api.gax.batching.BatcherImplTest -- finished future.get(3, TimeUnit.SECONDS) 02:49:59.391 [gax-test06][main] DEBUG c.g.api.gax.batching.BatcherImplTest -- Mockito.verify(callContext, ...) succeeded [ERROR] com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking_gax_test06 -- Time elapsed: 5.138 s <<< FAILURE! expected to be at least: 50 but was : 48 at com.google.api.gax.batching.BatcherImplTest.testThrottlingBlocking_gax_test06(BatcherImplTest.java:926)When the sleeping(50 ms) before flowController.release starts earlier than
BatcherImpl's stopwatch start time, the recorded throttledTime may
be shorter than throttledTime.Normal case:
- throttle start (stopwatch start)
- sleep(50 ms) starts
- sleep(50 ms) finishes and calls flowController.release
- stopwatch finishes, recording more than or equal to 50 ms.
Rare case:
- sleep(50 ms) starts
- throttle start (stopwatch start)
- sleep(50 ms) finishes and calls flowController.release
- stopwatch finishes, recording less than 50 ms.
assertThat(value.getValue()).isAtLeast(throttledTime)fails.
To avoid such bad operation order, we can make the "sleep(50 ms)" start only after the thread of "throttle start (stopwatch start)" becomes WAITING state:
List<Thread> batcherAddThreadHolder = Collections.synchronizedList(new ArrayList<>()); Future future = executor.submit( new Runnable() { Thread batcherAddThread; @Override public void run() { batcherAddThreadHolder.add(Thread.currentThread()); logger.fine("calling batcher.add(1)"); batcher.add(1); logger.fine("batcher.add(1) finished"); } }); do { // Wait until batcher.add blocks and starts the stopwatch. Thread.sleep(10); } while (batcherAddThreadHolder.isEmpty() || batcherAddThreadHolder.get(0).getState() != Thread.State.WAITING);- Batcher: "Represents a batching context where individual elements will be accumulated and flushed in a large batch request at some point in the future. The buffered elements can be flushed manually or when triggered by an internal threshold. This is intended to be used for high throughput scenarios at the cost of latency. Batcher instances are not thread safe. To use across different threads, create a new Batcher instance per thread."
- added a commit that references this issue
on Sep 18, 2023
The below test failed and then passed on rerun.