From 9c606cc663ee2fb0f2dc4d97e2f597457614280d Mon Sep 17 00:00:00 2001 From: Yahor Yuzefovich Date: Thu, 25 Feb 2021 16:34:40 -0800 Subject: [PATCH 1/2] colflow: do not set redundant tag on the tracing span This is unnecessary given that we're setting the componentID below that includes the flowID. Release justification: low-risk update to new functionality. Release note: None --- pkg/sql/colflow/vectorized_flow.go | 1 - 1 file changed, 1 deletion(-) diff --git a/pkg/sql/colflow/vectorized_flow.go b/pkg/sql/colflow/vectorized_flow.go index 397ec6d73104..7be228e2a463 100644 --- a/pkg/sql/colflow/vectorized_flow.go +++ b/pkg/sql/colflow/vectorized_flow.go @@ -960,7 +960,6 @@ func (s *vectorizedFlowCreator) setupOutput( // At the last outbox, we can accurately retrieve stats for the // whole flow from parent monitors. These stats are added to a // flow-level span. - span.SetTag(execinfrapb.FlowIDTagKey, flowCtx.ID) span.SetSpanStats(&execinfrapb.ComponentStats{ Component: execinfrapb.FlowComponentID(base.SQLInstanceID(outputStream.OriginNodeID), flowCtx.ID), FlowStats: execinfrapb.FlowStats{ From d37ee52ead421bbf5b9c8e66b19acedfdd0b7b1a Mon Sep 17 00:00:00 2001 From: Yahor Yuzefovich Date: Thu, 25 Feb 2021 17:00:08 -0800 Subject: [PATCH 2/2] tracing: do not set tags when setting stats We no longer need to set tags on the tracing span in order to propagate stats since we now propagate that info as a whole object (at the moment, twice - as a Structured payload and as DeprecatedStats protobuf; the latter will be removed after 21.1 branch is cut). Release justification: low-risk update to new functionality. Release note: None --- pkg/sql/opt/exec/execbuilder/testdata/select | 42 +++++++++---------- pkg/sql/rowflow/BUILD.bazel | 2 + pkg/sql/rowflow/routers_test.go | 44 ++++++++++++-------- pkg/sql/trace_test.go | 4 +- pkg/util/tracing/span.go | 3 -- 5 files changed, 51 insertions(+), 44 deletions(-) diff --git a/pkg/sql/opt/exec/execbuilder/testdata/select b/pkg/sql/opt/exec/execbuilder/testdata/select index b607f591804f..e778cab380ca 100644 --- a/pkg/sql/opt/exec/execbuilder/testdata/select +++ b/pkg/sql/opt/exec/execbuilder/testdata/select @@ -15,31 +15,29 @@ SET vectorize=off; SET tracing = on; BEGIN; SELECT 1; COMMIT; SELECT 2; SET trac # how many commands we ran in the session. query ITT SELECT - span, regexp_replace(regexp_replace(message, 'pos:[0-9]*', 'pos:?'), 'flowid: [0-9A-Fa-f-]*', 'flowid: ?'), operation + span, regexp_replace(message, 'pos:[0-9]*', 'pos:?'), operation FROM [SHOW TRACE FOR SESSION] WHERE message LIKE '%SPAN START%' OR message LIKE '%pos%executing%'; ---- -0 === SPAN START: session recording === session recording -1 === SPAN START: exec stmt === exec stmt -1 [NoTxn pos:?] executing ExecStmt: BEGIN TRANSACTION exec stmt -2 === SPAN START: sql txn === sql txn -3 === SPAN START: exec stmt === exec stmt -3 [Open pos:?] executing ExecStmt: SELECT 1 exec stmt -4 === SPAN START: consuming rows === consuming rows -5 === SPAN START: flow === -cockroach.flowid: ? flow -6 === SPAN START: exec stmt === exec stmt -6 [Open pos:?] executing ExecStmt: COMMIT TRANSACTION exec stmt -7 === SPAN START: exec stmt === exec stmt -7 [NoTxn pos:?] executing ExecStmt: SELECT 2 exec stmt -8 === SPAN START: sql txn === sql txn -9 === SPAN START: exec stmt === exec stmt -9 [Open pos:?] executing ExecStmt: SELECT 2 exec stmt -10 === SPAN START: consuming rows === consuming rows -11 === SPAN START: flow === -cockroach.flowid: ? flow -12 === SPAN START: exec stmt === exec stmt -12 [NoTxn pos:?] executing ExecStmt: SET TRACING = off exec stmt +0 === SPAN START: session recording === session recording +1 === SPAN START: exec stmt === exec stmt +1 [NoTxn pos:?] executing ExecStmt: BEGIN TRANSACTION exec stmt +2 === SPAN START: sql txn === sql txn +3 === SPAN START: exec stmt === exec stmt +3 [Open pos:?] executing ExecStmt: SELECT 1 exec stmt +4 === SPAN START: consuming rows === consuming rows +5 === SPAN START: flow === flow +6 === SPAN START: exec stmt === exec stmt +6 [Open pos:?] executing ExecStmt: COMMIT TRANSACTION exec stmt +7 === SPAN START: exec stmt === exec stmt +7 [NoTxn pos:?] executing ExecStmt: SELECT 2 exec stmt +8 === SPAN START: sql txn === sql txn +9 === SPAN START: exec stmt === exec stmt +9 [Open pos:?] executing ExecStmt: SELECT 2 exec stmt +10 === SPAN START: consuming rows === consuming rows +11 === SPAN START: flow === flow +12 === SPAN START: exec stmt === exec stmt +12 [NoTxn pos:?] executing ExecStmt: SET TRACING = off exec stmt # ------------------------------------------------------------------------------ # Numeric References Tests. diff --git a/pkg/sql/rowflow/BUILD.bazel b/pkg/sql/rowflow/BUILD.bazel index 2f67577ebcb0..dbee0016506f 100644 --- a/pkg/sql/rowflow/BUILD.bazel +++ b/pkg/sql/rowflow/BUILD.bazel @@ -58,5 +58,7 @@ go_test( "//pkg/util/randutil", "//pkg/util/tracing", "@com_github_cockroachdb_errors//:errors", + "@com_github_gogo_protobuf//types", + "@com_github_stretchr_testify//require", ], ) diff --git a/pkg/sql/rowflow/routers_test.go b/pkg/sql/rowflow/routers_test.go index 7b20b9fe7e56..da266d7c803a 100644 --- a/pkg/sql/rowflow/routers_test.go +++ b/pkg/sql/rowflow/routers_test.go @@ -15,7 +15,6 @@ import ( "context" "fmt" "math" - "strings" "sync" "sync/atomic" "testing" @@ -39,6 +38,8 @@ import ( "github.com/cockroachdb/cockroach/pkg/util/randutil" "github.com/cockroachdb/cockroach/pkg/util/tracing" "github.com/cockroachdb/errors" + pbtypes "github.com/gogo/protobuf/types" + "github.com/stretchr/testify/require" ) // setupRouter creates and starts a router. Returns the router and a WaitGroup @@ -870,25 +871,34 @@ func TestRouterDiskSpill(t *testing.T) { } traceMetaSeen = true span := meta.TraceData[0] - getTagValue := func(key string) string { - strValue, ok := span.Tags[key] - if !ok { - t.Errorf("missing tag: %s", key) + var stats execinfrapb.ComponentStats + var err error + var unmarshalled bool + span.Structured(func(any *pbtypes.Any) { + if !pbtypes.Is(any, &stats) { + return } - return strValue - } - t.Logf("tags: %v\n", span.Tags) - rowsRouted := getTagValue("cockroach.stat.input.tuples") - memMax := getTagValue("cockroach.stat.max.memory.allocated") - diskMax := getTagValue("cockroach.stat.max.scratch.disk.allocated") - if rowsRouted != fmt.Sprintf("%d", numRows) { - t.Errorf("expected %d rows routed, got %s", numRows, rowsRouted) + if err = pbtypes.UnmarshalAny(any, &stats); err != nil { + return + } + unmarshalled = true + }) + require.NoError(t, err) + require.True(t, unmarshalled) + require.True(t, stats.Inputs[0].NumTuples.HasValue()) + require.True(t, stats.Exec.MaxAllocatedMem.HasValue()) + require.True(t, stats.Exec.MaxAllocatedDisk.HasValue()) + rowsRouted := stats.Inputs[0].NumTuples.Value() + memMax := stats.Exec.MaxAllocatedMem.Value() + diskMax := stats.Exec.MaxAllocatedDisk.Value() + if rowsRouted != numRows { + t.Errorf("expected %d rows routed, got %d", numRows, rowsRouted) } - if strings.HasPrefix(memMax, `"0"`) { - t.Errorf("expected memMax > 0, got %s", memMax) + if memMax == 0 { + t.Errorf("expected memMax > 0, got %d", memMax) } - if strings.HasPrefix(diskMax, `"0"`) { - t.Errorf("expected diskMax > 0, got %s", diskMax) + if diskMax == 0 { + t.Errorf("expected diskMax > 0, got %d", diskMax) } } continue diff --git a/pkg/sql/trace_test.go b/pkg/sql/trace_test.go index e7bf36937cb5..3e120913d5aa 100644 --- a/pkg/sql/trace_test.go +++ b/pkg/sql/trace_test.go @@ -107,10 +107,10 @@ func TestTrace(t *testing.T) { // Check that stat collection from the above SELECT statement is output // to trace. We don't insert any rows in this test, thus the expected - // stat value is 0. + // num tuples value plus one is 1. rows, err := sqlDB.Query( "SELECT count(message) FROM crdb_internal.session_trace " + - "WHERE message LIKE '%cockroach.stat.kv.tuples.read: 0%'", + "WHERE message LIKE '%component%num_tuples%value_plus_one:1%'", ) if err != nil { t.Fatal(err) diff --git a/pkg/util/tracing/span.go b/pkg/util/tracing/span.go index 2206e816df17..17909f48eb57 100644 --- a/pkg/util/tracing/span.go +++ b/pkg/util/tracing/span.go @@ -314,9 +314,6 @@ func (s *spanInner) SetSpanStats(stats SpanStats) { s.RecordStructured(stats) s.crdb.mu.Lock() s.crdb.mu.stats = stats - for name, value := range stats.StatsTags() { - s.setTagInner(name, value, true /* locked */) - } s.crdb.mu.Unlock() }