util/tracing: don't return recordings for non-recording spans#75912
Merged
craig[bot] merged 1 commit intocockroachdb:masterfrom Feb 8, 2022
Merged
Conversation
This patch makes sp.GetRecording() return nil if the span was not recording. This is already what the documentation on GetRecording() was implying, but the actual behavior was different: a non-recording span (that's not a no-op span) would return a non-nil recording consisting only of the the span's metadata. This behavior is not necessarily unreasonable, but it turns out it's a bit dangerous from a performance perspective - there's a cost (e.g. some allocations) for generating this recording, and it was too easy for unsuspecting callers to pay that when they didn't want to. In particular, DistSQL was indiscriminently calling GetRecording() (through its GetTraceData* utilities), and paying this measurable cost unintentionally. Eliminating this cost is particularly important when the Tracer is configured in the "active spans registry" tracing mode; when not in that mode, all the spans would be no-ops and the GetRecording calls were shortcircuited anyway. This is seen in BenchmarkTracing//trace=on, particularly on "3node/scan" which was the benchmark with the bigest difference between tracing on and off. name old time/op new time/op delta Tracing/1node/scan/trace=on-32 214µs ± 4% 206µs ± 5% ~ (p=0.222 n=5+5) Tracing/1node/insert/trace=on-32 338µs ± 5% 334µs ± 4% ~ (p=0.690 n=5+5) Tracing/3node/scan/trace=on-32 515µs ± 3% 484µs ± 3% -6.11% (p=0.008 n=5+5) Tracing/3node/insert/trace=on-32 635µs ± 1% 627µs ± 1% ~ (p=0.095 n=5+5) name old alloc/op new alloc/op delta Tracing/1node/scan/trace=on-32 27.2kB ± 2% 25.6kB ± 2% -5.94% (p=0.008 n=5+5) Tracing/1node/insert/trace=on-32 45.2kB ± 2% 45.5kB ± 2% ~ (p=0.690 n=5+5) Tracing/3node/scan/trace=on-32 83.2kB ± 3% 79.7kB ± 5% ~ (p=0.095 n=5+5) Tracing/3node/insert/trace=on-32 102kB ± 2% 103kB ± 1% ~ (p=0.548 n=5+5) name old allocs/op new allocs/op delta Tracing/1node/scan/trace=on-32 242 ± 1% 229 ± 0% -5.37% (p=0.000 n=5+4) Tracing/1node/insert/trace=on-32 338 ± 1% 339 ± 1% ~ (p=0.563 n=5+5) Tracing/3node/scan/trace=on-32 819 ± 1% 788 ± 6% ~ (p=0.135 n=5+5) Tracing/3node/insert/trace=on-32 871 ± 0% 880 ± 0% +0.99% (p=0.016 n=4+5) This patch also introduces Span.GetConfiguredRecording(), as a simpler flavor of Span.GetRecording(<rec type>). The latter asks the caller for a recording type (for example, one can ask for a Structured recording on a span that's recording verbosely). The need for this flexibility is rare, so `GetConfiguredRecording()` uses the span's current recording mode. Release note: None
Member
abarganier
approved these changes
Feb 7, 2022
Contributor
abarganier
left a comment
There was a problem hiding this comment.
Pretty straightforward, nice optimization!
Reviewable status:
complete! 1 of 0 LGTMs obtained
andreimatei
commented
Feb 7, 2022
Contributor
Author
|
bors r+ |
Contributor
|
Build failed (retrying...): |
Contributor
|
Build succeeded: |
This file contains hidden or 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
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.
This patch makes sp.GetRecording() return nil if the span was not
recording. This is already what the documentation on GetRecording() was
implying, but the actual behavior was different: a non-recording span
(that's not a no-op span) would return a non-nil recording consisting
only of the the span's metadata. This behavior is not necessarily
unreasonable, but it turns out it's a bit dangerous from a performance
perspective - there's a cost (e.g. some allocations) for generating this
recording, and it was too easy for unsuspecting callers to pay that when
they didn't want to. In particular, DistSQL was indiscriminently calling
GetRecording() (through its GetTraceData* utilities), and paying this
measurable cost unintentionally.
Eliminating this cost is particularly important when the Tracer is
configured in the "active spans registry" tracing mode; when not in that
mode, all the spans would be no-ops and the GetRecording calls were
shortcircuited anyway. This is seen in BenchmarkTracing//trace=on,
particularly on "3node/scan" which was the benchmark with the bigest
difference between tracing on and off.
name old time/op new time/op delta
Tracing/1node/scan/trace=on-32 214µs ± 4% 206µs ± 5% ~ (p=0.222 n=5+5)
Tracing/1node/insert/trace=on-32 338µs ± 5% 334µs ± 4% ~ (p=0.690 n=5+5)
Tracing/3node/scan/trace=on-32 515µs ± 3% 484µs ± 3% -6.11% (p=0.008 n=5+5)
Tracing/3node/insert/trace=on-32 635µs ± 1% 627µs ± 1% ~ (p=0.095 n=5+5)
name old alloc/op new alloc/op delta
Tracing/1node/scan/trace=on-32 27.2kB ± 2% 25.6kB ± 2% -5.94% (p=0.008 n=5+5)
Tracing/1node/insert/trace=on-32 45.2kB ± 2% 45.5kB ± 2% ~ (p=0.690 n=5+5)
Tracing/3node/scan/trace=on-32 83.2kB ± 3% 79.7kB ± 5% ~ (p=0.095 n=5+5)
Tracing/3node/insert/trace=on-32 102kB ± 2% 103kB ± 1% ~ (p=0.548 n=5+5)
name old allocs/op new allocs/op delta
Tracing/1node/scan/trace=on-32 242 ± 1% 229 ± 0% -5.37% (p=0.000 n=5+4)
Tracing/1node/insert/trace=on-32 338 ± 1% 339 ± 1% ~ (p=0.563 n=5+5)
Tracing/3node/scan/trace=on-32 819 ± 1% 788 ± 6% ~ (p=0.135 n=5+5)
Tracing/3node/insert/trace=on-32 871 ± 0% 880 ± 0% +0.99% (p=0.016 n=4+5)
Release note: None