druid icon indicating copy to clipboard operation
druid copied to clipboard

HttpPostEmitter back off send() busy-loop

Open jasonk000 opened this issue 3 years ago • 5 comments

Description

Introduce a back-off to the HttpPostEmitter send() thread loop to minimise the amount of log spamming and CPU.

Fixes #11279.

Introduce HttpPostEmitterLoggerStressTest

Introduce a test to count how many logged events are triggered during a loop scenario. It confirms that no more than some maximum send timeout log events are written in duration of the test. Test runs typically for 6 seconds, and expects limit of 1000 send attempts in that 6 second period.

Currently, the HttpPostEmitter thread submits 150K events in the test window.

[ERROR] Failures: 
[ERROR] org.apache.druid.java.util.emitter.core.HttpPostEmitterLoggerStressTest.testBurstFollowedByQuietPeriod(org.apache.druid.java.util.emitter.core.HttpPostEmitterLoggerStressTest)
[ERROR]   Run 1: HttpPostEmitterLoggerStressTest.testBurstFollowedByQuietPeriod:98 too many timeouts (159620), expect less than (1000)
[ERROR]   Run 2: HttpPostEmitterLoggerStressTest.testBurstFollowedByQuietPeriod:98 too many timeouts (166201), expect less than (1000)
[ERROR]   Run 3: HttpPostEmitterLoggerStressTest.testBurstFollowedByQuietPeriod:98 too many timeouts (173177), expect less than (1000)
[ERROR]   Run 4: HttpPostEmitterLoggerStressTest.testBurstFollowedByQuietPeriod:98 too many timeouts (175135), expect less than (1000)

Introduce a backoff to the send() loop when the specific timeout is experienced.

A simple backoff is chosen at 1/5th the minimum time.

An alternative solution which might be better involves a larger rewrite of this class, as the class currently splits responsibilities for managing the batching and sending across multiple classes and threads. A simpler codebase might run a simpler submission loop with a more explicit throttle and batching mechanism instead of the current batching handoffs.

This PR has:

  • [x] been self-reviewed.
    • [ ] N/A using the concurrency checklist (Remove this item if the PR doesn't have any relation to concurrency.)
  • [x] added documentation for new or modified features or behaviors.
  • [x] added Javadocs for most classes and all non-trivial methods. Linked related entities via Javadoc links.
  • [ ] N/A added or updated version, license, or notice information in licenses.yaml
  • [x] added comments explaining the "why" and the intent of the code wherever would not be obvious for an unfamiliar reader.
  • [x] added unit tests or modified existing tests to cover new code paths, ensuring the threshold for code coverage is met.
  • [ ] N/A added integration tests.
  • [ ] been tested in a test Druid cluster.

jasonk000 avatar Dec 28 '21 23:12 jasonk000

This pull request has been marked as stale due to 60 days of inactivity. It will be closed in 4 weeks if no further activity occurs. If you think that's incorrect or this pull request should instead be reviewed, please simply write any comment. Even if closed, you can still revive the PR at any time or discuss it on the [email protected] list. Thank you for your contributions.

stale[bot] avatar Apr 17 '22 14:04 stale[bot]

Hi @FrankChen021 - do you have suggestions on taking forward this PR? it seems straightforward to me, let me know if you suggest more tests etc or should I tag another reviewer?

jasonk000 avatar Apr 23 '22 00:04 jasonk000

This issue is no longer marked as stale.

stale[bot] avatar Apr 23 '22 00:04 stale[bot]

@abhishekagarwal87 is this something you could take a look at too?

jasonk000 avatar May 20 '22 14:05 jasonk000

Sure @jasonk000. Hoping to review it sometime next week.

abhishekagarwal87 avatar May 20 '22 15:05 abhishekagarwal87

Adding some more background to this -- on clusters where we do not run this patch, we regularly see CPUs pinned in this code.

This node has five cores dedicated to spinning in this loop, which plays havoc with our scaling policy and metrics.

image

Here is a flamegraph with HttpPostEmitter highlighted image


A more serious edition, which I had to scroll down to capture, 25 CPUs pegged in this loop:

image image

I've highlighted HttpPostEmitter here, totalling 98.4% of all samples: image

jasonk000 avatar Nov 09 '22 21:11 jasonk000