apache / apache/druid

Metrics Emitter timeout after 12-16ms

Open
#11,033 6 comments 0 reactions 0 assignees View on GitHub
Area - Metrics/Event Emitting
Dominant language
Java
Stars
14.1k
Forks
3.8k
Avg merge
2d 58m
Merged PRs (30d)
233

Description

Happening in the Broker, but I am fairly sure it happened in Overlord and Coordinator too.

### Affected Version

Druid 0.20.1

### Description

Cluster:
- 2 x Router
- 2 x Overlord
- 2 x Coordinator
- 2 x Brokers
- 32 x Middlemanager
- 32 x Historicals

From time to time we stop receiving metrics on our metrics exporter. Druid logs starts throwing exceptions like:

```
Mar 25 11:40:35 druid-queryserver-1 java[20898]: 2021-03-25T11:40:35,758 ERROR [HttpPostEmitter-1] org.apache.druid.java.util.emitter.core.HttpPostEmitter - Timing out emitter batch send, last batch fill time [8] ms, timeout [16] ms
Mar 25 11:40:35 druid-queryserver-1 java[20898]: 2021-03-25T11:40:35,758 ERROR [HttpPostEmitter-1] org.apache.druid.java.util.emitter.core.HttpPostEmitter - Failed to send events to url[http://druid-exporter-1:8080/druid]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Request timeout to druid-exporter-1/XX.XX.XX.XX:XXXX after 16 ms
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_275]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1908) ~[?:1.8.0_275]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:202) ~[async-http-client-2.5.3.jar:?]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread.send(HttpPostEmitter.java:759) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread.access$1900(HttpPostEmitter.java:464) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread$1.perform(HttpPostEmitter.java:672) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread$1.perform(HttpPostEmitter.java:668) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:87) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:115) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:105) ~[druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread.sendWithRetries(HttpPostEmitter.java:666) [druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread.emit(HttpPostEmitter.java:574) [druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread.emitBatches(HttpPostEmitter.java:550) [druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.apache.druid.java.util.emitter.core.HttpPostEmitter$EmittingThread.run(HttpPostEmitter.java:503) [druid-core-0.20.1.jar:0.20.1]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: Caused by: java.util.concurrent.TimeoutException: Request timeout to druid-exporter-1/XX.XX.XX.XX:XXXX after 16 ms
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:43) ~[async-http-client-2.5.3.jar:?]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:50) ~[async-http-client-2.5.3.jar:?]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[netty-common-4.1.48.Final.jar:4.1.48.Final]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[netty-common-4.1.48.Final.jar:4.1.48.Final]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[netty-common-4.1.48.Final.jar:4.1.48.Final]
Mar 25 11:40:35 druid-queryserver-1 java[20898]: at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_275]
```

I understand that this can timeout if the receiving end is slow, but timeout at 12-16ms? That's a bit excessive.
I was not able to find a config to change this value. Could you point it to me if I missed it??
Thanks a lot!

Contributor guide

Open the contributing guide

Research direction

Start in org.apache.druid.java.util.emitter.core.HttpPostEmitter, especially EmittingThread.send and sendWithRetries, using the reported Druid 0.20.1 stack trace as the entry point. Trace where the 12–16 ms request timeout is obtained and compare it with the emitter configuration; done means the timeout behavior and its configuration are understood and addressed with appropriate coverage.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.