Skip to content

Commit

Permalink
sql: add statement fingerprint ID to sampled query
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
Thomas Hardy committed Jul 11, 2022
1 parent cf94eeb commit 75b1506
Show file tree
Hide file tree
Showing 8 changed files with 42 additions and 13 deletions.
1 change: 1 addition & 0 deletions docs/generated/eventlog.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
1 change: 0 additions & 1 deletion pkg/sql/conn_executor.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
4 changes: 3 additions & 1 deletion pkg/sql/conn_executor_exec.go
Original file line number Diff line number Diff line change
Expand Up @@ -1053,6 +1053,7 @@ func (ex *connExecutor) dispatchToExecutionEngine(
res.DisableBuffering()
}

var stmtFingerprintID roachpb.StmtFingerprintID
defer func() {
planner.maybeLogStatement(
ctx,
Expand All @@ -1064,6 +1065,7 @@ func (ex *connExecutor) dispatchToExecutionEngine(
ex.statsCollector.PhaseTimes().GetSessionPhaseTime(sessionphase.SessionQueryReceived),
&ex.extraTxnState.hasAdminRoleCache,
ex.server.TelemetryLoggingMetrics,
stmtFingerprintID,
)
}()

Expand Down Expand Up @@ -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,
)
Expand Down
24 changes: 14 additions & 10 deletions pkg/sql/exec_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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(
Expand All @@ -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 }" !
Expand Down Expand Up @@ -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 {
Expand Down
3 changes: 2 additions & 1 deletion pkg/sql/executor_statement_metrics.go
Original file line number Diff line number Diff line change
Expand Up @@ -116,7 +116,7 @@ func (ex *connExecutor) recordStatementSummary(
rowsAffected int,
stmtErr error,
stats topLevelQueryStats,
) {
) roachpb.StmtFingerprintID {
phaseTimes := ex.statsCollector.PhaseTimes()

// Collect the statistics.
Expand Down Expand Up @@ -233,6 +233,7 @@ func (ex *connExecutor) recordStatementSummary(
sessionAge,
)
}
return stmtFingerprintID
}

func (ex *connExecutor) updateOptCounters(planFlags planFlags) {
Expand Down
10 changes: 10 additions & 0 deletions pkg/sql/telemetry_logging_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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
Expand All @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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 {
Expand Down
9 changes: 9 additions & 0 deletions pkg/util/log/eventpb/json_encode_generated.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

3 changes: 3 additions & 0 deletions pkg/util/log/eventpb/telemetry.proto
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit 75b1506

Please sign in to comment.