Metrics Emitter timeout after 12-16ms
- 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
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