sql: add sql.trace.stmt.enable_threshold #57733

asubiotto · 2020-12-09T11:33:20Z

Release note (sql change): add sql.trace.stmt.enable_thresold. Similar to
sql.trace.txn.enable_threshold, this logs a trace of any statements that take
longer than the specified duration. This new setting allows for more
granularity than the transaction threshold since it applies to individual
statements and does not include overhead such as communication with a SQL
client.

cockroach-teamcity · 2020-12-09T11:33:28Z

This change is

asubiotto · 2020-12-09T11:34:01Z

This setting was useful in #56923

yuzefovich

Reviewed 4 of 4 files at r1.
Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @andreimatei, @asubiotto, and @RaduBerinde)

pkg/sql/conn_executor_exec.go, line 1478 at r1 (raw file):

			tracing.WithParentAndAutoCollection(parentSp),
			tracing.WithCtxLogTags(parentCtx),
			// WithForceRealSpan is used to support the use of session tracing, which

nit: I think this comment should be kept outside of the if block since it applies to the else branch too.

andreimatei

Reviewable status: complete! 2 of 0 LGTMs obtained (waiting on @asubiotto and @RaduBerinde)

pkg/sql/conn_executor_exec.go, line 626 at r1 (raw file):

	alreadyRecording := ex.transitionCtx.sessionTracing.Enabled()
	stmtTraceThreshold := traceStmtThreshold.Get(&ex.planner.execCfg.Settings.SV)
	if !alreadyRecording && stmtTraceThreshold > 0 {

why !alreadyRecording ?

pkg/sql/conn_executor_exec.go, line 628 at r1 (raw file):

The trace will only be logged once we determine the execution
time of this statement.

I'm not sure what this is telling me. What's the implied alternative? Consider striking it.

pkg/sql/conn_executor_exec.go, line 639 at r1 (raw file):

	if stmtThresholdSpan != nil {
		logTraceAboveThreshold(ctx, stmtThresholdSpan, fmt.Sprintf("SQL stmt %s", stmt.AST.String()), stmtTraceThreshold, timeutil.Since(ex.phaseTimes[sessionQueryReceived]))

I've bit my tongue on other instances in this patch, but this line is way too long

pkg/sql/conn_executor_exec.go, line 1464 at r1 (raw file):

}

// createRootOrChildSpan is a helper function used to create spans for txns and

nit: s/a helper function/

pkg/sql/conn_executor_exec.go, line 1467 at r1 (raw file):

// stmts. It inspects parentCtx for an existing span and creates a root span if
// none is found, or a child span if one is found. A context derived from
// parentCtx which additionally contains the new span is also returned.

nit: leave a TODO to use tracing.EnsureChildSpan when that one starts taking options. Right @tbg ?

pkg/sql/conn_executor_exec.go, line 1491 at r1 (raw file):

}

// logTraceAboveThreshold is a helper function used when txn or stmt threshold

This comment says everything but what the function does. Pls start with that.

pkg/sql/conn_executor_exec.go, line 1495 at r1 (raw file):

// tracing was enabled.
func logTraceAboveThreshold(
	ctx context.Context, sp *tracing.Span, opName string, threshold, elapsed time.Duration,

I'd make this take a recording, even if you keep the nil check inside the function. It's not like taking a span gives you any extra confidence in the assumptions made by the function.

pkg/sql/conn_executor_exec.go, line 1502 at r1 (raw file):

			if len(dump) > 0 {
				log.Infof(
					ctx, "%s took %s, exceeding threshold of %s:\n%s", opName, elapsed, threshold, dump,

pls leave a comment linking to #50166

pkg/sql/conn_executor_exec.go, line 1507 at r1 (raw file):

		}
	} else {
		log.Warning(ctx, "missing trace when threshold tracing was enabled")

move this case up, return early, and un-indent the common case.

pkg/sql/exec_util.go, line 166 at r1 (raw file):

var traceStmtThreshold = settings.RegisterPublicDurationSetting(
	"sql.trace.stmt.enable_threshold",
	"duration beyond which all statements are traced (set to 0 to disable)", 0,

pls cross-reference to the other setting in the descriptions of both settings

Release note (sql change): add sql.trace.stmt.enable_thresold. Similar to sql.trace.txn.enable_threshold, this logs a trace of any statements that take longer than the specified duration. This new setting allows for more granularity than the transaction threshold since it applies to individual statements and does not include overhead such as communication with a SQL client.

asubiotto

Reviewable status: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei, @RaduBerinde, and @yuzefovich)

pkg/sql/conn_executor_exec.go, line 626 at r1 (raw file):