Skip to content

Conversation

@jmwoliver
Copy link
Contributor

@jmwoliver jmwoliver commented Dec 18, 2025

Removing the slow queue warn log added in #228. We have found this to be very noisy and misleading. Upon further investigation, we found the timer starts at the beginning of the function call and then is designed to wait and loop until there is actual work. On systems that sit idle for a while and then do work, this leads to lots of logs like this:

2025/12/17 21:52:52 WARN Queue Get() process slow time: "239s"
2025/12/17 21:53:52 WARN Queue Get() process slow time: "60s"
2025/12/17 21:59:52 WARN Queue Get() process slow time: "359s"
2025/12/17 22:05:52 WARN Queue Get() process slow time: "359s"
2025/12/17 22:11:52 WARN Queue Get() process slow time: "359s"
2025/12/17 22:16:52 WARN Queue Get() process slow time: "300s"
2025/12/17 22:22:52 WARN Queue Get() process slow time: "359s"
2025/12/17 22:28:52 WARN Queue Get() process slow time: "359s"

We should rework the timing to only count when work is actually running. For now we will remove it and revisit updating the timer more accurately later, tracked in this issue: https://github.com/rstudio/package-manager/issues/16800

More discussion about this issue and investigation here: https://github.com/rstudio/package-manager/issues/16794


Ref https://github.com/rstudio/package-manager/issues/16794

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

After reviewing the logic, it looks like execution time may be miscalculated. In slow-process scenarios, there are two QueuePop calls, and we might need to reset start = time.Now() after the first call, ~line 360.
What do you think?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, but it could even wait/poll during the for loop and we would want to reset it each time. I added an idea of just tracking the timing when doing QueuePop() here: https://github.com/rstudio/package-manager/issues/16800

But I think for this release we should just remove this warn log and revisit it when we have more time.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed

@jmwoliver jmwoliver merged commit fd9d6c7 into main Dec 18, 2025
3 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants