sql,util: add vtable for node-local inflight span registry#59492
sql,util: add vtable for node-local inflight span registry#59492craig[bot] merged 1 commit intocockroachdb:masterfrom
Conversation
|
This change is |
30a1a48 to
9c32013
Compare
9c32013 to
8963ff7
Compare
knz
left a comment
There was a problem hiding this comment.
Reviewed 6 of 6 files at r1, 1 of 1 files at r2.
Reviewable status:complete! 0 of 0 LGTMs obtained (waiting on @angelapwen, @irfansharif, and @tbg)
pkg/sql/crdb_internal.go, line 1148 at r1 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
CI is failing on this line with the error
[Test archive] pkg/sql/crdb_internal.go:1148:42: cannot use func literal (type func(*tracing.Span) error) as type func(*tracing.Span) in argument to p.ExecCfg().Settings.Tracer.VisitSpans
It seems to compile fine locally and in fact complains if I remove the
error. Per discussion with @knz I addederrorto theVisitSpansAPI and have added it as an argument whereVisitSpansis used (including here).
The reason why it fails in CI is that you forgot to commit your changes to the VisitSpans function.
pkg/sql/crdb_internal.go, line 1141 at r2 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
Thoughts on the vtable name appreciated! I wonder if it would be more useful to call it
node_inflight_spansconsidering that is what people will be able to access. but the session tracing vtable is calledsession_trace. (I could also make this onenode_inflight_traceto be even more consistent.
node_inflight_spans looks fine, although the uneducated eye may not know what "spans" refers to, so node_inflight_trace_spans might be clearer.
pkg/testutils/testcluster/testcluster.go, line 132 at r2 (raw file):
tracer := tc.Server(i).Tracer().(*tracing.Tracer) testutils.SucceedsSoon(tc.t, func() error { tracer.VisitSpans(func(span *tracing.Span) error {
This is incorrect- you're ignoring the return value of VisitSpans here.
try:
return tracer.VisitSpans(...)
pkg/util/tracing/tracer_test.go, line 343 at r2 (raw file):
func getSortedActiveSpanOps(tr *Tracer) []string { var sl []string tr.VisitSpans(func(sp *Span) error {
_ = tr.VisitSpans(...)
tbg
left a comment
There was a problem hiding this comment.
Looking good!
Reviewed 6 of 6 files at r1, 1 of 1 files at r2.
Reviewable status:
pkg/sql/crdb_internal.go, line 1141 at r2 (raw file):
Previously, knz (kena) wrote…
node_inflight_spanslooks fine, although the uneducated eye may not know what "spans" refers to, sonode_inflight_trace_spansmight be clearer.
node_inflight_trace_spans sounds good to me.
pkg/sql/crdb_internal.go, line 1143 at r2 (raw file):
CREATE TABLE crdb_internal.node_inflight_tracing ( span_id INT NOT NULL, -- The span's ID. trace_id INT NOT NULL, -- The trace's ID.
The trace_id is hierarchically first, so I'd put it at the beginning.
pkg/sql/crdb_internal.go, line 1152 at r2 (raw file):
spanID := rec.SpanID traceID := rec.TraceID spanDuration := rec.Duration
Have you considered adding rec.StartTime here as well? It might be useful to filter on spans that were started during a time window in which an interesting event occurred.
Another one that I think we should definitely add is the OperationName. This is the prime thing we'll look at when finding specific operations.
pkg/sql/logictest/testdata/logic_test/crdb_internal_tenant, line 258 at r2 (raw file):
descriptor_id descriptor_name index_id dependedonby_id dependedonby_type dependedonby_index_id dependedonby_name dependedonby_details
nit: stray newline.
angelapwen
left a comment
There was a problem hiding this comment.
Thanks for the reviews ✨ Left a few clarifying comments and will push up some changes to the table name
Reviewable status:
pkg/sql/crdb_internal.go, line 1148 at r1 (raw file):
Previously, knz (kena) wrote…
The reason why it fails in CI is that you forgot to commit your changes to the VisitSpans function.
Ha.. thank you for the catch.
pkg/sql/crdb_internal.go, line 1141 at r2 (raw file):
Previously, tbg (Tobias Grieger) wrote…
node_inflight_trace_spanssounds good to me.
Thank you both! Sounds good.
pkg/sql/crdb_internal.go, line 1143 at r2 (raw file):
Previously, tbg (Tobias Grieger) wrote…
The trace_id is hierarchically first, so I'd put it at the beginning.
Done.
pkg/sql/crdb_internal.go, line 1152 at r2 (raw file):
Previously, tbg (Tobias Grieger) wrote…
Have you considered adding rec.StartTime here as well? It might be useful to filter on spans that were started during a time window in which an interesting event occurred.
Another one that I think we should definitely add is the OperationName. This is the prime thing we'll look at when finding specific operations.
Interesting. I guess I'd thought that having duration would be equally as good as StartTime. Perhaps we could just have StartTime then and the viewer would be able to figure out the duration (at least in a broad sense) at a glance, but also view spans started in a time window as you mentioned. Or do you think both would be necessary?
I can definitely add OperationName.
pkg/testutils/testcluster/testcluster.go, line 132 at r2 (raw file):
Previously, knz (kena) wrote…
This is incorrect- you're ignoring the return value of
VisitSpanshere.try:
return tracer.VisitSpans(...)
Interesting, I had been trying to replicate the intent of the original code:
cockroach/pkg/testutils/testcluster/testcluster.go
Lines 131 to 137 in 7d27d9a
tracer.VisitSpans() does not itself have a return value at the moment.
8963ff7 to
f1cac16
Compare
angelapwen
left a comment
There was a problem hiding this comment.
Reviewable status:
pkg/sql/crdb_internal.go, line 1152 at r2 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
Interesting. I guess I'd thought that having duration would be equally as good as StartTime. Perhaps we could just have StartTime then and the viewer would be able to figure out the duration (at least in a broad sense) at a glance, but also view spans started in a time window as you mentioned. Or do you think both would be necessary?
I can definitely add OperationName.
I have added OperationName for now.
pkg/testutils/testcluster/testcluster.go, line 132 at r2 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
Interesting, I had been trying to replicate the intent of the original code:
but I did not fully understand it. It seemed that the error was always returned here, and otherwise a nil error was returned.cockroach/pkg/testutils/testcluster/testcluster.go
Lines 131 to 137 in 7d27d9a
tracer.VisitSpans()does not itself have a return value at the moment.
For what it's worth, the TestStopServer test still passes (though I am not sure if it actually tests for this section of the code).
3fc6b20 to
9abe72f
Compare
|
pkg/testutils/testcluster/testcluster.go, line 132 at r2 (raw file): Previously, angelapwen (Angela P Wen) wrote…
Actually, I failed a linter test that there was an unchecked error in |
6e7273b to
0bd55ec
Compare
|
Try this diff, I think we'll need it. diff --git i/pkg/util/tracing/crdbspan.go w/pkg/util/tracing/crdbspan.go
index 4ae2211351..96a9f8455f 100644
--- i/pkg/util/tracing/crdbspan.go
+++ w/pkg/util/tracing/crdbspan.go
@@ -253,15 +253,18 @@ func (s *crdbSpan) getRecordingLocked(m mode) tracingpb.RecordedSpan {
rs.Tags[k] = v
}
+ if rs.Duration == -1 {
+ // -1 indicates an unfinished Span. For a recording it's better to put some
+ // duration in it, otherwise tools get confused. For example, we export
+ // recordings to Jaeger, and spans with a zero duration don't look nice.
+ rs.Duration = timeutil.Now().Sub(rs.StartTime)
+ }
+
// When nobody is configured to see our spans, skip some allocations
// related to Span UX improvements.
onlyBackgroundTracing := m == modeBackground && s.recordingType() == RecordingOff
if !onlyBackgroundTracing {
if rs.Duration == -1 {
- // -1 indicates an unfinished Span. For a recording it's better to put some
- // duration in it, otherwise tools get confused. For example, we export
- // recordings to Jaeger, and spans with a zero duration don't look nice.
- rs.Duration = timeutil.Now().Sub(rs.StartTime)
addTag("_unfinished", "1")
}
if s.mu.recording.recordingType.load() == RecordingVerbose { |
|
@irfansharif Yes, that change fixed the duration 00:00 that was previously recorded for the 2 root spans. Thank you ✨ |
0bd55ec to
9d35516
Compare
|
Not for this PR, but there might be value in allowing for an easy way to distinguish between in-flight spans and Finish()ed ones. #59560 (comment). Perhaps surfacing an |
c0615d8 to
4722bd5
Compare
4722bd5 to
9c0c917
Compare
|
@irfansharif Yeah, I see, it looks like the finish time is not surfaced in the recording but we could theoretically get it by adding duration to start time for Finish()ed spans and leaving the field blank for unfinished spans. The PR is ready for another look, passing CI now. I believe the only open review comment is @knz's on the return value of |
knz
left a comment
There was a problem hiding this comment.
However I'd like to see Irfan and/or Tobias chime in on the changes to crdbspan.go. I think this can be further simplified?
Reviewed 15 of 18 files at r3, 1 of 2 files at r4, 1 of 1 files at r5.
Reviewable status:
pkg/sql/crdb_internal.go, line 1151 at r5 (raw file):
)`, populate: func(ctx context.Context, p *planner, _ *dbdesc.Immutable, addRow func(...tree.Datum) error) error { err := p.ExecCfg().Settings.Tracer.VisitSpans(func(span *tracing.Span) error {
return p.ExecCfg() ...
pkg/testutils/testcluster/testcluster.go, line 132 at r2 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
Actually, I failed a linter test that there was an unchecked error in
VisitSpansso now it does return a value (just error though).
still: return tracer.VisitSpans(...).
pkg/util/tracing/crdbspan.go, line 259 at r5 (raw file):
// related to Span UX improvements. onlyBackgroundTracing := m == modeBackground && s.recordingType() == RecordingOff if !onlyBackgroundTracing {
I think I am confused by the changes to this function. @irfansharif @tbg can you have a look here?
9c0c917 to
f438ae4
Compare
angelapwen
left a comment
There was a problem hiding this comment.
Fixed the style nits. Irfan was the one who recommended the changes to crdbspan.go (though I had to move the location of where the duration is set to after the tags are added, otherwise the "_unfinished" tag was never added). I'm definitely open to further refactoring though! 😸
Reviewable status:
pkg/testutils/testcluster/testcluster.go, line 132 at r2 (raw file):
Previously, knz (kena) wrote…
still:
return tracer.VisitSpans(...).
Done (finally!)
pkg/util/tracing/tracer_test.go, line 343 at r2 (raw file):
Previously, knz (kena) wrote…
_ = tr.VisitSpans(...)
Done!
f438ae4 to
5f892c4
Compare
knz
left a comment
There was a problem hiding this comment.
Reviewed 1 of 18 files at r3, 2 of 2 files at r6.
Reviewable status:
pkg/util/tracing/crdbspan.go, line 259 at r5 (raw file):
Previously, knz (kena) wrote…
I think I am confused by the changes to this function. @irfansharif @tbg can you have a look here?
The real issue here is that there is an unconditional if rs.Duration == -1 { rs.Duration = ... } below.
So if we call getRecordingLocked() before a span is finished, there will never be an opportunity to update the Duration afterwards.
That's why I think the situation is incorrect.
In fact, you can readily see the two ideas conflict with each other: "Duration == -1 indicates the span is unfinished" and "unfinished spans should have a non-negative duration to ease the eyes of the viewer".
The solution here is to reject the idea of storing whether a span is finished or not in the Duration field. Make it a separate (new) boolean finished bool.
Then here in getRecording, update Duration unconditionally when the span is not finished yet.
tbg
left a comment
There was a problem hiding this comment.
Reviewed 14 of 18 files at r3, 1 of 2 files at r4, 1 of 1 files at r5, 2 of 2 files at r6.
Dismissed @angelapwen and @knz from 3 discussions.
Reviewable status:
pkg/cli/zip.go, line 97 at r6 (raw file):
"crdb_internal.node_build_info", "crdb_internal.node_inflight_trace_spans",
I think this is not the best choice UX wise. There may be a bunch of things open, but a lot of them don't matter. I think this should focus on spans that have been open "for some time". You probably talked it through with Raphael, if he thought this was ok as a starting point then it's fine by me. But I would've assumed something like a query
SELECT * FROM crdb_internal.node_inflight_trace_spans WHERE duration > 10*time.Second ORDER BY trace_id ASC, duration DESCDown the road, a textual representation of the spans that can't be manipulated after (it's not like we can reorder this table once it's been dumped to a text file :) ) is the best choice anyway, but it's on par with the rest of the data we dump. Always-on traces don't carry that much information anyway, we mostly care about finding the right goroutine id quickly.
pkg/cli/testdata/zip/partial1, line 178 at r6 (raw file):
retrieving SQL data for crdb_internal.leases... writing: debug/nodes/3/crdb_internal.leases.txt retrieving SQL data for crdb_internal.node_build_info... writing: debug/nodes/3/crdb_internal.node_build_info.txt retrieving SQL data for crdb_internal.node_inflight_trace_spans... writing: debug/nodes/3/crdb_internal.node_inflight_trace_spans.txt
I'm surprised by this large diff, where is this coming from?
pkg/util/tracing/crdbspan.go, line 268 at r4 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
Failing test answered my question, it does need to be moved to just after!
No tags must be added when onlyBackgroundTracing==true, and it's also confusing that there are now two places where we add the _unfinished tag. Just use s.mu.duration to make the determination on the unfinished tag, then you shouldn't need to move any code around and you can set rs.Duration at the top of the function.
pkg/util/tracing/crdbspan.go, line 259 at r5 (raw file):
Previously, knz (kena) wrote…
The real issue here is that there is an unconditional
if rs.Duration == -1 { rs.Duration = ... }below.So if we call
getRecordingLocked()before a span is finished, there will never be an opportunity to update the Duration afterwards.That's why I think the situation is incorrect.
In fact, you can readily see the two ideas conflict with each other: "Duration == -1 indicates the span is unfinished" and "unfinished spans should have a non-negative duration to ease the eyes of the viewer".
The solution here is to reject the idea of storing whether a span is finished or not in the Duration field. Make it a separate (new) boolean
finished bool.
Then here ingetRecording, updateDurationunconditionally when the span is not finished yet.
the RecordedSpan is created on each call to getRecordingLocked, so a new field is not strictly necessary. We get to see the original s.mu.recording on each invocation.
I still think we should add a bool RecordedSpan.Finished, or the vtable won't be able to hide finished spans, which we'll want to do. This would be added in recorded_span.proto.
But, let's not do this in this PR. It is useful to do so in the short term, though. Since every unfinished span can hold a few children alive, it'll be important to show only the unfinished spans in the vtable, and we can't right now.
pkg/util/tracing/tracer.go, line 618 at r6 (raw file):
for _, sp := range sl { if err := visitor(sp); err != nil { return err
if iterutil.Done(err) { return nil }
This allows you to return iterutil.StopIteration() from the visitor to stop visiting more spans gracefully.
This can also be a follow-up PR (ideally with a unit test).
pkg/util/tracing/tracer_test.go, line 341 at r6 (raw file):
} func getSortedActiveSpanOps(tr *Tracer) ([]string, error) {
the preferred pattern for testing helpers is
func getSortedActiveSpanOps(t *testing.T, tr *Tracer) []string {
t.Helper()
require.NoError(t, tr.VisitSpans(/* ... */))
}That way, you don't have to handle an error at each caller.
knz
left a comment
There was a problem hiding this comment.
Reviewable status:
pkg/util/tracing/crdbspan.go, line 259 at r5 (raw file):
Previously, tbg (Tobias Grieger) wrote…
the
RecordedSpanis created on each call togetRecordingLocked, so a new field is not strictly necessary. We get to see the originals.mu.recordingon each invocation.
I still think we should add a boolRecordedSpan.Finished, or the vtable won't be able to hide finished spans, which we'll want to do. This would be added inrecorded_span.proto.But, let's not do this in this PR. It is useful to do so in the short term, though. Since every unfinished span can hold a few children alive, it'll be important to show only the unfinished spans in the vtable, and we can't right now.
ok but then I don't understand why we don't have if rs.Duration == -1 { rs.Duration = ... } at the very top of this function, instead of two times underneath.
tbg
left a comment
There was a problem hiding this comment.
Reviewable status:
pkg/util/tracing/crdbspan.go, line 259 at r5 (raw file):
See my comment below, copied here for your convenience:
No tags must be added when onlyBackgroundTracing==true, and it's also confusing that there are now two places where we add the _unfinished tag. Just use s.mu.duration to make the determination on the unfinished tag, then you shouldn't need to move any code around and you can set rs.Duration at the top of the function.
angelapwen
left a comment
There was a problem hiding this comment.
Reviewable status:
pkg/cli/zip.go, line 97 at r6 (raw file):
Previously, tbg (Tobias Grieger) wrote…
I think this is not the best choice UX wise. There may be a bunch of things open, but a lot of them don't matter. I think this should focus on spans that have been open "for some time". You probably talked it through with Raphael, if he thought this was ok as a starting point then it's fine by me. But I would've assumed something like a query
SELECT * FROM crdb_internal.node_inflight_trace_spans WHERE duration > 10*time.Second ORDER BY trace_id ASC, duration DESCDown the road, a textual representation of the spans that can't be manipulated after (it's not like we can reorder this table once it's been dumped to a text file :) ) is the best choice anyway, but it's on par with the rest of the data we dump. Always-on traces don't carry that much information anyway, we mostly care about finding the right goroutine id quickly.
Hm: actually, I hadn't discussed this part with @knz as I was not aware there was an alternative to dumping the entire table. I see now that there is a custom select clause option. I'd be happy to do so unless Raphael has other thoughts.
pkg/cli/testdata/zip/partial1, line 178 at r6 (raw file):
Previously, tbg (Tobias Grieger) wrote…
I'm surprised by this large diff, where is this coming from?
Yes, I was as well: I ran the TestPartialZip with re-write flags on and resulted in this diff.
After your comment I actually just removed the majority of the diff that was added, only leaving in the node_inflight_trace_spans part and the test also passes, so I'll go ahead and push up the smaller diff.
pkg/sql/crdb_internal.go, line 1151 at r5 (raw file):
Previously, knz (kena) wrote…
return p.ExecCfg() ...
Done! Thanks.
pkg/util/tracing/crdbspan.go, line 268 at r4 (raw file):
Previously, tbg (Tobias Grieger) wrote…
No tags must be added when
onlyBackgroundTracing==true, and it's also confusing that there are now two places where we add the_unfinishedtag. Just uses.mu.durationto make the determination on the unfinished tag, then you shouldn't need to move any code around and you can setrs.Durationat the top of the function.
Done
pkg/util/tracing/crdbspan.go, line 259 at r5 (raw file):
Previously, tbg (Tobias Grieger) wrote…
See my comment below, copied here for your convenience:
No tags must be added when onlyBackgroundTracing==true, and it's also confusing that there are now two places where we add the _unfinished tag. Just use s.mu.duration to make the determination on the unfinished tag, then you shouldn't need to move any code around and you can set rs.Duration at the top of the function.
Thank you both. I'll update rs.Duration at the top of the function, and check s.mu.duration == -1 as Tobi suggested to set the unfinished tag. I agree regarding the Finished field in the proto just after this PR!
pkg/util/tracing/tracer_test.go, line 341 at r6 (raw file):
Previously, tbg (Tobias Grieger) wrote…
the preferred pattern for testing helpers is
func getSortedActiveSpanOps(t *testing.T, tr *Tracer) []string { t.Helper() require.NoError(t, tr.VisitSpans(/* ... */)) }That way, you don't have to handle an error at each caller.
Thank you, that helps a lot! I was wondering why none of the other tests looked like this 😸
cd4a5bc to
30f46d3
Compare
This change adds a virtual table, `crdb_internal.node_inflight_trace_spans` that exposes data on currently inflight spans in the current node. The table includes information on the span IDs, parent span IDs, trace IDs, start time, duration (measured by time of collection - start time of the span), and the span's operation. Release note (sql change): Adds a virtual table, `crdb_internal.node_inflight_trace_spans`, which exposes span ID, parent span ID, trace ID, start time, duration, and operation of node-local inflight spans.
30f46d3 to
fb8c5d8
Compare
|
Alright, I've made the requested changes except for this one on using |
knz
left a comment
There was a problem hiding this comment.
Reviewed 5 of 5 files at r7.
Reviewable status:
pkg/cli/zip.go, line 97 at r6 (raw file):
Previously, angelapwen (Angela P Wen) wrote…
Hm: actually, I hadn't discussed this part with @knz as I was not aware there was an alternative to dumping the entire table. I see now that there is a custom select clause option. I'd be happy to do so unless Raphael has other thoughts.
I think the result now is fine. Thank you.
|
bors r=knz |
|
Build succeeded: |
This change adds a virtual table,
crdb_internal.node_inflight_trace_spansthat exposes data on currently inflight spans in the current node.
The table includes information on the span IDs, parent span IDs, trace IDs,
start time, duration (measured by time of collection - start time of the
span), and the span's operation.
Part 1 of addressing #55733. Will follow up with a built-in that will
allow querying of a particular span ID to surface more detailed
recording information.
Release note (sql change): Adds a virtual table,
crdb_internal.node_inflight_trace_spans, which exposes span ID, parent spanID, trace ID, start time, duration, and operation of node-local inflight spans.