Builds: retries sometimes show large gaps in retry timing

[agjohnson]

See parent for more background, but summary of the issue is that concurrency limited builds don't execute retry tasks on a tight schedule (default is 300s). Instead, the gap between retries is anywhere from 5m, 30m, and I've seen 5 hour gaps.

Build task queue contention might be able to explain away a 10 min or maybe 30 min gap, but not consistent gaps and certainly not a 5 hour gap. To me, this feels like something else is happening here.

[humitos]

The big gaps are not because of queue contention, they happen on projects hitting concurrency limit constantly. When the build is mark to be retried in 5 minutes in the future, it's then executed at that time but due to concurrency limit on the project, it's retried again. That happens constantly and then you get these big gaps.

I've only noticed these gaps, but they were always on these type of projects.

[agjohnson]

Not sure I follow. How does a task get a 30 minute or 5 hour gap in between retry tasks then? The task needs to picked up by a worker at retry to evaluate the concurrency limit.

I'm not describing the cumulative difference between commands executing or something, I'm describing the time difference between the worker setting the task to retry and actually picking up the the retried task.

https://onenr.io/0BQ1J0aJ5wx

https://onenr.io/0Zw0J0YrNjv

These are just the two builds I noted before, there are many others and logging has the data on what is actually happening here.

[humitos]

I'm not describing the cumulative difference between commands executing or something, I'm describing the time difference between the worker setting the task to retry and actually picking up the the retried task.

Ah, good point! The only explanation to the screenshot you shared is build queue backed up... but it doesn't make sense to happen that often, and makes me think there should be something else.

[agjohnson]

Yeah definitely. While it could be queue backups, it seems like it would have to be unlikely. I suppose the next step here could be to pull a list of builds that retried repeatedly and test the timings?

It might just be easier to add some code and try to log this scenario when we notice it at the code level. I don't think we have a way to query retries at all, but you can look at the logs for Retrying this task and look for repeat build ids in the columns (you might have to add the column)

https://onenr.io/0BQ1JWmpWwx

But it's still a lot of manual searching, I didn't see any in the handful of builds I tried.

[humitos]

It might just be easier to add some code and try to log this scenario when we notice it at the code level

How are you thinking we can detect this scenario at code level? 🤔

[agjohnson]

I was thinking either storing a history of when tasks are attempted, or if the task gives us the time the task was scheduled to be executed we could also just log the time difference.

[humitos]

I opened #12500 to save Build.task_executed_at when the task containing the build is grabbed by a worker. The worker checks if the build was created or retried more than 10 minutes ago, and logs a warning in that case. This means the build was in the queue waiting for a few time. Would this help?

[agjohnson]

Yeah, that seems like a great place to start. If we need to we could also test something closer to ~6m to get an accurate view of all the occurances of retry time skew but it's the >10min retries that are the most concerning right now.