sql: slow query log does not report cancellation error code #122722

rafiss · 2024-04-19T22:02:51Z

Describe the problem

The slow query log includes error codes for slow queries. The error code is incorrect for queries that timed out due to statement_timeout or that were canceled explicitly.

To Reproduce

root@localhost:26257/defaultdb> SET CLUSTER SETTING sql.log.slow_query.latency_threshold = '500ms';
SET CLUSTER SETTING

root@localhost:26257/defaultdb> select pg_sleep(1);
  pg_sleep
------------
     t
(1 row)

root@localhost:26257/defaultdb> select pg_sleep(10);
^C  # this is me pressing Ctrl-C to cancel the query

attempting to cancel query...
ERROR: query execution canceled
SQLSTATE: 57014

root@localhost:26257/defaultdb> set statement_timeout = '2s';
SET

root@localhost:26257/defaultdb> select pg_sleep(10);
ERROR: query execution canceled due to statement timeout
SQLSTATE: 57014

Now open cockroach-sql-slow.log. It contains:

I240419 21:52:58.263697 707131 10@util/log/event_log.go:32 ⋮ [T1,Vsystem,n1,client=127.0.0.1:58837,hostnossl,user=root] 1 ={"Timestamp":1713563577261449000,"EventType":"slow_query","Statement":"SELECT pg_sleep(‹1.0›)","Tag":"SELECT","User":"root","ApplicationName":"$ cockroach sql","ExecMode":"exec","NumRows":1,"Age":1001.2132,"TxnCounter":8,"StmtPosInTxn":1}
I240419 21:53:30.362793 707131 10@util/log/event_log.go:32 ⋮ [T1,Vsystem,n1,client=127.0.0.1:58837,hostnossl,user=root] 2 ={"Timestamp":1713563607446246000,"EventType":"slow_query","Statement":"SELECT pg_sleep(‹10.0›)","Tag":"SELECT","User":"root","ApplicationName":"$ cockroach sql","ExecMode":"exec","SQLSTATE":"XXUUU","ErrorText":"pg_sleep(): context canceled","Age":2916.5344,"TxnCounter":10,"StmtPosInTxn":1}
I240419 21:54:45.471589 707131 10@util/log/event_log.go:32 ⋮ [T1,Vsystem,n1,client=127.0.0.1:58837,hostnossl,user=root] 3 ={"Timestamp":1713563683468890000,"EventType":"slow_query","Statement":"SELECT ‹pg_sleep›(‹10›)","Tag":"SELECT","User":"root","ApplicationName":"$ cockroach sql","ExecMode":"exec","SQLSTATE":"XXUUU","ErrorText":"pg_sleep(): context canceled","Age":2002.7068,"TxnCounter":14,"StmtPosInTxn":1}

Expected behavior

The first line in those logs is correct. But the latter 2 should have an error code of 57014 (instead of XXUUU).

Environment:
Tested this on v23.2.1, but all versions are affected.

Additional context
The issue is that the error code is added here

cockroach/pkg/sql/conn_executor_exec.go

Lines 479 to 484 in e9d1b46

    
           // Detect context cancelation and overwrite whatever error might have been 
        
           // set on the result before. The idea is that once the query's context is 
        
           // canceled, all sorts of actors can detect the cancelation and set all 
        
           // sorts of errors on the result. Rather than trying to impose discipline 
        
           // in that jungle, we just overwrite them all here with an error that's 
        
           // nicer to look at for the client.

and here

cockroach/pkg/sql/conn_executor_exec.go

Lines 522 to 529 in e9d1b46

    
           if queryTimedOut { 
        
           	// A timed out query should never produce retryable errors/events/payloads 
        
           	// so we intercept and overwrite them all here. 
        
           	retEv = eventNonRetriableErr{ 
        
           		IsCommit: fsm.FromBool(isCommit(ast)), 
        
           	} 
        
           	res.SetError(sqlerrors.QueryTimeoutError) 
        
           	retPayload = eventNonRetriableErrPayload{err: sqlerrors.QueryTimeoutError}

That error rewriting logic is in execStmtInOpenState. The slow query log is written in dispatchToExecutionEngine. Since execStmtInOpenState is a caller of dispatchToExecutionEngine, that means the error code is only added after the log is written.

see https://cockroachlabs.slack.com/archives/C06PEGL22UX/p1713373695222239?thread_ts=1713193977.393989&cid=C06PEGL22UX

Jira issue: CRDB-38034

Epic CRDB-38033

The text was updated successfully, but these errors were encountered:

rafiss · 2024-04-23T18:37:31Z

As a first attempt, let's see if we can move the logging code into execStmtInOpenState. The logging is currently done here:

cockroach/pkg/sql/conn_executor_exec.go

Lines 1861 to 1918 in e9d1b46

    
           defer func() { 
        
           	var bulkJobId uint64 
        
           	if ppInfo := getPausablePortalInfo(); ppInfo != nil && !ppInfo.dispatchToExecutionEngine.cleanup.isComplete { 
        
           		ppInfo.dispatchToExecutionEngine.cleanup.appendFunc(namedFunc{ 
        
           			fName: "log statement", 
        
           			f: func() { 
        
           				if planner.extendedEvalCtx.Annotations == nil { 
        
           					// This is a safety check in case resetPlanner() was 
        
           					// executed, but then we never set the annotations on 
        
           					// the planner. Formatting the stmt for logging requires 
        
           					// non-nil annotations. 
        
           					planner.extendedEvalCtx.Annotations = &planner.semaCtx.Annotations 
        
           				} 
        
           				planner.maybeLogStatement( 
        
           					ctx, 
        
           					ex.executorType, 
        
           					int(ex.state.mu.autoRetryCounter), 
        
           					int(ex.extraTxnState.txnCounter.Load()), 
        
           					ppInfo.dispatchToExecutionEngine.rowsAffected, 
        
           					ex.state.mu.stmtCount, 
        
           					bulkJobId, 
        
           					ppInfo.curRes.ErrAllowReleased(), 
        
           					ex.statsCollector.PhaseTimes().GetSessionPhaseTime(sessionphase.SessionQueryReceived), 
        
           					&ex.extraTxnState.hasAdminRoleCache, 
        
           					ex.server.TelemetryLoggingMetrics, 
        
           					ppInfo.dispatchToExecutionEngine.stmtFingerprintID, 
        
           					ppInfo.dispatchToExecutionEngine.queryStats, 
        
           					ex.statsCollector, 
        
           					ex.extraTxnState.shouldLogToTelemetry) 
        
           			}, 
        
           		}) 
        
           	} else { 
        
           		// Note that for bulk job query (IMPORT, BACKUP and RESTORE), we don't 
        
           		// use this numRows entry. We emit the number of changed rows when the job 
        
           		// completes. (see the usages of logutil.LogJobCompletion()). 
        
           		nonBulkJobNumRows := res.RowsAffected() 
        
           		switch planner.stmt.AST.(type) { 
        
           		case *tree.Import, *tree.Restore, *tree.Backup: 
        
           			bulkJobId = res.GetBulkJobId() 
        
           		} 
        
           		planner.maybeLogStatement( 
        
           			ctx, 
        
           			ex.executorType, 
        
           			int(ex.state.mu.autoRetryCounter), 
        
           			int(ex.extraTxnState.txnCounter.Load()), 
        
           			nonBulkJobNumRows, 
        
           			ex.state.mu.stmtCount, 
        
           			bulkJobId, 
        
           			res.Err(), 
        
           			ex.statsCollector.PhaseTimes().GetSessionPhaseTime(sessionphase.SessionQueryReceived), 
        
           			&ex.extraTxnState.hasAdminRoleCache, 
        
           			ex.server.TelemetryLoggingMetrics, 
        
           			stmtFingerprintID, 
        
           			&stats, 
        
           			ex.statsCollector, 
        
           			ex.extraTxnState.shouldLogToTelemetry) 
        
           	} 
        
           }()

rimadeodhar · 2024-05-06T19:21:43Z

Moving to the observability team as discussed with @nkodali

xinhaoz · 2024-05-13T22:41:44Z

I tested this out today and it looks like we can move the logging into execOpenState fine. There's some nuances with pausible portals and preserving the order of cleanup operations. Overall should be doable, hoping to get a PR out this week.

Previously topLevelQueryStats were being passed directly into the logging function after execution in dispatchToExecutionEngine. This commit persists the top level stats of the query execution into the planner's instrumentation helper, similar to what we do with sampled query exec stats. This allows us to move the logging operation in dispatchToExecutionEngine to `execStmtInOpenState`. Part of: cockroachdb#122722 Release note: None

Currently we construct the stmt fingerprint id at various places to pass to the logging function. We only need the statement fingerprint id for telemetry logging, so this construction is wasteful in other scenarios. This commit moves the stmt fingerprint id generation to the logging function. Summary: - Record the current stmt fingerprint id in the stats collector when writing sql stats. This value is reset at the start of stmt exec. - Construct stmt fingerprint at the time of logging based on the AST in the planner if it was not available in the stats collector. This change is motivated by the desire to move logging from `disatpchToExecutionEngine` to `execStmtInOpenState`. See issue for details. Part of: cockroachdb#122722

Currently we construct the stmt fingerprint id at various places to pass to the logging function. We only need the statement fingerprint id for telemetry logging, so this construction is wasteful in other scenarios. This commit moves the stmt fingerprint id generation to the logging function. Summary: - Record the current stmt fingerprint id in the stats collector when writing sql stats. This value is reset at the start of stmt exec. - Construct stmt fingerprint at the time of logging based on the AST in the planner if it was not available in the stats collector. This change is motivated by the desire to move logging from `disatpchToExecutionEngine` to `execStmtInOpenState`. See issue for details. Part of: cockroachdb#122722 Release note: None

Previously topLevelQueryStats were being passed directly into the logging function after execution in dispatchToExecutionEngine. This commit persists the top level stats of the query execution into the planner's instrumentation helper, similar to what we do with sampled query exec stats. This allows us to move the logging operation in dispatchToExecutionEngine to `execStmtInOpenState`. Part of: cockroachdb#122722 Release note: None

Currently we construct the stmt fingerprint id at various places to pass to the logging function. We only need the statement fingerprint id for telemetry logging, so this construction is wasteful in other scenarios. This commit moves the stmt fingerprint id generation to the logging function. Summary: - Record the current stmt fingerprint id in the stats collector when writing sql stats. This value is reset at the start of stmt exec. - Construct stmt fingerprint at the time of logging based on the AST in the planner if it was not available in the stats collector. This change is motivated by the desire to move logging from `disatpchToExecutionEngine` to `execStmtInOpenState`. See issue for details. Part of: cockroachdb#122722 Release note: None

Setting a query timeout or cancellation error occurs in execStmtInOpenState, while logging occurs in dispatchToExecutionEngine (called on by the former). This previously resulted in the incorrect pg error code being surfaced when logging cancelled queries. This commit moves statement logging from dispatchToExecutionEngine to execStmtInOpenState so that we have the correct error information at the time of logging. Epic: none Fixes: cockroachdb#122722 Release note (bug fix): Fixes a bug in logging where error code was misreported for cancelled queries. Affected channels: SQL_PERF (slow query logs), SQL_EXEC (sql exec logs).