From 75b15069ce0a10ed029500a252708a53e7264c07 Mon Sep 17 00:00:00 2001 From: Thomas Hardy Date: Mon, 11 Jul 2022 15:36:47 +0000 Subject: [PATCH] sql: add statement fingerprint ID to sampled query This change adds the statement fingerprint ID to the sampled query log, allowing us to measure the uniqueness of a workload. Release note (sql change): Sampled query telemetry log now includes the statement's fingerprint ID. --- docs/generated/eventlog.md | 1 + pkg/sql/conn_executor.go | 1 - pkg/sql/conn_executor_exec.go | 4 +++- pkg/sql/exec_log.go | 24 +++++++++++-------- pkg/sql/executor_statement_metrics.go | 3 ++- pkg/sql/telemetry_logging_test.go | 10 ++++++++ pkg/util/log/eventpb/json_encode_generated.go | 9 +++++++ pkg/util/log/eventpb/telemetry.proto | 3 +++ 8 files changed, 42 insertions(+), 13 deletions(-) diff --git a/docs/generated/eventlog.md b/docs/generated/eventlog.md index 7a71d8af4444..c5da8204bf80 100644 --- a/docs/generated/eventlog.md +++ b/docs/generated/eventlog.md @@ -2439,6 +2439,7 @@ contains common SQL event/execution details. | `StatementID` | Statement ID of the query. | no | | `TransactionID` | Transaction ID of the query. | no | | `DatabaseID` | Database ID of the query. | no | +| `StatementFingerprintID` | Statement fingerprint ID of the query. | no | #### Common fields diff --git a/pkg/sql/conn_executor.go b/pkg/sql/conn_executor.go index 7ea1f3b5ff26..1c0e14061d4a 100644 --- a/pkg/sql/conn_executor.go +++ b/pkg/sql/conn_executor.go @@ -1353,7 +1353,6 @@ type connExecutor struct { savepoints savepointStack sessionDataStack *sessiondata.Stack } - // transactionStatementFingerprintIDs tracks all statement IDs that make up the current // transaction. It's length is bound by the TxnStatsNumStmtFingerprintIDsToRecord // cluster setting. diff --git a/pkg/sql/conn_executor_exec.go b/pkg/sql/conn_executor_exec.go index 764ce48cf2bf..af63ae108c9c 100644 --- a/pkg/sql/conn_executor_exec.go +++ b/pkg/sql/conn_executor_exec.go @@ -1053,6 +1053,7 @@ func (ex *connExecutor) dispatchToExecutionEngine( res.DisableBuffering() } + var stmtFingerprintID roachpb.StmtFingerprintID defer func() { planner.maybeLogStatement( ctx, @@ -1064,6 +1065,7 @@ func (ex *connExecutor) dispatchToExecutionEngine( ex.statsCollector.PhaseTimes().GetSessionPhaseTime(sessionphase.SessionQueryReceived), &ex.extraTxnState.hasAdminRoleCache, ex.server.TelemetryLoggingMetrics, + stmtFingerprintID, ) }() @@ -1170,7 +1172,7 @@ func (ex *connExecutor) dispatchToExecutionEngine( // Record the statement summary. This also closes the plan if the // plan has not been closed earlier. - ex.recordStatementSummary( + stmtFingerprintID = ex.recordStatementSummary( ctx, planner, int(atomic.LoadInt32(ex.extraTxnState.atomicAutoRetryCounter)), res.RowsAffected(), res.Err(), stats, ) diff --git a/pkg/sql/exec_log.go b/pkg/sql/exec_log.go index 0fd49a8b3794..ceadb215b804 100644 --- a/pkg/sql/exec_log.go +++ b/pkg/sql/exec_log.go @@ -16,6 +16,7 @@ import ( "fmt" "time" + "github.com/cockroachdb/cockroach/pkg/roachpb" "github.com/cockroachdb/cockroach/pkg/settings" "github.com/cockroachdb/cockroach/pkg/sql/catalog" "github.com/cockroachdb/cockroach/pkg/sql/catalog/descpb" @@ -155,8 +156,9 @@ func (p *planner) maybeLogStatement( queryReceived time.Time, hasAdminRoleCache *HasAdminRoleCache, telemetryLoggingMetrics *TelemetryLoggingMetrics, + stmtFingerprintID roachpb.StmtFingerprintID, ) { - p.maybeLogStatementInternal(ctx, execType, numRetries, txnCounter, rows, err, queryReceived, hasAdminRoleCache, telemetryLoggingMetrics) + p.maybeLogStatementInternal(ctx, execType, numRetries, txnCounter, rows, err, queryReceived, hasAdminRoleCache, telemetryLoggingMetrics, stmtFingerprintID) } func (p *planner) maybeLogStatementInternal( @@ -167,6 +169,7 @@ func (p *planner) maybeLogStatementInternal( startTime time.Time, hasAdminRoleCache *HasAdminRoleCache, telemetryMetrics *TelemetryLoggingMetrics, + stmtFingerprintID roachpb.StmtFingerprintID, ) { // Note: if you find the code below crashing because p.execCfg == nil, // do not add a test "if p.execCfg == nil { do nothing }" ! @@ -386,15 +389,16 @@ func (p *planner) maybeLogStatementInternal( skippedQueries := telemetryMetrics.resetSkippedQueryCount() databaseName := p.CurrentDatabase() sampledQuery := eventpb.SampledQuery{ - CommonSQLExecDetails: execDetails, - SkippedQueries: skippedQueries, - CostEstimate: p.curPlan.instrumentation.costEstimate, - Distribution: p.curPlan.instrumentation.distribution.String(), - PlanGist: p.curPlan.instrumentation.planGist.String(), - SessionID: p.extendedEvalCtx.SessionID.String(), - Database: p.CurrentDatabase(), - StatementID: p.stmt.QueryID.String(), - TransactionID: p.txn.ID().String(), + CommonSQLExecDetails: execDetails, + SkippedQueries: skippedQueries, + CostEstimate: p.curPlan.instrumentation.costEstimate, + Distribution: p.curPlan.instrumentation.distribution.String(), + PlanGist: p.curPlan.instrumentation.planGist.String(), + SessionID: p.extendedEvalCtx.SessionID.String(), + Database: databaseName, + StatementID: p.stmt.QueryID.String(), + TransactionID: p.txn.ID().String(), + StatementFingerprintID: uint64(stmtFingerprintID), } db, _ := p.Descriptors().GetImmutableDatabaseByName(ctx, p.txn, databaseName, tree.DatabaseLookupFlags{Required: true}) if db != nil { diff --git a/pkg/sql/executor_statement_metrics.go b/pkg/sql/executor_statement_metrics.go index b58570589052..7af5452b8d9e 100644 --- a/pkg/sql/executor_statement_metrics.go +++ b/pkg/sql/executor_statement_metrics.go @@ -116,7 +116,7 @@ func (ex *connExecutor) recordStatementSummary( rowsAffected int, stmtErr error, stats topLevelQueryStats, -) { +) roachpb.StmtFingerprintID { phaseTimes := ex.statsCollector.PhaseTimes() // Collect the statistics. @@ -233,6 +233,7 @@ func (ex *connExecutor) recordStatementSummary( sessionAge, ) } + return stmtFingerprintID } func (ex *connExecutor) updateOptCounters(planFlags planFlags) { diff --git a/pkg/sql/telemetry_logging_test.go b/pkg/sql/telemetry_logging_test.go index 349c953330d5..0bda38a519a2 100644 --- a/pkg/sql/telemetry_logging_test.go +++ b/pkg/sql/telemetry_logging_test.go @@ -22,6 +22,7 @@ import ( "time" "github.com/cockroachdb/cockroach/pkg/base" + "github.com/cockroachdb/cockroach/pkg/roachpb" "github.com/cockroachdb/cockroach/pkg/testutils/serverutils" "github.com/cockroachdb/cockroach/pkg/testutils/sqlutils" "github.com/cockroachdb/cockroach/pkg/util/leaktest" @@ -119,6 +120,7 @@ func TestTelemetryLogging(t *testing.T) { testData := []struct { name string query string + queryNoConstants string execTimestampsSeconds []float64 // Execute the query with the following timestamps. expectedLogStatement string stubMaxEventFrequency int64 @@ -133,6 +135,7 @@ func TestTelemetryLogging(t *testing.T) { // logged since we log all statements that are not of type DML. "truncate-table-query", "TRUNCATE t;", + "TRUNCATE TABLE t", []float64{1, 1.1, 1.2, 2}, `TRUNCATE TABLE`, 1, @@ -145,6 +148,7 @@ func TestTelemetryLogging(t *testing.T) { // The first statement should be logged. "select-*-limit-1-query", "SELECT * FROM t LIMIT 1;", + "SELECT * FROM t LIMIT _", []float64{3}, `SELECT * FROM \"\".\"\".t LIMIT ‹1›`, 1, @@ -158,6 +162,7 @@ func TestTelemetryLogging(t *testing.T) { // thus 2 log statements are expected, with 2 skipped queries. "select-*-limit-2-query", "SELECT * FROM t LIMIT 2;", + "SELECT * FROM t LIMIT _", []float64{4, 4.1, 4.2, 5}, `SELECT * FROM \"\".\"\".t LIMIT ‹2›`, 1, @@ -170,6 +175,7 @@ func TestTelemetryLogging(t *testing.T) { // Once required time has elapsed, the next statement should be logged. "select-*-limit-3-query", "SELECT * FROM t LIMIT 3;", + "SELECT * FROM t LIMIT _", []float64{6, 6.01, 6.05, 6.06, 6.1, 6.2}, `SELECT * FROM \"\".\"\".t LIMIT ‹3›`, 10, @@ -277,6 +283,10 @@ func TestTelemetryLogging(t *testing.T) { if !strings.Contains(e.Message, "\"DatabaseID\":"+strconv.Itoa(int(dbID))) { t.Errorf("expected to find DatabaseID: %v", dbID) } + stmtFingerprintID := roachpb.ConstructStatementFingerprintID(tc.queryNoConstants, false, true, databaseName) + if !strings.Contains(e.Message, "\"StatementFingerprintID\":"+strconv.FormatUint(uint64(stmtFingerprintID), 10)) { + t.Errorf("expected to find StatementFingerprintID: %v", stmtFingerprintID) + } } } if logCount != expectedLogCount { diff --git a/pkg/util/log/eventpb/json_encode_generated.go b/pkg/util/log/eventpb/json_encode_generated.go index 1ee4b674af53..060038c85052 100644 --- a/pkg/util/log/eventpb/json_encode_generated.go +++ b/pkg/util/log/eventpb/json_encode_generated.go @@ -3285,6 +3285,15 @@ func (m *SampledQuery) AppendJSONFields(printComma bool, b redact.RedactableByte b = strconv.AppendUint(b, uint64(m.DatabaseID), 10) } + if m.StatementFingerprintID != 0 { + if printComma { + b = append(b, ',') + } + printComma = true + b = append(b, "\"StatementFingerprintID\":"...) + b = strconv.AppendUint(b, uint64(m.StatementFingerprintID), 10) + } + return printComma, b } diff --git a/pkg/util/log/eventpb/telemetry.proto b/pkg/util/log/eventpb/telemetry.proto index 99cff40b72b2..ffd1b6aebf69 100644 --- a/pkg/util/log/eventpb/telemetry.proto +++ b/pkg/util/log/eventpb/telemetry.proto @@ -61,6 +61,9 @@ message SampledQuery { // Database ID of the query. uint32 database_id = 12 [(gogoproto.customname) = "DatabaseID", (gogoproto.jsontag) = ",omitempty"]; + + // Statement fingerprint ID of the query. + uint64 statement_fingerprint_id = 13 [(gogoproto.customname) = "StatementFingerprintID", (gogoproto.jsontag) = ',omitempty']; } // CapturedIndexUsageStats