Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tracing: use timeutil for Now() and Since() #91289

Merged
merged 1 commit into from
Nov 4, 2022

Conversation

yuzefovich
Copy link
Member

@yuzefovich yuzefovich commented Nov 4, 2022

Previously, for performance reasons (as well as a few others) we used
time.Now() and time.Since in the tracing library. But the work in
f782e45 alleviated those concerns, so
we can now switch to using timeutil library in two places.

Tracer_StartSpanCtx/opts=none-24                                    508ns ± 0%     512ns ± 0%  +0.80%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real-24                                    510ns ± 1%     515ns ± 1%  +0.96%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,logtag-24                             539ns ± 1%     544ns ± 1%  +0.90%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent-24                         480ns ± 0%     486ns ± 1%  +1.26%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent-24                       523ns ± 1%     527ns ± 1%  +0.91%  (p=0.004 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener-24       755ns ± 0%     765ns ± 0%  +1.40%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24     547ns ± 1%     552ns ± 1%  +0.89%  (p=0.000 n=10+10)
Span_GetRecording/root-only-24                                     7.36ns ± 0%    6.75ns ± 0%  -8.26%  (p=0.000 n=10+10)
Span_GetRecording/child-only-24                                    7.36ns ± 0%    6.75ns ± 0%  -8.30%  (p=0.000 n=10+10)
Span_GetRecording/root-child-24                                    7.36ns ± 0%    6.74ns ± 0%  -8.32%  (p=0.000 n=10+10)
RecordingWithStructuredEvent/with-event-listener-24                3.47µs ± 1%    3.47µs ± 1%    ~     (p=0.541 n=10+10)
RecordingWithStructuredEvent/without-event-listener-24             3.31µs ± 0%    3.32µs ± 1%    ~     (p=0.271 n=10+10)
SpanCreation/detached-child=false-24                               1.07µs ± 1%    1.07µs ± 1%    ~     (p=0.955 n=10+10)
SpanCreation/detached-child=true-24                                1.84µs ± 1%    1.82µs ± 1%  -1.30%  (p=0.000 n=10+10)

And no changes in allocations.

Epic: None

Release note: None

@yuzefovich yuzefovich requested review from andreimatei and a team November 4, 2022 16:13
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@yuzefovich
Copy link
Member Author

Am I missing something here for why we're using the local time in this one spot?

Copy link
Contributor

@andreimatei andreimatei left a comment

Choose a reason for hiding this comment

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

:lgtm:

Am I missing something here for why we're using the local time in this one spot?

I think there used to be a significant performance penalty for using timeutil.Now in Since calculations before f782e45

Please run the benchmarks in the tracing package to see if they say anything.

And remove the tracer.go linter exception from lint_test.go. There's crdbspan.go in there too, because it uses time.Since(); I think it can use timeutil.Since() and also be removed from the exemptions.

Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained

@yuzefovich yuzefovich force-pushed the tracing-utc-start-time branch from b016757 to 9047185 Compare November 4, 2022 17:41
Previously, for performance reasons (as well as a few others) we used
`time.Now()` and `time.Since` in the tracing library. But the work in
f782e45 alleviated those concerns, so
we can now switch to using `timeutil` library in two places.
```
Tracer_StartSpanCtx/opts=none-24                                    508ns ± 0%     512ns ± 0%  +0.80%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real-24                                    510ns ± 1%     515ns ± 1%  +0.96%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,logtag-24                             539ns ± 1%     544ns ± 1%  +0.90%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent-24                         480ns ± 0%     486ns ± 1%  +1.26%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent-24                       523ns ± 1%     527ns ± 1%  +0.91%  (p=0.004 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener-24       755ns ± 0%     765ns ± 0%  +1.40%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24     547ns ± 1%     552ns ± 1%  +0.89%  (p=0.000 n=10+10)
Span_GetRecording/root-only-24                                     7.36ns ± 0%    6.75ns ± 0%  -8.26%  (p=0.000 n=10+10)
Span_GetRecording/child-only-24                                    7.36ns ± 0%    6.75ns ± 0%  -8.30%  (p=0.000 n=10+10)
Span_GetRecording/root-child-24                                    7.36ns ± 0%    6.74ns ± 0%  -8.32%  (p=0.000 n=10+10)
RecordingWithStructuredEvent/with-event-listener-24                3.47µs ± 1%    3.47µs ± 1%    ~     (p=0.541 n=10+10)
RecordingWithStructuredEvent/without-event-listener-24             3.31µs ± 0%    3.32µs ± 1%    ~     (p=0.271 n=10+10)
SpanCreation/detached-child=false-24                               1.07µs ± 1%    1.07µs ± 1%    ~     (p=0.955 n=10+10)
SpanCreation/detached-child=true-24                                1.84µs ± 1%    1.82µs ± 1%  -1.30%  (p=0.000 n=10+10)
```
And no changes in allocations.

Epic: None

Release note: None
@yuzefovich yuzefovich force-pushed the tracing-utc-start-time branch from 9047185 to ab51513 Compare November 4, 2022 17:56
@yuzefovich yuzefovich changed the title tracing: use UTC time for "startTime" of spans tracing: use timeutil for Now() and Since() Nov 4, 2022
@yuzefovich
Copy link
Member Author

TFTR!

The benchmarks didn't show changes:

name                                                             old time/op    new time/op    delta
Tracer_StartSpanCtx/opts=none-24                                    508ns ± 0%     512ns ± 0%  +0.80%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real-24                                    510ns ± 1%     515ns ± 1%  +0.96%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,logtag-24                             539ns ± 1%     544ns ± 1%  +0.90%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent-24                         480ns ± 0%     486ns ± 1%  +1.26%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent-24                       523ns ± 1%     527ns ± 1%  +0.91%  (p=0.004 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener-24       755ns ± 0%     765ns ± 0%  +1.40%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24     547ns ± 1%     552ns ± 1%  +0.89%  (p=0.000 n=10+10)
Span_GetRecording/root-only-24                                     7.36ns ± 0%    6.75ns ± 0%  -8.26%  (p=0.000 n=10+10)
Span_GetRecording/child-only-24                                    7.36ns ± 0%    6.75ns ± 0%  -8.30%  (p=0.000 n=10+10)
Span_GetRecording/root-child-24                                    7.36ns ± 0%    6.74ns ± 0%  -8.32%  (p=0.000 n=10+10)
RecordingWithStructuredEvent/with-event-listener-24                3.47µs ± 1%    3.47µs ± 1%    ~     (p=0.541 n=10+10)
RecordingWithStructuredEvent/without-event-listener-24             3.31µs ± 0%    3.32µs ± 1%    ~     (p=0.271 n=10+10)
SpanCreation/detached-child=false-24                               1.07µs ± 1%    1.07µs ± 1%    ~     (p=0.955 n=10+10)
SpanCreation/detached-child=true-24                                1.84µs ± 1%    1.82µs ± 1%  -1.30%  (p=0.000 n=10+10)

name                                                             old alloc/op   new alloc/op   delta
Tracer_StartSpanCtx/opts=none-24                                    48.0B ± 0%     48.0B ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real-24                                    48.0B ± 0%     48.0B ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,logtag-24                             48.0B ± 0%     48.0B ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent-24                         48.0B ± 0%     48.0B ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent-24                       48.0B ± 0%     48.0B ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener-24       96.0B ± 0%     96.0B ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24     48.0B ± 0%     48.0B ± 0%    ~     (all equal)
Span_GetRecording/root-only-24                                      0.00B          0.00B         ~     (all equal)
Span_GetRecording/child-only-24                                     0.00B          0.00B         ~     (all equal)
Span_GetRecording/root-child-24                                     0.00B          0.00B         ~     (all equal)
RecordingWithStructuredEvent/with-event-listener-24                1.26kB ± 0%    1.26kB ± 0%    ~     (all equal)
RecordingWithStructuredEvent/without-event-listener-24             1.22kB ± 0%    1.22kB ± 0%    ~     (all equal)
SpanCreation/detached-child=false-24                                 289B ± 0%      289B ± 0%    ~     (all equal)
SpanCreation/detached-child=true-24                                  293B ± 0%      293B ± 0%    ~     (all equal)

name                                                             old allocs/op  new allocs/op  delta
Tracer_StartSpanCtx/opts=none-24                                     1.00 ± 0%      1.00 ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real-24                                     1.00 ± 0%      1.00 ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,logtag-24                              1.00 ± 0%      1.00 ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent-24                          1.00 ± 0%      1.00 ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent-24                        1.00 ± 0%      1.00 ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,autoparent,withEventListener-24        2.00 ± 0%      2.00 ± 0%    ~     (all equal)
Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24      1.00 ± 0%      1.00 ± 0%    ~     (all equal)
Span_GetRecording/root-only-24                                       0.00           0.00         ~     (all equal)
Span_GetRecording/child-only-24                                      0.00           0.00         ~     (all equal)
Span_GetRecording/root-child-24                                      0.00           0.00         ~     (all equal)
RecordingWithStructuredEvent/with-event-listener-24                  20.0 ± 0%      20.0 ± 0%    ~     (all equal)
RecordingWithStructuredEvent/without-event-listener-24               18.0 ± 0%      18.0 ± 0%    ~     (all equal)
SpanCreation/detached-child=false-24                                 6.00 ± 0%      6.00 ± 0%    ~     (all equal)
SpanCreation/detached-child=true-24                                  6.00 ± 0%      6.00 ± 0%    ~     (all equal)

@yuzefovich
Copy link
Member Author

WDYT about backporting to 22.2?

@yuzefovich
Copy link
Member Author

bors r+

@craig
Copy link
Contributor

craig bot commented Nov 4, 2022

Build succeeded:

@craig craig bot merged commit c57b340 into cockroachdb:master Nov 4, 2022
@yuzefovich yuzefovich deleted the tracing-utc-start-time branch November 4, 2022 20:47
@andreimatei
Copy link
Contributor

WDYT about backporting to 22.2?

Where did non-UTC timestamps show up exactly? (you seem to have deleted this from the commit msg for some reason :P )

@yuzefovich
Copy link
Member Author

I probably just never mentioned that - the way I got here was by trying to determine the time when a particular stmt bundle was collected, so I found startTime field in trace.json and then looked at the code to see whether it was in UTC or not.

@andreimatei
Copy link
Contributor

That's not reason enough for a backport IMO.

@yuzefovich
Copy link
Member Author

Ack.

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