Only wake up from waitDeps to trace when debugging #2176
+15
−1
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
|
Reminder for the PR assignee: If this is a user-visible change, please update the changelog as part of the PR. |
|
I think I actually prefer this simpler diff: diff --git a/internal/dag/walk.go b/internal/dag/walk.go
index d73575cd2f..6c882f87dd 100644
--- a/internal/dag/walk.go
+++ b/internal/dag/walk.go
@@ -408,6 +409,15 @@ func (w *Walker) walkVertex(v Vertex, info *walkerVertex) {
w.diagsLock.Unlock()
}
+func debugTimer() <-chan time.Time {
+ // This is expensive to do at scale, so we only do it when debugging.
+ if logging.IsDebugOrHigher() {
+ return time.After(time.Second * 5)
+ }
+
+ return nil
+}
+
func (w *Walker) waitDeps(
v Vertex,
deps map[Vertex]<-chan struct{},
@@ -429,7 +439,7 @@ func (w *Walker) waitDeps(
doneCh <- false
return
- case <-time.After(time.Second * 5):
+ case <-debugTimer():
log.Printf("[TRACE] dag/walk: vertex %q is waiting for %q",
VertexName(v), VertexName(dep))
}It's a little weird but it has the same result, let me know which you prefer (if any)! |
abstractionfactory
previously approved these changes
Nov 20, 2024
jonjohnsonjr
force-pushed
the
waitDeps
branch
2 times, most recently
from
c27c507
to
4e49b29
Compare
cam72cam
previously approved these changes
Nov 26, 2024
When a vertex is waiting on its dependencies, it blocks on those deps, but it also wakes up every 5 seconds in order to log what it's waiting for. Those logs are immediately discarded unless TRACE logs are enabled. This is similar to opentofu#1810 I've pulled out the timer creation into a separate function which only conditionally creates the timer if debugging logs are enabled. This allows us to avoid creating/selecting on timers at all, which takes up 90% of the waitDeps on-CPU time (and puts additional pressure on the scheduler). Signed-off-by: Jon Johnson <[email protected]>
jonjohnsonjr
force-pushed
the
waitDeps
branch
from
4e49b29
to
22a5b79
Compare
|
Just re-pushed something that (I think) appeases the linter. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
When a vertex is waiting on its dependencies, it blocks on those deps, but it also wakes up every 5 seconds in order to log what it's waiting for. Those logs are immediately discarded unless TRACE logs are enabled.
This is similar to #1810
I've pulled out the timer creation into a separate function which only conditionally creates the timer if debugging logs are enabled. This allows us to avoid creating/selecting on timers at all, which takes up 90% of the waitDeps on-CPU time (and puts additional pressure on the scheduler).
Grabbed some screenshots of perf difference against our (somewhat pathological) workload:
Profiling before (3.6s):
Profiling after (318ms):
Target Release
1.9.0
Checklist
Go checklist
Website/documentation checklist