PostingsForMatchersCache: don't create new spans, reduce logging verbosity #575
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
…osity Creating a new span for each promQL matcher for each query can end up being too verbose to navigate in grafana. This PR replaces the span with a trace log. Overall starting a span was also expensive - according to profiles it's about 9% of the CPU of PostingsForMatchers and it's about 25% of the memory allocations. Adding events is about 2% of the CPU and ~5% of the allocations. In addition to that it removes some log lines in `postingsForMatchersPromise` because I think they just log the same thing multiple times. I also removed some calls to AddEvent to amortize the cost of tracing further.
Comment on lines
-187
to
-189
| span.AddEvent("postingsForMatchers succeeded", trace.WithAttributes( | ||
| attribute.String("cache_key", key), | ||
| )) |
There was a problem hiding this comment.
removed this event because it should be accounted for in the "returned postings" log line
Comment on lines
-181
to
-184
| span.AddEvent("postingsForMatchers failed", trace.WithAttributes( | ||
| attribute.String("cache_key", key), | ||
| attribute.String("err", err.Error()), | ||
| )) |
There was a problem hiding this comment.
removed because this should be accounted for in the RecordError calls in PostingsForMatchers
Comment on lines
-129
to
-148
| span.AddEvent("interrupting wait on postingsForMatchers promise due to context error", trace.WithAttributes( | ||
| attribute.String("err", ctx.Err().Error()), | ||
| )) | ||
| return nil, ctx.Err() | ||
| return nil, fmt.Errorf("interrupting wait on postingsForMatchers promise due to context error: %w", ctx.Err()) | ||
| case <-p.done: | ||
| // Checking context error is necessary for deterministic tests, | ||
| // as channel selection order is random | ||
| if ctx.Err() != nil { | ||
| span.AddEvent("completed postingsForMatchers promise, but context has error", trace.WithAttributes( | ||
| attribute.String("err", ctx.Err().Error()), | ||
| )) | ||
| return nil, ctx.Err() | ||
| return nil, fmt.Errorf("completed postingsForMatchers promise, but context has error: %w", ctx.Err()) | ||
| } | ||
| if p.err != nil { | ||
| span.AddEvent("postingsForMatchers promise completed with error", trace.WithAttributes( | ||
| attribute.String("err", p.err.Error()), | ||
| )) | ||
| return nil, p.err | ||
| return nil, fmt.Errorf("postingsForMatchers promise completed with error: %w", p.err) | ||
| } | ||
| span.AddEvent("postingsForMatchers promise completed successfully") |
There was a problem hiding this comment.
adding events means that the error will be duplicated with the RecordError call in PostingsForMatchers. It's also more expensive.
"postingsForMatchers promise completed successfully" should be accounted for in "returned postings"
1 task
aknuds1
reviewed
Dec 13, 2023
dimitarvdimitrov
deleted the
dimitar/postings-for-matchers-reduce-logging
branch
4 tasks
2 tasks
|
I didn't see these spans for ingester queries in Mimir, so created grafana/mimir#8242 |
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.
Follow-up of #553
Creating a new span for each promQL matcher for each query can end up being too verbose to navigate in grafana. This PR replaces the span with a trace log.
Overall starting a span was also expensive - according to profiles it's about 9% of the CPU of PostingsForMatchers and it's about 25% of the memory allocations. Adding events is about 2% of the CPU and ~5% of the allocations.
CPU
CPU Details
Allocations
In addition to that it removes some log lines in
postingsForMatchersPromisebecause I think they just log the same thing multiple times. I also removed some calls to AddEvent to amortize the cost of tracing further.