Skip to content

tracing: introduce a StructuredEvent listener#80460

Merged
craig[bot] merged 1 commit intocockroachdb:masterfrom
adityamaru:event-listener
May 16, 2022
Merged

tracing: introduce a StructuredEvent listener#80460
craig[bot] merged 1 commit intocockroachdb:masterfrom
adityamaru:event-listener

Conversation

@adityamaru
Copy link
Copy Markdown
Contributor

@adityamaru adityamaru commented Apr 25, 2022

This change adds an option WithEventListeners(...) that allows for
specifying an EventListener during span creation. An EventListener will
be notified on every StructuredEvent recorded by the span and its children.
The event listeners will be removed once the span is Finish()'ed and will no
longer receive StructuredEvent notifications. Remote spans will notify
the registerd event listeners when the remote span recording is imported into
the span with the event listeners.

The motivation for this change was to allow higher level aggregators
to watch every event without relying on periodically pulling their
root span's Recording. This way the aggregator can be sure not to
miss "important" events that may be rotated out of the underlying
ring buffer due to memory constraints.

Informs: #80395

Release note: None

@cockroach-teamcity
Copy link
Copy Markdown
Member

This change is Reviewable

@adityamaru
Copy link
Copy Markdown
Contributor Author

@andreimatei I took a stab at this and ran some benchmarks, let me know what you think. I might need some help building intuition about which of the below regressions are unexpected/prohibitive.

I ran:
benchdiff/benchdiff --old=11a0a9f420 --new=c5c238efb2 --post-checkout='make buildshort' --count=20 ./pkg/util/tracing | tee out;

(old is master, new is the first commit in this PR)

name                                           old time/op    new time/op    delta
SpanCreation/detached-child=false-24             1.04µs ± 4%    1.05µs ± 2%     ~     (p=0.372 n=20+18)
SpanCreation/detached-child=true-24              1.74µs ± 5%    1.77µs ± 5%     ~     (p=0.176 n=20+20)
Span_GetRecording/child-only-24                  6.76ns ± 0%    6.77ns ± 0%   +0.25%  (p=0.000 n=19+18)
Span_GetRecording/root-child-24                  6.75ns ± 1%    6.77ns ± 0%   +0.34%  (p=0.000 n=20+19)
Span_GetRecording/root-only-24                   6.77ns ± 1%    6.80ns ± 0%   +0.41%  (p=0.000 n=20+16)
Tracer_StartSpanCtx/opts=real,logtag-24           375ns ± 2%     387ns ± 1%   +3.26%  (p=0.000 n=20+18)
Tracer_StartSpanCtx/opts=real-24                  352ns ± 2%     364ns ± 1%   +3.41%  (p=0.000 n=19+19)
Tracer_StartSpanCtx/opts=none-24                  351ns ± 2%     364ns ± 1%   +3.71%  (p=0.000 n=19+19)
Tracer_StartSpanCtx/opts=real,manualparent-24     427ns ± 1%     447ns ± 1%   +4.87%  (p=0.000 n=20+18)
Tracer_StartSpanCtx/opts=real,autoparent-24       402ns ± 1%     423ns ± 1%   +5.38%  (p=0.000 n=20+18)
RecordingWithStructuredEvent-24                  1.81µs ± 1%    1.92µs ± 1%   +6.21%  (p=0.000 n=20+20)

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)
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)
SpanCreation/detached-child=false-24               289B ± 0%      289B ± 0%     ~     (all equal)
SpanCreation/detached-child=true-24                293B ± 0%      293B ± 0%     ~     (all equal)
RecordingWithStructuredEvent-24                    548B ± 0%      576B ± 0%   +5.11%  (p=0.000 n=20+20)


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)
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)
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)
RecordingWithStructuredEvent-24                    10.0 ± 0%      12.0 ± 0%  +20.00%  (p=0.000 n=20+20)

Copy link
Copy Markdown
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.

I'd be curious to see if the StartSpanCtx numbers improve if we remove eventListenerAlloc.

And can you please tell me what the two new allocations in RecordingWithStructuredEvent are?

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)


pkg/util/tracing/crdbspan.go line 131 at r1 (raw file):

	// whenever a Structured event is recorded by the span.
	//
	// Child spans of this span will inherit this list of EventListeners.

s/of this span/


pkg/util/tracing/crdbspan.go line 141 at r1 (raw file):

type eventListener struct {
	Key      string

do the fields need to be exported? Unexported struct with exported fields is weird, I think.


pkg/util/tracing/crdbspan.go line 555 at r1 (raw file):

	}

	// TODO(during review): Should we limit the number of listeners a span can register?

I wouldn't worry about it


pkg/util/tracing/crdbspan.go line 566 at r1 (raw file):

// unregisterEventListenerLocked unregisters a previously registered
// EventListener.
func (s *crdbSpan) unregisterEventListenerLocked(key string) {

do you think we need deregistration? And also the de-duping by key? What use cases do you have in mind?


pkg/util/tracing/crdbspan.go line 587 at r1 (raw file):

	for _, listener := range s.mu.eventListeners {
		wg.Add(1)
		go func(l EventListener) {

why call on a different goroutine, particularly since you keep the mutex for the duration? I pretty sure the overhead of the goroutines will be more than the theoretical parallelization.


pkg/util/tracing/span.go line 485 at r1 (raw file):

	// span recording Structured events during traced operations.
	//
	// Listen can be called concurrently with other Listen calls on the same

I'd either say more or less here. Say that the listener cannot be called concurrently on the same span, and talk about different spans.


pkg/util/tracing/span.go line 487 at r1 (raw file):

	// Listen can be called concurrently with other Listen calls on the same
	// EventListener.
	Listen(event Structured)

I think Notify or Signal would be more common names.


pkg/util/tracing/span.go line 490 at r1 (raw file):

}

// RegisterEventListener adds an EventListener to the span. The listener can

s/can listen/is notified


pkg/util/tracing/span.go line 490 at r1 (raw file):

}

// RegisterEventListener adds an EventListener to the span. The listener can

Let's talk about the relationship, or lack of, with recordings imported from remote spans. Do we call the listener on events from those at import time? (I think we should).


pkg/util/tracing/span.go line 499 at r1 (raw file):

}

// UnregisterEventListener unregisters a previously registered EventListener

if we keep the deregistration, let's specify that, once this returns, no further calls to Listen coming from this span are possible (and so commit to Unregister synchronizing with notifyEventListeners).
But what about children spans? Don't we want a recursive deregstration?
Or again lets consider if deregistration is really necessary.


pkg/util/tracing/span_options.go line 108 at r1 (raw file):

		opts.Parent.i.crdb.mu.Lock()
		defer opts.Parent.i.crdb.mu.Unlock()
		return opts.Parent.i.crdb.mu.eventListeners

I think we need to make a copy here instead of aliasing the parent slice (i.e. make the copy here and not in reset()).
Is it feasible to add a test for this bug? Like, create a parent, add a listener and then race an operation on the parent that touches that listener (e.g. a deregistration) with creating a child creation. Hopefully the race detector will catch it.


pkg/util/tracing/tracer.go line 1035 at r1 (raw file):

	h.childrenAlloc = [4]childRef{}
	h.structuredEventsAlloc = [3]interface{}{}
	h.eventListenerAlloc = [3]eventListener{}

I wouldn't bother with pooling listener slices until it becomes common for spans to have listeners (if ever).


pkg/util/tracing/bench_test.go line 83 at r2 (raw file):

	}

	// Benchmarks with a root and child span.

I find the old structure easier to read because it lists all the benchmarks. I'd rather add a listener parameter to tc (and then don't use unkeyed literals when constructing the array of tests since there'll be too many bools). And this way you can keep the names of the pre-existing benchmarks as they were.

@adityamaru adityamaru force-pushed the event-listener branch 2 times, most recently from 01aa384 to a40901a Compare April 25, 2022 23:44
Copy link
Copy Markdown
Contributor Author

@adityamaru adityamaru left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei and @dt)


pkg/util/tracing/crdbspan.go line 131 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/of this span/

Done.


pkg/util/tracing/crdbspan.go line 141 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

do the fields need to be exported? Unexported struct with exported fields is weird, I think.

Done.


pkg/util/tracing/crdbspan.go line 555 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I wouldn't worry about it

Done.


pkg/util/tracing/crdbspan.go line 566 at r1 (raw file):

do you think we need deregistration?

I mentioned this below, but I don't think we do. I was worried about aggregators outliving the span they were listening on, but it makes more sense to establish a contract that calls out that behaviour as wrong.

Following the above, there is also no need for a key.


pkg/util/tracing/crdbspan.go line 587 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

why call on a different goroutine, particularly since you keep the mutex for the duration? I pretty sure the overhead of the goroutines will be more than the theoretical parallelization.

makes sense, removed.


pkg/util/tracing/span.go line 485 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I'd either say more or less here. Say that the listener cannot be called concurrently on the same span, and talk about different spans.

Done.


pkg/util/tracing/span.go line 487 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think Notify or Signal would be more common names.

changed to Notify


pkg/util/tracing/span.go line 490 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/can listen/is notified

Done.


pkg/util/tracing/span.go line 490 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Let's talk about the relationship, or lack of, with recordings imported from remote spans. Do we call the listener on events from those at import time? (I think we should).

good catch, added to the comment, and also added logic to notify the listener at the time of importing.


pkg/util/tracing/span.go line 499 at r1 (raw file):

But what about children spans? Don't we want a recursive deregstration?

That's a good point and convinces me that maybe we shouldn't have unregistration. My concern initially was the span outliving the object listening in on events, but I think we can rely on listeners to ensure this is not the case.


pkg/util/tracing/span_options.go line 108 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think we need to make a copy here instead of aliasing the parent slice (i.e. make the copy here and not in reset()).
Is it feasible to add a test for this bug? Like, create a parent, add a listener and then race an operation on the parent that touches that listener (e.g. a deregistration) with creating a child creation. Hopefully the race detector will catch it.

oops yeah, you're right. I'll try working on a test.


pkg/util/tracing/tracer.go line 1035 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I wouldn't bother with pooling listener slices until it becomes common for spans to have listeners (if ever).

Done.


pkg/util/tracing/bench_test.go line 83 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I find the old structure easier to read because it lists all the benchmarks. I'd rather add a listener parameter to tc (and then don't use unkeyed literals when constructing the array of tests since there'll be too many bools). And this way you can keep the names of the pre-existing benchmarks as they were.

Makes sense, done.

@adityamaru
Copy link
Copy Markdown
Contributor Author

New benchmark results without the alloc pooling, and after incorporating other comments.

name                                           old time/op    new time/op    delta
Span_GetRecording/root-only-24                   6.73ns ± 0%    6.74ns ± 1%    ~     (p=0.287 n=10+9)
SpanCreation/detached-child=false-24             1.05µs ± 2%    1.05µs ± 3%    ~     (p=0.847 n=9+9)
SpanCreation/detached-child=true-24              1.77µs ± 4%    1.80µs ± 2%    ~     (p=0.116 n=10+8)
Span_GetRecording/child-only-24                  6.70ns ± 0%    6.72ns ± 0%  +0.30%  (p=0.010 n=9+8)
Span_GetRecording/root-child-24                  6.71ns ± 0%    6.73ns ± 1%  +0.37%  (p=0.004 n=8+10)
Tracer_StartSpanCtx/opts=none-24                  354ns ± 2%     357ns ± 1%  +0.68%  (p=0.015 n=9+9)
Tracer_StartSpanCtx/opts=real-24                  353ns ± 1%     358ns ± 2%  +1.33%  (p=0.004 n=10+9)
Tracer_StartSpanCtx/opts=real,logtag-24           375ns ± 3%     381ns ± 1%  +1.44%  (p=0.008 n=10+10)
RecordingWithStructuredEvent-24                  1.84µs ± 1%    1.91µs ± 0%  +4.00%  (p=0.000 n=10+9)
Tracer_StartSpanCtx/opts=real,manualparent-24     428ns ± 1%     449ns ± 1%  +4.71%  (p=0.000 n=10+10)
Tracer_StartSpanCtx/opts=real,autoparent-24       403ns ± 1%     424ns ± 1%  +5.24%  (p=0.000 n=9+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)
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-24                    548B ± 0%      548B ± 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)
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-24                    10.0 ± 0%      10.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)

@adityamaru
Copy link
Copy Markdown
Contributor Author

adityamaru commented Apr 25, 2022

I also ran:

RecordingWithStructuredEvent/without-event-listener vs RecordingWithStructuredEvent/with-event-listener

gceworker-adityamaru% benchstat old new
name                                                 old time/op    new time/op    delta
RecordingWithStructuredEvent/with-event-listener-24    2.25µs ± 0%    2.32µs ± 0%   +3.10%  (p=0.000 n=8+9)

name                                                 old alloc/op   new alloc/op   delta
RecordingWithStructuredEvent/with-event-listener-24      548B ± 0%      564B ± 0%   +2.92%  (p=0.000 n=10+10)

name                                                 old allocs/op  new allocs/op  delta
RecordingWithStructuredEvent/with-event-listener-24      10.0 ± 0%      11.0 ± 0%  +10.00%  (p=0.000 n=10+10)

BenchmarkTracer_StartSpanCtx/opts=real,autoparent vs BenchmarkTracer_StartSpanCtx/opts=real,autoparent,withEventListener

gceworker-adityamaru% benchstat old-start new-start
name                                         old time/op    new time/op    delta
Tracer_StartSpanCtx/opts=real,autoparent-24     565ns ± 2%     565ns ± 1%   ~     (p=0.853 n=10+10)

name                                         old alloc/op   new alloc/op   delta
Tracer_StartSpanCtx/opts=real,autoparent-24     48.0B ± 0%     48.0B ± 0%   ~     (all equal)

name                                         old allocs/op  new allocs/op  delta
Tracer_StartSpanCtx/opts=real,autoparent-24      1.00 ± 0%      1.00 ± 0%   ~     (all equal)

Tracer_StartSpanCtx/opts=real,manualparent-24 vs Tracer_StartSpanCtx/opts=real,manualparent,withEventListener-24

name                                           old time/op    new time/op    delta
Tracer_StartSpanCtx/opts=real,manualparent-24     591ns ± 1%     594ns ± 2%   ~     (p=0.255 n=10+10)

name                                           old alloc/op   new alloc/op   delta
Tracer_StartSpanCtx/opts=real,manualparent-24     48.0B ± 0%     48.0B ± 0%   ~     (all equal)

name                                           old allocs/op  new allocs/op  delta
Tracer_StartSpanCtx/opts=real,manualparent-24      1.00 ± 0%      1.00 ± 0%   ~     (all equal)

@adityamaru adityamaru marked this pull request as ready for review April 26, 2022 00:27
@adityamaru adityamaru requested review from a team and andreimatei April 26, 2022 00:27
Copy link
Copy Markdown
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.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru, @andreimatei, and @dt)


pkg/util/tracing/crdbspan.go line 566 at r1 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

do you think we need deregistration?

I mentioned this below, but I don't think we do. I was worried about aggregators outliving the span they were listening on, but it makes more sense to establish a contract that calls out that behaviour as wrong.

Following the above, there is also no need for a key.

I think we should remove

well, we want the the listener to outlive the span, don't we? One thing I would do is remove the listeners


pkg/util/tracing/span.go line 499 at r1 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

But what about children spans? Don't we want a recursive deregstration?

That's a good point and convinces me that maybe we shouldn't have unregistration. My concern initially was the span outliving the object listening in on events, but I think we can rely on listeners to ensure this is not the case.

I think the Listener should indeed outlive its span. But, I think that once the span is Finish()ed, the Listener shouldn't get any more events (i.e. from the children spans).
I think the way I'd implement it is different than what we currently have: instead of having each span independently have references to its listeners (direct and inherited), I think it might be better if we have spans route their structured events to their parent. We don't want to always do that, for performance, but I think we can do it for all spans that are children (direct on indirect) from a span with a listener. So, I'd have each span maintain a bit saying whether the parent is interested in the events. WDYT?


pkg/util/tracing/span.go line 478 at r3 (raw file):

// EventListener is an object that can be registered to listen for Structured
// events recorded by the span.

nit: s/by the span/by a span and its children


pkg/util/tracing/span.go line 480 at r3 (raw file):

// events recorded by the span.
type EventListener interface {
	// Notify is invoked on every Structured event recorded by the span.

s/by the span/by the span and its hildren, recursively.


pkg/util/tracing/span.go line 492 at r3 (raw file):

// RegisterEventListener adds an EventListener to the span. The listener is
// notified of Structured events recorded by the span and its children.

This says "and its children", but that's not true for the existing children, is it? As written, the listener only applies to future children. I don't think these are the semantics we want; we don't have such asymmetries in other parts of the API (e.g. enabling recording applies to both current and future children). So, if this API stays, I think we definitely want it to apply to the current children.
But, I'd consider if this API is needed. An alternative is to pass the Listener at span creation time as an option - WithListener or such. I think we should definitely do that even if this API stays. But, if we have the creation option, maybe we don't need the dynamic flavor, or at least not initially?
Also see next comment below.


pkg/util/tracing/span_options.go line 108 at r1 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

oops yeah, you're right. I'll try working on a test.

we're still not making a copy :P

Copy link
Copy Markdown
Contributor Author

@adityamaru adityamaru left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru, @andreimatei, and @dt)


pkg/util/tracing/crdbspan.go line 566 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think we should remove

well, we want the the listener to outlive the span, don't we? One thing I would do is remove the listeners

Ahh i misspoke, I meant what I wrote below i.e "span outliving the object listening in on events".


pkg/util/tracing/span.go line 499 at r1 (raw file):

I think it might be better if we have spans route their structured events to their parent

I agree with your point about not supporting dynamic registration for the time being, and only relying on WithEventListeners() passed in on span creation. Assuming we only support WithEventListeners(), when a span records a structured event it'll do something like this? This way it recursively notifies the listeners registered with its parents (direct or indirect).

func (s *span) notifyListeners(item Structured) {
    if s.Parent != nil && s.Parent.RouteToNotifyListeners {
          s.Parent.notifyListeners(item)
     }

     for _, l := range s.listeners {
          l.Notify(item)
     }
}

Remote children will continue to work the same way they do in this PR, i.e. we notify on ImportRemoteSpans.

@adityamaru
Copy link
Copy Markdown
Contributor Author

adityamaru commented Apr 26, 2022

the Listener shouldn't get any more events (i.e. from the children spans)

can you help me understand when we allow a child span to outlive the parent, and if this is a problem since we'll remove the listeners from a span on span.Finish()?

@adityamaru adityamaru requested a review from andreimatei April 26, 2022 21:41
Copy link
Copy Markdown
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.

A span can always outlive its parent. The fact that lifetime of the child is unrelated to the lifetime of the parent can be expressed explicitly when the child is created through the WithFollowsFrom() option. Our tracer ignores that option; only 3rd party OpenTelemetry ones sometimes make use of it. Explicit or not, it's not clear what not allowing a child to outlive the parent would mean. Should uses of a child after the span is finished be considered a use-after-finish (which is a crash in test builds)? Or should the uses of that span be silently ignored? We don't take either of these options, and I think it's for the better.

if this is a problem since we'll remove the listeners from a span on span.Finish()?

I don't think it's a problem, provided that we do things as I was suggesting: have listeners be attached only to a single span, not also attached directly to the parent. The semantics are then clear: you attach a listener to a span and, once that span finishes, the listener will not be notified any more. I think that'd be a good API.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)


pkg/util/tracing/crdbspan.go line 566 at r1 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

Ahh i misspoke, I meant what I wrote below i.e "span outliving the object listening in on events".

my comment here was incomplete/gibberish, as I had moved my real comments elsewhere :)


pkg/util/tracing/span.go line 499 at r1 (raw file):

it'll do something like this?

yeah, that's what I'm thinking. Except I think the RouteToNotifyListeners should live on s, not on s.Parent.

Copy link
Copy Markdown
Contributor Author

@adityamaru adityamaru left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru, @andreimatei, and @dt)


pkg/util/tracing/crdbspan.go line 566 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

my comment here was incomplete/gibberish, as I had moved my real comments elsewhere :)

Done.


pkg/util/tracing/span.go line 499 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

it'll do something like this?

yeah, that's what I'm thinking. Except I think the RouteToNotifyListeners should live on s, not on s.Parent.

Done.


pkg/util/tracing/span.go line 480 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/by the span/by the span and its hildren, recursively.

Done.


pkg/util/tracing/span.go line 492 at r3 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

This says "and its children", but that's not true for the existing children, is it? As written, the listener only applies to future children. I don't think these are the semantics we want; we don't have such asymmetries in other parts of the API (e.g. enabling recording applies to both current and future children). So, if this API stays, I think we definitely want it to apply to the current children.
But, I'd consider if this API is needed. An alternative is to pass the Listener at span creation time as an option - WithListener or such. I think we should definitely do that even if this API stays. But, if we have the creation option, maybe we don't need the dynamic flavor, or at least not initially?
Also see next comment below.

Added a WithListeners option, and removed the register API.

@adityamaru adityamaru force-pushed the event-listener branch 2 times, most recently from 5af4dd6 to 4446ed8 Compare May 1, 2022 21:56
@adityamaru adityamaru requested a review from andreimatei May 1, 2022 21:57

func (ev eventListenersOption) apply(opts spanOptions) spanOptions {
eventListeners := ([]EventListener)(ev)
opts.EventListeners = eventListeners
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

hmm is it better to take a copy here at the cost of an additional alloc?

Copy link
Copy Markdown
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.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru, @andreimatei, and @dt)


pkg/util/tracing/span_options.go line 115 at r7 (raw file):

	var notifyParentOnStructuredEvent bool
	parent := opts.Parent.i.crdb
	if parent == nil {

I don't think this protection is necessary; we don't seem to have it in other places. i.crdb is not nilable now, and I think it cannot be made nil-able in the future without a bunch of refactoring.


pkg/util/tracing/span_options.go line 118 at r7 (raw file):

		return false
	}
	parent.withLock(func() {

let's make this a method on parent - maybe WantEventNotifications().


pkg/util/tracing/span_options.go line 475 at r7 (raw file):

// WithEventListeners registers eventListeners to the span. The listeners are
// notified of Structured events recorded by the span and its children. The

s/The listeners are removed when the span is Finish()'ed./Once the span is finished, the listeners are not notified of events any more even from surviving child spans.
(since there's no "removing" to speak of)


pkg/util/tracing/span_options.go line 479 at r7 (raw file):

//
// The listeners will also be notified of StructuredEvents recorded on remote
// spans, when the Recording is imported using sp.ImportRemoteSpans.

s/when the Recording is imported using sp.ImportRemoteSpans/when the remote recording is imported by the span or one of its children.


pkg/util/tracing/span_options.go line 470 at r8 (raw file):

Previously, adityamaru (Aditya Maru) wrote…

hmm is it better to take a copy here at the cost of an additional alloc?

I don't think we need a copy here; I doubt that any caller would benefit from the option to further mutate the slice (and the callee treats it as read-only, so the caller can also keep using it as read-only, right?). If you want to be pedantic, you can specify on WithEventListeners that the caller shouldn't mutate the slice after the call.

Copy link
Copy Markdown
Contributor Author

@adityamaru adityamaru left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru, @andreimatei, and @dt)


pkg/util/tracing/span_options.go line 115 at r7 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I don't think this protection is necessary; we don't seem to have it in other places. i.crdb is not nilable now, and I think it cannot be made nil-able in the future without a bunch of refactoring.

Done.


pkg/util/tracing/span_options.go line 118 at r7 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

let's make this a method on parent - maybe WantEventNotifications().

Done.


pkg/util/tracing/span_options.go line 475 at r7 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/The listeners are removed when the span is Finish()'ed./Once the span is finished, the listeners are not notified of events any more even from surviving child spans.
(since there's no "removing" to speak of)

Done.


pkg/util/tracing/span_options.go line 479 at r7 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

s/when the Recording is imported using sp.ImportRemoteSpans/when the remote recording is imported by the span or one of its children.

Done.

@adityamaru adityamaru requested a review from andreimatei May 2, 2022 21:17
Copy link
Copy Markdown
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.

Almost there. Please squash the 2nd commit into the first; I don't think there's a reason to make it separate. And please remind me if there's any benchmark differences to note.
But I'd consider not merging this without a user - at least an imminent user in a perhaps different PR. Cause maybe more things will come to light when we try to use the thing.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @adityamaru and @dt)


pkg/util/tracing/crdbspan.go line 481 at r9 (raw file):

	for _, span := range children {
		for _, record := range span.StructuredRecords {
			s.notifyEventListeners(record.Payload)

I think it'd be interesting to note on the listener docs that remote events are imported out of order. That may seem obvious for remote events vs local events, but it's not obvious for remote events ingested at the same time.


pkg/util/tracing/crdbspan.go line 558 at r9 (raw file):

	s.mu.Lock()
	defer s.mu.Unlock()
	if !s.mu.parent.empty() && s.mu.recording.notifyParentOnStructuredEvent {

I think notifyParentOnStructuredEvent should be unset when the parent is reset. That'd be cleaner, and allow us here to not test parent.empty().


pkg/util/tracing/crdbspan.go line 560 at r9 (raw file):

	if !s.mu.parent.empty() && s.mu.recording.notifyParentOnStructuredEvent {
		parent := s.mu.parent.Span.i.crdb
		if parent != nil {

get rid of this protection


pkg/util/tracing/crdbspan.go line 596 at r9 (raw file):
Hmm have we talked about the interactions between recording and listeners? The doc currently says

The listeners are notified of Structured events recorded by the span and its children
If things stay as they are, let's make it a lot more explicit that listeners without recording don't do anything.

I'm not sure what the answer should be. For local events (i.e. on the listener's node), there's no cost to passing the events to the listener even if the span is not recording. But that's not true for remote events, and those wouldn't be ingested with the code as written - which is potentially confusing. On the other hand, making WithListeners imply WithRecording(RecordingStructured) adds some cost. We could imagine extensions to the API that make WithListeners imply recording only on the remote children. Or extensions that serialize and "push" the listener aggregators to remote nodes. But it all seems complicated.
If the first user is jobs, who records any way, I'd say let's make WithListeners imply a minimum level of recording (i.e. structured) and document it as such. Of course, if WithRecording(RecordingVerbose) is specified, that should override.


Relatedly, there's the issue of the relationship with the WithForceRealSpan option. If the Tracer is not configured with WithTracingMode(TracingModeActiveRegistry), then specifying WithListeners() in isolation is useless. So, I think WithListeners should imply WithForceRealSpans. That would happen implicitly if we make it imply WithRecording(...).


pkg/util/tracing/tracer.go line 1190 at r9 (raw file):

		traceID, spanID, opName, uint64(goid.Get()),
		startTime, opts.LogTags, opts.EventListeners, opts.SpanKind,
		otelSpan, netTr, opts.Sterile, notifyParentOnStructuredEvent)

Instead of passing notifyParentOnStructuredEvent to newSpan, I think we should leave newSpan alone (it doesn't seem to know about parents at the moment) and do the work below, where we link the new span to the parent (i.e. just below the s.i.crdb.mu.parent = opts.Parent.move() line).
Also, I don't think the opts struct should have the notifyParentOnStructuredEvent(); let's also move that logic here and keep opts dumb. I'm sorry I didn't say that before; I hadn't realized where the code I was reading was.


pkg/util/tracing/span_test.go line 716 at r9 (raw file):

func TestEventListener(t *testing.T) {
	ctx := context.Background()
	tr := NewTracerWithOpt(ctx, WithTracingMode(TracingModeActiveSpansRegistry))

do we need the WithTracingMode option? I don't think we do, since the test is always recording.


pkg/util/tracing/span_test.go line 758 at r9 (raw file):

	sp.Finish()
}

I'd add a test with a parent finishing before a child, and checking that child events are not seen by a listener registered on the parent.

Copy link
Copy Markdown
Contributor Author

@adityamaru adityamaru left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @andreimatei and @dt)


pkg/util/tracing/crdbspan.go line 481 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think it'd be interesting to note on the listener docs that remote events are imported out of order. That may seem obvious for remote events vs local events, but it's not obvious for remote events ingested at the same time.

Done.


pkg/util/tracing/crdbspan.go line 558 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think notifyParentOnStructuredEvent should be unset when the parent is reset. That'd be cleaner, and allow us here to not test parent.empty().

Done.


pkg/util/tracing/crdbspan.go line 560 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

get rid of this protection

Done.


pkg/util/tracing/crdbspan.go line 596 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Hmm have we talked about the interactions between recording and listeners? The doc currently says

The listeners are notified of Structured events recorded by the span and its children
If things stay as they are, let's make it a lot more explicit that listeners without recording don't do anything.

I'm not sure what the answer should be. For local events (i.e. on the listener's node), there's no cost to passing the events to the listener even if the span is not recording. But that's not true for remote events, and those wouldn't be ingested with the code as written - which is potentially confusing. On the other hand, making WithListeners imply WithRecording(RecordingStructured) adds some cost. We could imagine extensions to the API that make WithListeners imply recording only on the remote children. Or extensions that serialize and "push" the listener aggregators to remote nodes. But it all seems complicated.
If the first user is jobs, who records any way, I'd say let's make WithListeners imply a minimum level of recording (i.e. structured) and document it as such. Of course, if WithRecording(RecordingVerbose) is specified, that should override.


Relatedly, there's the issue of the relationship with the WithForceRealSpan option. If the Tracer is not configured with WithTracingMode(TracingModeActiveRegistry), then specifying WithListeners() in isolation is useless. So, I think WithListeners should imply WithForceRealSpans. That would happen implicitly if we make it imply WithRecording(...).

Good point, I've changed the WithEventListeners option to imply RecordingStructured. If a span has a WithRecording(...) we will respect that instead cause it can only be used to set the recording to structured or verbose.


pkg/util/tracing/span_options.go line 108 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

we're still not making a copy :P

Stale comment post refactors, done.


pkg/util/tracing/tracer.go line 1190 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

Instead of passing notifyParentOnStructuredEvent to newSpan, I think we should leave newSpan alone (it doesn't seem to know about parents at the moment) and do the work below, where we link the new span to the parent (i.e. just below the s.i.crdb.mu.parent = opts.Parent.move() line).
Also, I don't think the opts struct should have the notifyParentOnStructuredEvent(); let's also move that logic here and keep opts dumb. I'm sorry I didn't say that before; I hadn't realized where the code I was reading was.

Done.


pkg/util/tracing/span_test.go line 716 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

do we need the WithTracingMode option? I don't think we do, since the test is always recording.

Done.


pkg/util/tracing/span_test.go line 758 at r9 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I'd add a test with a parent finishing before a child, and checking that child events are not seen by a listener registered on the parent.

Done.

@adityamaru
Copy link
Copy Markdown
Contributor Author

I'd consider not merging this without a user

Given the merge conflicts that might arise from #81079, I'm leaning towards checking this in. I did whip up #81270 as a prototype of how this can/will be used.

@adityamaru adityamaru requested a review from andreimatei May 16, 2022 00:49
@andreimatei
Copy link
Copy Markdown
Contributor

ok, merge ahead

This change adds an option `WithEventListeners(...)` that allows for
specifying an EventListener during span creation. An EventListener will
be notified on every StructuredEvent recorded by the span and its children.
The event listeners will be removed once the span is Finish()'ed and will no
longer receive StructuredEvent notifications. Remote spans will notify
the registerd event listeners when the remote span recording is imported into
the span with the event listeners.

The motivation for this change was to allow higher level aggregators
to watch every event without relying on periodically pulling their
root span's Recording. This way the aggregator can be sure not to
miss "important" events that may be rotated out of the underlying
ring buffer due to memory constraints.

Informs: cockroachdb#80395

Release note: None
@adityamaru
Copy link
Copy Markdown
Contributor Author

Benchmarks don't show anything notable, thanks for the review! Will merge on green.

building benchmark binaries for 'd5b3fe7' 1/1 /
test binaries already exist for '8f28fb9'; skipping build

  pkg=1/1 iter=10/10 cockroachdb/cockroach/pkg/util/tracing /

name                                           old time/op    new time/op    delta
Tracer_StartSpanCtx/opts=real-24                  352ns ± 2%     354ns ± 0%    ~     (p=0.092 n=10+10)
SpanCreation/detached-child=false-24             1.04µs ± 2%    1.04µs ± 1%    ~     (p=0.493 n=10+10)
SpanCreation/detached-child=true-24              1.74µs ± 4%    1.71µs ± 3%    ~     (p=0.108 n=10+9)
Tracer_StartSpanCtx/opts=real,logtag-24           376ns ± 1%     380ns ± 1%  +1.00%  (p=0.002 n=10+9)
Tracer_StartSpanCtx/opts=none-24                  351ns ± 1%     356ns ± 1%  +1.45%  (p=0.000 n=9+10)
Tracer_StartSpanCtx/opts=real,autoparent-24       405ns ± 1%     411ns ± 0%  +1.49%  (p=0.000 n=10+8)
Tracer_StartSpanCtx/opts=real,manualparent-24     427ns ± 0%     440ns ± 1%  +3.12%  (p=0.000 n=10+10)
RecordingWithStructuredEvent-24                  1.99µs ± 1%    2.05µs ± 1%  +3.23%  (p=0.000 n=10+10)
Span_GetRecording/root-only-24                   6.78ns ± 0%    7.43ns ± 0%  +9.63%  (p=0.000 n=9+9)
Span_GetRecording/child-only-24                  6.76ns ± 0%    7.43ns ± 0%  +9.87%  (p=0.000 n=10+9)
Span_GetRecording/root-child-24                  6.77ns ± 0%    7.44ns ± 0%  +9.90%  (p=0.000 n=9+9)

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)
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-24                    740B ± 0%      740B ± 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)
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-24                    12.0 ± 0%      12.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)

@adityamaru
Copy link
Copy Markdown
Contributor Author

bors r=andreimatei

@craig
Copy link
Copy Markdown
Contributor

craig bot commented May 16, 2022

Build succeeded:

@craig craig bot merged commit 711ccb5 into cockroachdb:master May 16, 2022
@adityamaru adityamaru deleted the event-listener branch May 17, 2022 14:41
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