Skip to content

Commit

Permalink
sql: fix the session tracing in some cases
Browse files Browse the repository at this point in the history 
When the session tracing is started, we might need to start two tracing
spans: we always start a span for the connection, but also if we're
inside of a txn, we start a separate span for the txn. Previously, the
span of the previous txn wasn't properly cleaned up when the session
tracing is started again outside of a txn, which resulted in old
(irrelevant) entries being added to the newer trace. Now this is fixed.

Additionally, this commit makes sure to finish the tracing spans (which
wasn't done previously).

Release note (bug fix): Previously, the session trace (i.e. `SHOW TRACE
FOR SESSION`) could contain entries that corresponded to the previous
trace (i.e. `SET TRACING=ON` didn't properly reset the trace). Now this
is fixed.
  • Loading branch information
@yuzefovich
yuzefovich committed May 6, 2021
1 parent 97e3a2e commit 3568d74
Show file tree
Hide file tree
Showing 3 changed files with 75 additions and 38 deletions.
18 changes: 8 additions & 10 deletions pkg/sql/exec_util.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1612,10 +1612,11 @@ type SessionTracing struct {
ex *connExecutor

// firstTxnSpan is the span of the first txn that was active when session
// tracing was enabled.
// tracing was enabled. It is finished and unset in StopTracing.
firstTxnSpan *tracing.Span

// connSpan is the connection's span. This is recording.
// connSpan is the connection's span. This is recording. It is finished and
// unset in StopTracing.
connSpan *tracing.Span

// lastRecording will collect the recording when stopping tracing.
Expand Down Expand Up @@ -1731,7 +1732,6 @@ func (st *SessionTracing) StartTracing(
}

// StopTracing stops the trace that was started with StartTracing().
// An error is returned if tracing was not active.
func (st *SessionTracing) StopTracing() error {
if !st.enabled {
// We're not currently tracing. No-op.
Expand All @@ -1742,18 +1742,16 @@ func (st *SessionTracing) StopTracing() error {
st.showResults = false
st.recordingType = tracing.RecordingOff

// Accumulate all recordings and finish the tracing spans.
var spans []tracingpb.RecordedSpan

if st.firstTxnSpan != nil {
spans = append(spans, st.firstTxnSpan.GetRecording()...)
st.firstTxnSpan.SetVerbose(false)
st.firstTxnSpan.Finish()
st.firstTxnSpan = nil
}
st.connSpan.Finish()
spans = append(spans, st.connSpan.GetRecording()...)
// NOTE: We're stopping recording on the connection's ctx only; the stopping
// is not inherited by children. If we are inside of a txn, that span will
// continue recording, even though nobody will collect its recording again.
st.connSpan.SetVerbose(false)
st.connSpan.Finish()
st.connSpan = nil
st.ex.ctxHolder.unhijack()

var err error
Expand Down
28 changes: 0 additions & 28 deletions pkg/sql/opt/exec/execbuilder/testdata/autocommit_nonmetamorphic
View file
Original file line number Diff line number Diff line change
Expand Up @@ -110,7 +110,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 CPut, 1 EndTxn to (n1,s1):1

# TODO(radu): allow non-side-effecting projections.
Expand All @@ -134,7 +133,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1

# Insert with RETURNING statement with side-effects should not auto-commit.
Expand All @@ -159,7 +157,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1

# Another way to test the scenario above: generate an error and ensure that the
Expand Down Expand Up @@ -195,7 +192,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 1 Put, 1 EndTxn to (n1,s1):1

# Multi-row upsert should auto-commit.
Expand All @@ -217,7 +213,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 Put, 1 EndTxn to (n1,s1):1

# No auto-commit inside a transaction.
Expand Down Expand Up @@ -266,7 +261,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 2 Put, 1 EndTxn to (n1,s1):1

# TODO(radu): allow non-side-effecting projections.
Expand All @@ -290,7 +284,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1

# Upsert with RETURNING statement with side-effects should not auto-commit.
Expand All @@ -315,7 +308,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1

# Another way to test the scenario above: generate an error and ensure that the
Expand Down Expand Up @@ -351,7 +343,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put, 1 EndTxn to (n1,s1):1

Expand Down Expand Up @@ -403,8 +394,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put, 1 EndTxn to (n1,s1):1

# TODO(radu): allow non-side-effecting projections.
Expand All @@ -429,8 +418,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
----
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1

# Update with RETURNING statement with side-effects should not auto-commit.
Expand All @@ -456,8 +443,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
----
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1

# Another way to test the scenario above: generate an error and ensure that the
Expand Down Expand Up @@ -493,8 +478,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 DelRng, 1 EndTxn to (n1,s1):1

# Multi-row delete should auto-commit.
Expand All @@ -516,8 +499,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Put to (n1,s1):1
dist sender send r37: sending batch 1 DelRng, 1 EndTxn to (n1,s1):1

# No auto-commit inside a transaction.
Expand Down Expand Up @@ -566,7 +547,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%PushTxn%'
AND message NOT LIKE '%QueryTxn%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Del, 1 EndTxn to (n1,s1):1

Expand All @@ -590,7 +570,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Del to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1
Expand All @@ -616,7 +595,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 2 Del to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1
Expand Down Expand Up @@ -666,7 +644,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 Get to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1
Expand All @@ -690,7 +667,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 1 Put to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
Expand All @@ -716,7 +692,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 Get to (n1,s1):1
dist sender send r37: sending batch 1 Del to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
Expand Down Expand Up @@ -745,7 +720,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 1 Scan to (n1,s1):1
dist sender send r37: sending batch 1 Del, 1 EndTxn to (n1,s1):1

Expand Down Expand Up @@ -775,7 +749,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1
Expand All @@ -801,7 +774,6 @@ WHERE message LIKE '%r$rangeid: sending batch%'
AND message NOT LIKE '%QueryTxn%'
AND operation NOT LIKE '%async%'
----
dist sender send r37: sending batch 1 DelRng to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 2 CPut to (n1,s1):1
dist sender send r37: sending batch 1 EndTxn to (n1,s1):1
67 changes: 67 additions & 0 deletions pkg/sql/opt/exec/execbuilder/testdata/show_trace_nonmetamorphic
View file
Original file line number Diff line number Diff line change
Expand Up @@ -316,3 +316,70 @@ SET tracing = on; SELECT * FROM t; SET tracing = off
# dist sender send r6: sending batch 1 Get to (n1,s1):1
# dist sender send querying next range at /Table/12/1
# dist sender send r8: sending batch 1 Scan to (n1,s1):1

# Regression tests for incorrect interaction between consecutive session traces
# (#59203, #60672).
statement ok
CREATE TABLE a (a INT PRIMARY KEY)

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

# Populate table descriptor cache.
query I
SELECT * FROM a
----

statement ok
BEGIN;
SET TRACING=ON;
INSERT INTO a VALUES (1);
ROLLBACK

# The tracing is still enabled. Insert a couple of rows with auto-commit, and
# stop the tracing.
statement ok
INSERT INTO a VALUES (2), (3);
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 r38: sending batch 1 CPut to (n1,s1):1
dist sender send r38: sending batch 1 EndTxn to (n1,s1):1
dist sender send r38: sending batch 2 CPut, 1 EndTxn to (n1,s1):1

# Make another session trace.
statement ok
BEGIN;
SET TRACING=ON;
INSERT INTO a VALUES (4), (5), (6);
SET TRACING=OFF;
COMMIT

# Start the tracing again and insert a few rows with auto-commit.
statement ok
SET TRACING=ON;
INSERT INTO a VALUES (7), (8), (9), (10);

# The tracing is still enabled. Insert a few rows, rollback the txn, and stop
# the tracing.
statement ok
BEGIN;
INSERT INTO a VALUES (11), (12), (13), (14), (15);
ROLLBACK;
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 r38: sending batch 4 CPut, 1 EndTxn to (n1,s1):1
dist sender send r38: sending batch 5 CPut to (n1,s1):1
dist sender send r38: sending batch 1 EndTxn to (n1,s1):1

0 comments on commit 3568d74

Please sign in to comment.