Merge #151433

151433: sql, tracing: add cluster setting to omit internal txns from tracing  r=dhartunian a=dhartunian

A cluster setting has been added,
`sql.trace.txn.include_internal.enabled` which is enabled by default,
to include internal transactions in the probabilistic transaction
tracing and latency capture.

Typically we want this off, but it's `true` by default since that's
always been the behavior until now. It's recommended that this be
disabled when debugging a customer workload.

Epic: None

Release note (obs change): when enabling probabilistic
transaction tracing via the `sql.trace.txn.enable_threshold`
and `sql.trace.txn.sample_rate` cluster settings, it's typical
that you would want to omit internal transactions from being
considered for tracing and logging. You can now do this by setting
`sql.trace.txn.include_internal.enabled` to false.

----
Prior commit is being reviewed here: #151414

Also tests are not correct yet, I'm trying to use this patch to consolidate tests from the last one to prevent lots of small tests that have to start their own servers.

Co-authored-by: David Hartunian <[email protected]>

Author: craig[bot]

docs/generated/settings/settings-for-tenants.txt

@@ -390,6 +390,7 @@ sql.temp_object_cleaner.wait_interval	duration	30m0s	how long after creation a t
 sql.log.all_statements.enabled (alias: sql.trace.log_statement_execute)	boolean	false	set to true to enable logging of all executed statements	application
 sql.trace.stmt.enable_threshold	duration	0s	enables tracing on all statements; statements executing for longer than this duration will have their trace logged (set to 0 to disable); note that enabling this may have a negative performance impact; this setting applies to individual statements within a transaction and is therefore finer-grained than sql.trace.txn.enable_threshold	application
 sql.trace.txn.enable_threshold	duration	0s	enables transaction traces for transactions exceeding this duration, used with `sql.trace.txn.sample_rate`	application
+sql.trace.txn.include_internal.enabled	boolean	true	enables tracing internal transactions as well as external workload using sample rate and threshold settings	application
 sql.trace.txn.jaeger_json_output.enabled	boolean	false	enables Jaeger JSON output for transaction traces in logs	application
 sql.trace.txn.sample_rate	float	1	enables probabilistic transaction tracing. It should be used in conjunction with `sql.trace.txn.enable_threshold`. A percentage of transactions between 0 and 1.0 will have tracing enabled, and only those which exceed the configured threshold will be logged.	application
 sql.ttl.changefeed_replication.disabled	boolean	false	if true, deletes issued by TTL will not be replicated via changefeeds (this setting will be ignored by changefeeds that have the ignore_disable_changefeed_replication option set; such changefeeds will continue to replicate all TTL deletes)	application

docs/generated/settings/settings.html

@@ -345,6 +345,7 @@
 <tr><td><div id="setting-sql-trace-log-statement-execute" class="anchored"><code>sql.log.all_statements.enabled<br />(alias: sql.trace.log_statement_execute)</code></div></td><td>boolean</td><td><code>false</code></td><td>set to true to enable logging of all executed statements</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-sql-trace-stmt-enable-threshold" class="anchored"><code>sql.trace.stmt.enable_threshold</code></div></td><td>duration</td><td><code>0s</code></td><td>enables tracing on all statements; statements executing for longer than this duration will have their trace logged (set to 0 to disable); note that enabling this may have a negative performance impact; this setting applies to individual statements within a transaction and is therefore finer-grained than sql.trace.txn.enable_threshold</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-sql-trace-txn-enable-threshold" class="anchored"><code>sql.trace.txn.enable_threshold</code></div></td><td>duration</td><td><code>0s</code></td><td>enables transaction traces for transactions exceeding this duration, used with `sql.trace.txn.sample_rate`</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
+<tr><td><div id="setting-sql-trace-txn-include-internal-enabled" class="anchored"><code>sql.trace.txn.include_internal.enabled</code></div></td><td>boolean</td><td><code>true</code></td><td>enables tracing internal transactions as well as external workload using sample rate and threshold settings</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-sql-trace-txn-jaeger-json-output-enabled" class="anchored"><code>sql.trace.txn.jaeger_json_output.enabled</code></div></td><td>boolean</td><td><code>false</code></td><td>enables Jaeger JSON output for transaction traces in logs</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-sql-trace-txn-sample-rate" class="anchored"><code>sql.trace.txn.sample_rate</code></div></td><td>float</td><td><code>1</code></td><td>enables probabilistic transaction tracing. It should be used in conjunction with `sql.trace.txn.enable_threshold`. A percentage of transactions between 0 and 1.0 will have tracing enabled, and only those which exceed the configured threshold will be logged.</td><td>Serverless/Dedicated/Self-Hosted</td></tr>
 <tr><td><div id="setting-sql-ttl-changefeed-replication-disabled" class="anchored"><code>sql.ttl.changefeed_replication.disabled</code></div></td><td>boolean</td><td><code>false</code></td><td>if true, deletes issued by TTL will not be replicated via changefeeds (this setting will be ignored by changefeeds that have the ignore_disable_changefeed_replication option set; such changefeeds will continue to replicate all TTL deletes)</td><td>Serverless/Dedicated/Self-Hosted</td></tr>

pkg/sql/conn_executor.go

@@ -1163,6 +1163,7 @@ func (s *Server) newConnExecutor(
 			mon:                          txnMon,
 			connCtx:                      ctx,
 			testingForceRealTracingSpans: s.cfg.TestingKnobs.ForceRealTracingSpans,
+			execType:                     executorType,
 		},
 		transitionCtx: transitionCtx{
 			db:           s.cfg.DB,

pkg/sql/exec_util.go

@@ -291,6 +291,16 @@ var TraceTxnOutputJaegerJSON = settings.RegisterBoolSetting(
 	false,
 	settings.WithPublic)
 
+// TraceTxnIncludeInternal when enabled will also subject internal queries to trace capture.
+var TraceTxnIncludeInternal = settings.RegisterBoolSetting(
+	settings.ApplicationLevel,
+	"sql.trace.txn.include_internal.enabled",
+	"enables tracing internal transactions as well as external workload using "+
+		"sample rate and threshold settings",
+	true,
+	settings.WithPublic,
+)
+
 // TraceStmtThreshold is identical to traceTxnThreshold except it applies to
 // individual statements in a transaction. The motivation for this setting is
 // to be able to reduce the noise associated with a larger transaction (e.g.

pkg/sql/trace_test.go

@@ -21,6 +21,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/settings/cluster"
 	"github.com/cockroachdb/cockroach/pkg/sql"
 	"github.com/cockroachdb/cockroach/pkg/sql/catalog/descs"
+	"github.com/cockroachdb/cockroach/pkg/sql/sessiondata"
 	"github.com/cockroachdb/cockroach/pkg/testutils"
 	"github.com/cockroachdb/cockroach/pkg/testutils/pgurlutils"
 	"github.com/cockroachdb/cockroach/pkg/testutils/serverutils"
@@ -615,6 +616,8 @@ func TestTraceTxnSampleRateAndThreshold(t *testing.T) {
 		sampleRate            float64
 		threshold             time.Duration
 		exptToTraceEventually bool
+		checkJaegerOutput     bool
+		checkExcludeInternal  bool
 	}{
 		{
 			name:                  "no sample rate and no threshold",
@@ -646,6 +649,20 @@ func TestTraceTxnSampleRateAndThreshold(t *testing.T) {
 			threshold:             1 * time.Nanosecond,
 			exptToTraceEventually: true,
 		},
+		{
+			name:                  "jaeger output with sample rate 1.0 and threshold 1ns should trace",
+			sampleRate:            1.0,
+			threshold:             1 * time.Nanosecond,
+			exptToTraceEventually: true,
+			checkJaegerOutput:     true,
+		},
+		{
+			name:                  "internal queries omitted with cluster setting",
+			sampleRate:            1.0,
+			threshold:             1 * time.Nanosecond,
+			exptToTraceEventually: true,
+			checkExcludeInternal:  true,
+		},
 	} {
 		t.Run(tc.name, func(t *testing.T) {
 			sql.TraceTxnThreshold.Override(ctx, &settings.SV, tc.threshold)
@@ -655,14 +672,46 @@ func TestTraceTxnSampleRateAndThreshold(t *testing.T) {
 			r := sqlutils.MakeSQLRunner(db)
 
 			if tc.exptToTraceEventually {
-				testutils.SucceedsSoon(t, func() error {
-					r.Exec(t, "SELECT pg_sleep(0.01)")
+				if tc.checkJaegerOutput {
+					sql.TraceTxnOutputJaegerJSON.Override(ctx, &settings.SV, true)
+					testutils.SucceedsSoon(t, func() error {
+						r.Exec(t, "SELECT pg_sleep(0.01)")
+						log.FlushAllSync()
+						if !appLogsSpy.Has(logtestutils.MatchesF(regexp.QuoteMeta("ExecStmt: SELECT pg_sleep(0.01)"))) {
+							return errors.New("no sql txn log found (tracing did not happen)")
+						}
+						if !appLogsSpy.Has(logtestutils.MatchesF(regexp.QuoteMeta("{\"refType\":\"CHILD_OF\",\"traceID\":\""))) {
+							return errors.New("no Jaeger JSON found")
+						}
+						return nil
+					})
+				} else if tc.checkExcludeInternal {
+					sql.TraceTxnIncludeInternal.Override(ctx, &settings.SV, false)
 					log.FlushAllSync()
-					if !appLogsSpy.Has(logtestutils.MatchesF(regexp.QuoteMeta("ExecStmt: SELECT pg_sleep(0.01)"))) {
-						return errors.New("no sql txn log found (tracing did not happen)")
+					appLogsSpy.Reset() // Clear logs after setting the cluster setting
+
+					// Use the internal executor directly to create actual internal transactions
+					ie := s.InternalExecutor().(*sql.InternalExecutor)
+					_, err := ie.ExecEx(ctx, "test-internal-query", nil, /* txn */
+						sessiondata.NodeUserSessionDataOverride,
+						"SELECT pg_sleep(0.01)")
+					if err != nil {
+						t.Fatal(err)
 					}
-					return nil
-				})
+					log.FlushAllSync()
+					if appLogsSpy.Has(logtestutils.MatchesF(regexp.QuoteMeta("ExecStmt: SELECT pg_sleep(0.01)"))) {
+						t.Fatal("internal sql txn log found when internal transactions should be excluded from tracing")
+					}
+				} else {
+					testutils.SucceedsSoon(t, func() error {
+						r.Exec(t, "SELECT pg_sleep(0.01)")
+						log.FlushAllSync()
+						if !appLogsSpy.Has(logtestutils.MatchesF(regexp.QuoteMeta("ExecStmt: SELECT pg_sleep(0.01)"))) {
+							return errors.New("no sql txn log found (tracing did not happen)")
+						}
+						return nil
+					})
+				}
 			} else {
 				r.Exec(t, "SELECT pg_sleep(0.01)")
 				log.FlushAllSync()

pkg/sql/txn_state.go

@@ -142,6 +142,9 @@ type txnState struct {
 	// testingForceRealTracingSpans is a test-only knob that forces the use of
 	// real (i.e. not no-op) tracing spans for every statement.
 	testingForceRealTracingSpans bool
+
+	// execType records the executor type for the transaction.
+	execType executorType
 }
 
 // txnType represents the type of a SQL transaction.
@@ -218,7 +221,11 @@ func (ts *txnState) resetForNewSQLTxn(
 	duration := TraceTxnThreshold.Get(&tranCtx.settings.SV)
 
 	sampleRate := TraceTxnSampleRate.Get(&tranCtx.settings.SV)
+	includeInternal := TraceTxnIncludeInternal.Get(&tranCtx.settings.SV)
 	ts.shouldRecord = sampleRate > 0 && duration > 0 && rng.Float64() < sampleRate
+	if !includeInternal && ts.execType == executorTypeInternal {
+		ts.shouldRecord = false
+	}
 	ts.outputJaegerJSON = TraceTxnOutputJaegerJSON.Get(&tranCtx.settings.SV)
 
 	if alreadyRecording || ts.shouldRecord {