tracing: wrongly emitting trace events for session's first txn

[irfansharif]

See #59193. We bisected a failure in TestExecBuild/local/autocommit_nonmetamorphic to #58897, which simply enabled always-on tracing. We're now doubly emitting trace data when we shouldn't be.

[irfansharif]

I don't think we're double emitting trace events. I think it's more that we're not resetting trace events in a span correctly. We used to expect the following data driven output for the following query:

statement ok
SET TRACING=ON;
  WITH cte AS (INSERT INTO ab VALUES (3, 3), (4, 4) RETURNING a, b)
  INSERT INTO ab (SELECT a*10, b*10 FROM cte);
SET TRACING=OFF

query TT
SELECT operation, message FROM [SHOW KV TRACE FOR SESSION]
WHERE message       LIKE '%r$rangeid: sending batch%'
  AND message   NOT LIKE '%PushTxn%'
  AND message   NOT LIKE '%QueryTxn%'
  AND operation NOT LIKE '%async%'
----
dist sender send  r35: sending batch 2 CPut to (n1,s1):1
dist sender send  r35: sending batch 2 CPut to (n1,s1):1
dist sender send  r35: sending batch 1 EndTxn to (n1,s1):1

Which fails with:

testdata/autocommit_nonmetamorphic:797: SELECT operation, message FROM [SHOW KV TRACE FOR SESSION]
WHERE message       LIKE '%r35: sending batch%'
  AND message   NOT LIKE '%PushTxn%'
  AND message   NOT LIKE '%QueryTxn%'
  AND operation NOT LIKE '%async%'
expected:
    dist sender send  r35: sending batch 2 CPut to (n1,s1):1
    dist sender send  r35: sending batch 2 CPut to (n1,s1):1
    dist sender send  r35: sending batch 1 EndTxn to (n1,s1):1
but found (query options: "") :
    dist sender send  r35: sending batch 1 DelRng to (n1,s1):1
    dist sender send  r35: sending batch 2 CPut to (n1,s1):1
    dist sender send  r35: sending batch 2 CPut to (n1,s1):1
    dist sender send  r35: sending batch 1 EndTxn to (n1,s1):1

Where's the DelRng coming from? Probably some previous trace. I double checked to see that running that query+trace capture in isolation (without any of the preceding trace captures) doesn't run into the same error. So we're definitely not resetting the span correctly, somewhere.

[irfansharif]

I think it's got to do with how we expect traces to behave with ROLLBACK.

# LogicTest: local !metamorphic

statement ok
CREATE TABLE ab (a INT PRIMARY KEY, b INT, FAMILY f1 (a, b))

# Get the range id.
let $rangeid
SELECT range_id FROM [ SHOW RANGES FROM TABLE ab ]

# Populate table descriptor cache.
query II
SELECT * FROM ab
----

# No auto-commit inside a transaction.
statement ok
BEGIN

statement ok
SET TRACING=ON;
  INSERT INTO ab VALUES (4, 4), (5, 5);
SET TRACING=OFF

query TT
SELECT operation, message FROM [SHOW KV TRACE FOR SESSION]
WHERE message     LIKE '%r$rangeid: sending batch%'
  AND message NOT LIKE '%PushTxn%'
  AND message NOT LIKE '%QueryTxn%'
----
dist sender send  r35: sending batch 2 CPut to (n1,s1):1

statement ok
ROLLBACK

statement ok
SET TRACING=ON;
  INSERT INTO ab VALUES (6, 6), (7, 7) RETURNING a, b;
SET TRACING=OFF

query TT
SELECT operation, message FROM [SHOW KV TRACE FOR SESSION]
WHERE message     LIKE '%r$rangeid: sending batch%'
  AND message NOT LIKE '%PushTxn%'
  AND message NOT LIKE '%QueryTxn%'
----
dist sender send  r35: sending batch 2 CPut, 1 EndTxn to (n1,s1):1

This is what I expect to behave like, but it doesn't, the "dist sender send r35: sending batch 2 CPut to (n1,s1):1" recording from the rolled back statement still shows up in future traces, despite "resetting" the trace using SET TRACING = on

 --- FAIL: TestExecBuild/local (0.00s)
        --- FAIL: TestExecBuild/local/tracing (0.23s)
            logic.go:2306: let $rangeid = 35
            logic.go:2265:

                testdata/tracing:49: SELECT operation, message FROM [SHOW KV TRACE FOR SESSION]
                WHERE message     LIKE '%r35: sending batch%'
                  AND message NOT LIKE '%PushTxn%'
                  AND message NOT LIKE '%QueryTxn%'
                expected:
                    dist sender send  r35: sending batch 2 CPut, 1 EndTxn to (n1,s1):1
                but found (query options: "") :
                    dist sender send  r35: sending batch 2 CPut to (n1,s1):1
                    dist sender send  r35: sending batch 2 CPut, 1 EndTxn to (n1,s1):1

[irfansharif]

I see that we're grabbing onto the first txn's span in the session here:

cockroach/pkg/sql/exec_util.go

Lines 1483 to 1485 in 854246a

	// firstTxnSpan is the span of the first txn that was active when session
	// tracing was enabled.
	firstTxnSpan *tracing.Span

And since we're not really ever "consuming" span data from the aborted txn, it'll show up in future traces. We've had this behaviour for a while, and not sure if it's a sensible default. Handy repro #59458.

[irfansharif]

yo @asubiotto, I think this is in your ballpark. I don't know if we'll have time to do anything about it, or if it's worthwhile for 21.1, but I do think it's a "bug".

[asubiotto]

Hmm, thanks for raising this. We'll hopefully get to trace-related fixes during the stability period.

[irfansharif]

Are we still planning on addressing this?

[asubiotto]

It's a nice to have for 21.1 so not certain we'll definitely have it done for 21.1. We'll take a look at addressing it once we've completed higher-priority items.

[irfansharif]

I'm having to get into the weeds of this SessionTracer guy to work through the implications of #61777. Specifically, if we're not creating real spans unless absolutely needed, we can't rely on the assumptions of this code:

cockroach/pkg/sql/exec_util.go

Lines 1645 to 1656 in a86cf54

	// If we're inside a transaction, start recording on the txn span.
	if _, ok := st.ex.machine.CurState().(stateNoTxn); !ok {
	sp := tracing.SpanFromContext(st.ex.state.Ctx)
	if sp == nil {
	return errors.Errorf("no txn span for SessionTracing")
	}
	// We want to clear out any existing recordings so they don't show up in
	// future traces.
	sp.ResetRecording()
	sp.SetVerbose(true)
	st.firstTxnSpan = sp
	}

I think we'll want to hijack the txn's span + context in the same manner we do for the conn below. Does that sound right to you? +cc @cockroachdb/kv-east / @tbg.

[asubiotto]

That sounds reasonable to me, but this code is new to me too. (cc @andreimatei in case you want to chime in)