Merge #151414

151414: tracing, sql: add Jaeger output option for transaction traces r=dhartunian a=dhartunian

Adds a cluster setting `sql.trace.txn.jaeger_json_output.enabled`
which is false by default, but when true will write Jaeger compatible
JSON to the logs for transactions that meet the bar for verbose
traces.

Epic: None

Release note: when outputting transaction traces to logs using
probabilistic and/or statement latency-based triggers, users have
the option to write the logs in Jaeger-compatible JSON format
to the logs for easier analysis. Setting the cluster setting
`sql.trace.txn.jaeger_json_output.enabled` to true, will change the
output format.

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.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
 sql.ttl.default_delete_batch_size	integer	100	default amount of rows to delete in a single query during a TTL job	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-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>
 <tr><td><div id="setting-sql-ttl-default-delete-batch-size" class="anchored"><code>sql.ttl.default_delete_batch_size</code></div></td><td>integer</td><td><code>100</code></td><td>default amount of rows to delete in a single query during a TTL job</td><td>Serverless/Dedicated/Self-Hosted</td></tr>

pkg/bench/rttanalysis/rtt_analysis_bench.go

@@ -223,7 +223,7 @@ func executeRoundTripTest(
 		if haveExp && !exp.matches(int(res)) && !*rewriteFlag {
 			reportf(`%s: got %v, expected %v`, b.Name(), res, exp)
 			dir := getDir()
-			jaegerJSON, err := r.ToJaegerJSON(tc.Stmt, "", "n0")
+			jaegerJSON, err := r.ToJaegerJSON(tc.Stmt, "", "n0", true /* indent */)
 			require.NoError(b, err)
 			path := filepath.Join(dir, strings.Replace(b.Name(), "/", "_", -1)) + ".jaeger.json"
 			require.NoError(b, os.WriteFile(path, []byte(jaegerJSON), 0666))

pkg/cli/debug_send_kv_batch.go

@@ -199,7 +199,7 @@ func runSendKVBatch(cmd *cobra.Command, args []string) error {
 			// all the sub-spans. With an empty string, the node ID of the
 			// node that processes the request is properly annotated in the
 			// Jaeger UI.
-			j, err := rec.ToJaegerJSON(ba.Summary(), "", "")
+			j, err := rec.ToJaegerJSON(ba.Summary(), "", "", true /* indent */)
 			if err != nil {
 				return err
 			}

pkg/sql/conn_executor_exec.go

@@ -1123,6 +1123,7 @@ func (ex *connExecutor) execStmtInOpenState(
 				redactableStmt,     /* detail */
 				stmtTraceThreshold, /* threshold */
 				stmtDur,            /* elapsed */
+				false,              /* outputJaegerJSON */
 			)
 		} else {
 			stmtThresholdSpan.Finish()
@@ -2181,6 +2182,7 @@ func (ex *connExecutor) execStmtInOpenStateWithPausablePortal(
 				redactableStmt,     /* detail */
 				stmtTraceThreshold, /* threshold */
 				stmtDur,            /* elapsed */
+				false,              /* outputJaegerJSON */
 			)
 		} else {
 			stmtThresholdSpan.Finish()
@@ -4546,11 +4548,23 @@ func logTraceAboveThreshold(
 	opName redact.RedactableString,
 	detail redact.RedactableString,
 	threshold, elapsed time.Duration,
+	outputJaegerJSON bool,
 ) {
 	if r == nil {
 		log.Warning(ctx, "missing trace when threshold tracing was enabled")
 	}
-	log.SqlExec.Infof(ctx, "%s took %s, exceeding threshold of %s:\n%s\n%s", opName, elapsed, threshold, detail, r)
+	output := ""
+	var err error
+	if outputJaegerJSON {
+		output, err = r.ToJaegerJSON("unknown stmt", "no comment", "unknown node", false /* indent */)
+		if err != nil {
+			log.Warningf(ctx, "trace could not be converted to jaeger JSON: %s", err.Error())
+			output = r.String()
+		}
+	} else {
+		output = r.String()
+	}
+	log.SqlExec.Infof(ctx, "%s took %s, exceeding threshold of %s:\n%s\n%s", opName, elapsed, threshold, detail, output)
 }
 
 func (ex *connExecutor) execWithProfiling(

pkg/sql/crdb_internal.go

@@ -1926,7 +1926,7 @@ CREATE TABLE crdb_internal.cluster_inflight_traces (
 		for ; iter.Valid(); iter.Next(ctx) {
 			nodeID, recording := iter.Value()
 			traceString := recording.String()
-			traceJaegerJSON, err := recording.ToJaegerJSON("", "", fmt.Sprintf("node %d", nodeID))
+			traceJaegerJSON, err := recording.ToJaegerJSON("", "", fmt.Sprintf("node %d", nodeID), true /* indent */)
 			if err != nil {
 				return false, err
 			}

pkg/sql/exec_util.go

@@ -283,6 +283,14 @@ var TraceTxnSampleRate = settings.RegisterFloatSetting(
 	settings.NonNegativeFloatWithMaximum(1.0),
 	settings.WithPublic)
 
+// TraceTxnOutputJaegerJSON sets the output format of transaction trace logs.
+var TraceTxnOutputJaegerJSON = settings.RegisterBoolSetting(
+	settings.ApplicationLevel,
+	"sql.trace.txn.jaeger_json_output.enabled",
+	"enables Jaeger JSON output for transaction traces in logs",
+	false,
+	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/explain_bundle.go

@@ -504,7 +504,7 @@ func (b *stmtBundleBuilder) addTrace() {
 This trace can be imported into Jaeger for visualization. From the Jaeger Search screen, select the JSON File.
 Jaeger can be started using docker with: docker run -d --name jaeger -p 16686:16686 jaegertracing/all-in-one:1.17
 The UI can then be accessed at http://localhost:16686/search`, b.stmt)
-	jaegerJSON, err := b.trace.ToJaegerJSON(b.stmt, comment, "")
+	jaegerJSON, err := b.trace.ToJaegerJSON(b.stmt, comment, "", true /* indent */)
 	if err != nil {
 		b.errorStrings = append(b.errorStrings, fmt.Sprintf("error getting jaeger trace: %v", err))
 		b.z.AddFile("trace-jaeger.txt", err.Error())

pkg/sql/trace_test.go

@@ -675,3 +675,44 @@ func TestTraceTxnSampleRateAndThreshold(t *testing.T) {
 		})
 	}
 }
+
+func TestTraceTxnJaegerOutput(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+	defer log.Scope(t).Close(t)
+
+	ctx := context.Background()
+	settings := cluster.MakeTestingClusterSettings()
+
+	s, db, _ := serverutils.StartServer(t, base.TestServerArgs{
+		Settings: settings,
+	})
+	defer s.Stopper().Stop(ctx)
+
+	appLogsSpy := logtestutils.NewLogSpy(
+		t,
+		// This string match is constructed from the log.SqlExec.Infof format
+		// string found in conn_executor_exec.go:logTraceAboveThreshold
+		logtestutils.MatchesF("exceeding threshold of"),
+	)
+	cleanup := log.InterceptWith(ctx, appLogsSpy)
+	defer cleanup()
+
+	sql.TraceTxnOutputJaegerJSON.Override(ctx, &settings.SV, true)
+	sql.TraceTxnThreshold.Override(ctx, &settings.SV, time.Nanosecond)
+	sql.TraceTxnSampleRate.Override(ctx, &settings.SV, 1)
+	log.FlushAllSync()
+	appLogsSpy.Reset()
+	r := sqlutils.MakeSQLRunner(db)
+
+	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
+	})
+}

pkg/sql/txn_state.go

@@ -98,6 +98,10 @@ type txnState struct {
 	// positive duration trigger for logging.
 	shouldRecord bool
 
+	// outputJaegerJSON is used to indicate whether the traces in logs
+	// should be in a plaintext or Jaeger format.
+	outputJaegerJSON bool
+
 	// recordingThreshold, is not zero, indicates that sp is recording and that
 	// the recording should be dumped to the log if execution of the transaction
 	// took more than this.
@@ -215,6 +219,7 @@ func (ts *txnState) resetForNewSQLTxn(
 
 	sampleRate := TraceTxnSampleRate.Get(&tranCtx.settings.SV)
 	ts.shouldRecord = sampleRate > 0 && duration > 0 && rng.Float64() < sampleRate
+	ts.outputJaegerJSON = TraceTxnOutputJaegerJSON.Get(&tranCtx.settings.SV)
 
 	if alreadyRecording || ts.shouldRecord {
 		ts.Ctx, sp = tracing.EnsureChildSpan(ctx, tranCtx.tracer, opName,
@@ -300,6 +305,7 @@ func (ts *txnState) finishSQLTxn() (txnID uuid.UUID, commitTimestamp hlc.Timesta
 				redact.Sprint(redact.Safe(txnID)),   /* detail */
 				ts.recordingThreshold,               /* threshold */
 				elapsed,                             /* elapsed */
+				ts.outputJaegerJSON,                 /* outputJaegerJSON */
 			)
 		}
 	}