You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@druid.apache.org by GitBox <gi...@apache.org> on 2022/04/15 22:11:15 UTC
[GitHub] [druid] harinirajendran opened a new issue, #11414: Kafka ingestion lag spikes up whenever tasks are rolling
harinirajendran opened a new issue, #11414:
URL: https://github.com/apache/druid/issues/11414
### Affected Version
0.21
### Description
We have a druid cluster in which we are ingesting about 2.5M events/second. We have 90 ingestion tasks for 1 of our data sources with task duration set to 1 hr. Whenever the tasks roll every hour, Kafka ingestion lag spikes up anywhere from 3M to even 15M `druid.ingest.kafka.lag`. On further analysis, we noted that while tasks are rolling, some of the active ingestion tasks are stuck in `pause` state for a long time (sometimes up to 1.5-2 minutes) during which those tasks aren't ingesting any data resulting in ingestion lag spike.
Logs from MM tasks with a huge gap between `pause` and `resume`
```
{"@timestamp":"2021-06-21T17:34:51.628Z", "log.level":"DEBUG", "message":"Received pause command, pausing ingestion until resumed.", "service.name":"druid/middleManager","event.dataset":"druid/middleManager.log","process.thread.name":"task-runner-0-priority-0","log.logger":"org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner"}
{"@timestamp":"2021-06-21T17:36:27.089Z", "log.level":"DEBUG", "message":"Received pause command, pausing ingestion until resumed.", "service.name":"druid/middleManager","event.dataset":"druid/middleManager.log","process.thread.name":"task-runner-0-priority-0","log.logger":"org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner"}
{"@timestamp":"2021-06-21T17:36:27.097Z", "log.level":"DEBUG", "message":"Received resume command, resuming ingestion.", "service.name":"druid/middleManager","event.dataset":"druid/middleManager.log","process.thread.name":"task-runner-0-priority-0","log.logger":"org.apache.druid.indexing.seekablestream.SeekableStreamIndexTaskRunner"}
```
In the above loglines, we can see that that task was in `pause` state from `17:34:51` to `17:36:27`.
On further analysis, we figured out that the MM taskRunner goes to a pause state when it is requesting a `checkpoint` notice [here](https://github.com/apache/druid/blob/8264203cee688607091232897749e959e7706010/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/SeekableStreamIndexTaskRunner.java#L729).
From the time the taskRunner submits the checkpoint notice, it actually takes around 1.5 minutes for the coordinator to actually process this checkpoint notice. We can see it in the coordinator logs below for a specific task.
```
Jun 21, 2021 @ 17:34:51.624 Performing action for task[<task_id>]: CheckPointDataSourceMetadataAction{supervisorId='<supervisor_id>', taskGroupId='14', checkpointMetadata=KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream='<kafka-topic>', partitionSequenceNumberMap={104=238760642689, 14=337995870870}, exclusivePartitions=[]}}} coordinator-0
Jun 21, 2021 @ 17:34:51.624 Checkpointing [KafkaDataSourceMetadata{SeekableStreamStartSequenceNumbers=SeekableStreamStartSequenceNumbers{stream='<kafka-topic>', partitionSequenceNumberMap={104=238760642689, 14=337995870870}, exclusivePartitions=[]}}] for taskGroup [14] coordinator-0
Jun 21, 2021 @ 17:36:27.086 Pause task[<task_id>] coordinator-0
Jun 21, 2021 @ 17:36:27.087 HTTP POST: http://<MMHost:MMport>/druid/worker/v1/chat/<task_id>/pause coordinator-0
Jun 21, 2021 @ 17:36:27.089 SetEndOffsets task[<task_id>] endOffsets[{104=238763631003, 14=337998805846}] finalize[false] coordinator-0
Jun 21, 2021 @ 17:36:27.089 Task [<task_id>] paused successfully coordinator-0
Jun 21, 2021 @ 17:36:27.091 HTTP POST: http://<MMHost:MMport>/druid/worker/v1/chat/<task_id>/offsets/end?finish=false coordinator-0
Jun 21, 2021 @ 17:36:27.097 Handled checkpoint notice, new checkpoint is [{104=238763631003, 14=337998805846}] for taskGroup [14] coordinator-0
```
Note that this long pause of ingestion task happens **only** when tasks are rolling. Not during other times.
Our guess here is that, while tasks are rolling, the [notices queue](https://github.com/confluentinc/druid/blob/0.21.0-confluent/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java#L752) has a lot of notices in them and each notice takes a long time to be processed thus causing significant delay in the `checkpoint` notice as well to be processed once its added to the queue.
Currently, we do not have logs in place to figure out how many notices are there in this queue at any point and how long does each notice takes to get executed.
Spent some more time analyzing further and we saw that some of the following functions [here](https://github.com/apache/druid/blob/master/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java#L1447) are taking multiple seconds when tasks are rolling as opposed to few milliseconds when tasks aren't.
```
discoverTasks();
updateTaskStatus();
checkTaskDuration();
checkPendingCompletionTasks();
checkCurrentTaskState();
```
Some of the above functions require checking task status and that seems to be taking a long time.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] jasonk000 commented on issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by "jasonk000 (via GitHub)" <gi...@apache.org>.
jasonk000 commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1546534220
@harinirajendran , can you confirm if this is still an issue with Druid 25?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
Re: [I] Kafka ingestion lag spikes up whenever tasks are rolling (druid)
Posted by "gianm (via GitHub)" <gi...@apache.org>.
gianm commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-2835791554
I think there are actually two root causes of ingestion lag:
1. Bottlenecks in the Overlord around operations like leader failover, task discovery, segment allocations. If the Overlord cannot execute these operations quickly then ingestion tasks will at some point get stalled. (For example: if a task gets data for a new time period, it cannot proceed until a segment is allocated.)
2. When the Overlord rolls tasks, it first tells the old ones to stop ingesting, then it launches new ones. This means that there is always a stall of roughly task-launch-time whenever a roll happens.
A lot of work has been done on area (1), recently led by @kfaraz. In an earlier comment I listed some enhancements that were made in Druid 25. Since then, there has been more work, a few highlights including:
- Batch segment allocation enabled by default: https://github.com/apache/druid/pull/13942
- Reduced metadata store usage during segment allocation: https://github.com/apache/druid/pull/17496
- Segment metadata cache on the Overlord (ships in Druid 33 but not yet on by default): https://github.com/apache/druid/pull/17653
- Improve concurrency in TaskQueue (hasn't shipped yet): https://github.com/apache/druid/pull/17828
There are other PRs too, these are just the first few that come to mind.
As far as I know, there hasn't been work done on (2). In most of our production environments this is a source of small but noticeable lag. When we use the k8s launcher, it's generally 10–15s of lag each rollover period. The main reason that tasks are rolled like this is that the new tasks have their start offsets included in the task spec, so they can't be created until the old tasks stop reading. This could be fixed by doing something like:
- Remove start offsets from the task spec
- Add a `setStartOffsets` API call that the Overlord should call when it knows the start offsets
- The Overlord should launch the new tasks early. To make this possible it needs to have a little warning of when the new tasks will be needed (maybe 1 minute). For `taskDuration` based rollover this is easy. For `maxRowsPerSegment` or `maxTotalRows` based rollover, the supervisor doesn't have visibility into the numbers, so it will need to retrieve them from tasks periodically in order to get proper warning.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] gianm commented on issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by GitBox <gi...@apache.org>.
gianm commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1105898687
> The log line I searched was something like `Started ServerConnector@6e475994{HTTP/1.1, (http/1.1)}{0.0.0.0:8102}` which happens roughly at the 4th second after the tasks start. And runNotice at the overlord gets stuck [here](https://github.com/confluentinc/druid/blob/0.21.0-confluent/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java#L1442) for that duration until task can respond to the `/status` call. This is my observation. Does it make sense?
@harinirajendran It does make sense. Out of curiosity -- what did you have chatThreads set to? I wonder if your number of tasks is much higher than your number of chat threads, and that caused the delays to compound.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] harinirajendran commented on issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by GitBox <gi...@apache.org>.
harinirajendran commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1108858672
> > The log line I searched was something like `Started ServerConnector@6e475994{HTTP/1.1, (http/1.1)}{0.0.0.0:8102}` which happens roughly at the 4th second after the tasks start. And runNotice at the overlord gets stuck [here](https://github.com/confluentinc/druid/blob/0.21.0-confluent/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java#L1442) for that duration until task can respond to the `/status` call. This is my observation. Does it make sense?
>
> @harinirajendran It does make sense. Out of curiosity -- what did you have chatThreads set to? I wonder if your number of tasks is much higher than your number of chat threads, and that caused the delays to compound.
@gianm : We just use the default value for chatThreads. The document says `default == min(10, taskCount * replicas)` . So, it should be 10 in our case.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] harinirajendran commented on issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by GitBox <gi...@apache.org>.
harinirajendran commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1100437789
We solved this problem by switching from Middle Managers to Indexers. The hourly spikes don't happen anymore.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
Re: [I] Kafka ingestion lag spikes up whenever tasks are rolling (druid)
Posted by "FrankChen021 (via GitHub)" <gi...@apache.org>.
FrankChen021 commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-2804382488
Let me pop up this issue to discuss. I think the PRs linked in this issue does not solve the problem from the root. And the last reply suggested that even after these PRs have been applied, the problem is still there.
If we are going to transit to K8S-based ingestion, I'm worried about the lag problem will be magnified because K8S scheduling introduces extra latency such as POD resource allocation(especially LocalPV), image pulling from remote repository. Based on my observations, the latency can be seconds. This means for K8S-based ingestion, tasks start slower than they do Middle Managers.
I'm wondering if you have any plans or any ideas to solve this problem, including the latency introduced by the K8S scheduling? @gianm @maytasm
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] gianm commented on issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by GitBox <gi...@apache.org>.
gianm commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1105898543
> The log line I searched was something like `Started ServerConnector@6e475994{HTTP/1.1, (http/1.1)}{0.0.0.0:8102}` which happens roughly at the 4th second after the tasks start. And runNotice at the overlord gets stuck [here](https://github.com/confluentinc/druid/blob/0.21.0-confluent/indexing-service/src/main/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java#L1442) for that duration until task can respond to the `/status` call. This is my observation. Does it make sense?
It does make sense. Out of curiosity -- what did you have chatThreads set to? I wonder if your number of tasks is much higher than your number of chat threads, and that caused the delays to compound.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
Re: [I] Kafka ingestion lag spikes up whenever tasks are rolling (druid)
Posted by "maytasm (via GitHub)" <gi...@apache.org>.
maytasm commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-2840513462
One more thing to add to (2) from the above, the PR https://github.com/apache/druid/pull/14533 may also help with (2). This may help if the supervisor is configured with a lot of tasks (and/or stopTaskCount is large) or many supervisors roll over at the same time.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
Re: [I] Kafka ingestion lag spikes up whenever tasks are rolling (druid)
Posted by "layoaster (via GitHub)" <gi...@apache.org>.
layoaster commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1852413230
FYI this is still an issue on Druid 27.0.0. I had set a task duration of 10 min (to reduce querying load on MMs peons) and you can see avg lag spikes matches the task roll period.
This is currently not a big deal because we have low traffic but when testing but higher volumes the spikes become a real burden because the lag spikes cannot be reduced within the 10 min period so the lag keeps increasing.
And like the OP, the Kafka tasks reports the highest avg pending time.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] harinirajendran closed issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by GitBox <gi...@apache.org>.
harinirajendran closed issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
URL: https://github.com/apache/druid/issues/11414
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] gianm commented on issue #11414: Kafka ingestion lag spikes up whenever tasks are rolling
Posted by GitBox <gi...@apache.org>.
gianm commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-1311505442
Some recent work in this area of SeekableStreamSupervisor:
- Eliminate some unnecessary metadata calls: https://github.com/apache/druid/pull/13328
- Don't ever queue more than one RunNotice at a time: https://github.com/apache/druid/pull/13334
- Contact tasks asynchronously, eliminate `chatThreads`, reduce load on `workerThreads`: https://github.com/apache/druid/pull/13354
We are targeting Druid 25 for all of these. If anyone has a chance to try these patches out in advance of the release, please let us know!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
Re: [I] Kafka ingestion lag spikes up whenever tasks are rolling (druid)
Posted by "zargor (via GitHub)" <gi...@apache.org>.
zargor commented on issue #11414:
URL: https://github.com/apache/druid/issues/11414#issuecomment-2870064625
> One more thing to add to (2) from the above, the PR [#14533](https://github.com/apache/druid/pull/14533) may also help with (2). This may help if the supervisor is configured with a lot of tasks (and/or stopTaskCount is large) or many supervisors roll over at the same time.
@maytasm This looks promising. Is the property mentioned, avaialble in later versions of druid, in particular `v30.0.0` ?
(we experience this issue during peak hours when more load occurs, and the lag spikes steeply, and hourly)
I would also try to follow @gianm 's comment 👍
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org