Skip to content
This repository was archived by the owner on May 14, 2026. It is now read-only.

test: fix concurrency issue in testThrottlingBlocking - #2001

Merged
gcf-merge-on-green[bot] merged 4 commits into
googleapis:mainfrom
suztomo:i1193_fix
Sep 18, 2023
Merged

gcf-merge-on-green[bot] merged 4 commits into
googleapis:mainfrom
suztomo:i1193_fix

Conversation

@suztomo

@suztomo suztomo commented Sep 18, 2023 •

Copy link
Copy Markdown
Member

At the end of the test, it verifies that the batcher waited more than throttled time by capturing the argument of callContext.withOption(). There were two problems:

"Zero interactions with this mock" problem

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.

The callContext.withOption method is called by BatcherImpl.sendOutstanding() method via
BatcherImpl$PushCurrentBatchRunnable in another thread.

executor.scheduleWithFixedDelay(runnable, delay, delay, TimeUnit.MILLISECONDS);

Technically, there's no guarantee that the thread calls the withOption method within a certain timeframe, especially when we run the tests concurrently in a machine with many CPU cores (the nightly test setup). That's why we occasionally saw "Zero interactions with this mock" problem.

In my experiment (https://github.com/suztomo/gax-batcher-impl-test-reproducer/blob/main/README.md), increasing 100 ms timeout to 1000 ms just worked good to prevent false positives. The assertion is not about timing, but about BatcherImpl recording the throttled time correctly.

After fixing this problem, then I saw another problem below.

"expected to be at least: 50 but was: 48" problem

[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)

At the end of the test, it verifies that the batcher waited more than throttled time by capturing the argument of callContext.withOption(). In ideal, usual scenarios,

  1. In thread A, the batcher blocks at batcher.add (because of flowController) the thread and starts stopwatch to measure throttled time.
  2. In thread B (created by the BatcherImplTest) sleeps 50 ms (throttledTime)
  3. In thread B, BatcherImplTest calls flowController.release(), which wakes up the thread A.
  4. The batcher records it was blocked more than 50 ms.

However, in rare cases, these events happens in this order:

  1. Thread B starts sleeping 50 ms.
  2. In thread A the batcher blocks at batcher.add (because of flowController) and starts stopwatch to measure throttled time.
  3. In thread B, after 50 ms sleep, BatcherImplTest calls flowController.release(), which wakes up the thread A.
  4. The batcher records it was blocked less than 50 ms. This makes the test assertion fail with "expected to be at least: 50 but was: 48" message.

To prevent this rare case, BatcherImplTest needs to wait before sleeping 50 ms in thread B. In this pull request, I add a do-while loop to check the thread A (the thread of batcher.add) is in Thread.State.WAITING state before making the sleeping of 50 ms.

  • Make sure to open an issue as a bug/issue before writing your code! That way we can discuss the change, evaluate designs, and agree on the general idea
  • Ensure the tests and linter pass
  • Code coverage does not decrease (if any source code was changed)
  • Appropriate docs were updated (if necessary)

Fixes #1193 ☕️

@suztomo
suztomo requested a review from a team September 18, 2023 13:43
@product-auto-label product-auto-label Bot added the size: s Pull request size is small. label Sep 18, 2023
@suztomo

suztomo commented Sep 18, 2023

Copy link
Copy Markdown
Member Author

java-storage downstream test issue is known. Joe is following up.

Error: Failed to execute goal on project google-cloud-storage: Could not resolve dependencies for project com.google.cloud:google-cloud-storage:jar:2.27.0: org.opentest4j:opentest4j:jar:1.3.0 was not found in https://maven-central.storage-download.googleapis.com/maven2/ during a previous attempt. This failure was cached in the local repository and resolution is not reattempted until the update interval of google-maven-central has elapsed or updates are forced -> [Help 1]

@suztomo suztomo added the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
@gcf-owl-bot gcf-owl-bot Bot removed the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
@suztomo
suztomo requested a review from blakeli0 September 18, 2023 14:08
@suztomo suztomo added the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
@gcf-owl-bot gcf-owl-bot Bot removed the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
}

@Test
@Test(timeout = 60000)

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This breaks an infinite loop, if any. The normal execution time is around 1 second. 1 minute should be enough.

@suztomo suztomo added the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
@gcf-owl-bot gcf-owl-bot Bot removed the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
@suztomo suztomo added automerge Merge the pull request once unit tests and other checks pass. owlbot:run Add this label to trigger the Owlbot post processor. labels Sep 18, 2023
@gcf-owl-bot gcf-owl-bot Bot removed the owlbot:run Add this label to trigger the Owlbot post processor. label Sep 18, 2023
@sonarqubecloud

Copy link
Copy Markdown

[gapic-generator-java-root] Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

No Coverage information No Coverage information
0.0% 0.0% Duplication

@sonarqubecloud

Copy link
Copy Markdown

[java_showcase_integration_tests] Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

No Coverage information No Coverage information
0.0% 0.0% Duplication

@gcf-merge-on-green
gcf-merge-on-green Bot merged commit 8fb0bf3 into googleapis:main Sep 18, 2023
@gcf-merge-on-green gcf-merge-on-green Bot removed the automerge Merge the pull request once unit tests and other checks pass. label Sep 18, 2023
@sonarqubecloud

Copy link
Copy Markdown

[java_showcase_unit_tests] Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

No Coverage information No Coverage information
0.0% 0.0% Duplication

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

size: s Pull request size is small.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

gax-java: Flaky BatcherImplTest.testThrottlingBlocking - Zero interactions with this mock

2 participants