Skip to content

Commit

Permalink
Browse files Browse the repository at this point in the history
108395: telemetry: log all querys used by internal-console r=maryliag a=maryliag

Add a cluster setting to make it possible to log
all queries used by our console (application name
starts with `$ internal-console`).
The console emits just a couple of them, so there
should be no concern with performance.

This commit also updates querys used by our console to include de `internal-console` on the application name.

Fixes cockroachdb#94250

Release note: None

Co-authored-by: maryliag <[email protected]>
  • Loading branch information
craig[bot] and maryliag committed Aug 10, 2023
2 parents 4b208ca + db4323f commit d819b9c
Show file tree
Hide file tree
Showing 5 changed files with 132 additions and 18 deletions.
27 changes: 14 additions & 13 deletions pkg/server/combined_statement_stats.go
Original file line number Diff line number Diff line change
Expand Up @@ -218,7 +218,7 @@ FROM crdb_internal.statement_activity
// Format string "2006-01-02 15:04:05.00" is a golang-specific string
it, err := ie.QueryIteratorEx(
ctx,
"activity-min-ts",
"console-combined-stmts-activity-min-ts",
nil,
sessiondata.NodeUserSessionDataOverride,
fmt.Sprintf(queryWithPlaceholders, zeroDate.Format("2006-01-02 15:04:05.00"), testingKnobs.GetAOSTClause()))
Expand Down Expand Up @@ -280,7 +280,7 @@ func getTotalRuntimeSecs(
getRuntime := func(table string) (float32, error) {
it, err := ie.QueryIteratorEx(
ctx,
fmt.Sprintf(`%s-total-runtime`, table),
fmt.Sprintf(`console-combined-stmts-%s-total-runtime`, table),
nil,
sessiondata.NodeUserSessionDataOverride,
fmt.Sprintf(`
Expand Down Expand Up @@ -740,8 +740,9 @@ func getIterator(
whereClause,
aostClause,
orderAndLimit)
opName := fmt.Sprintf(`console-combined-stmts-%s`, queryInfo)

it, err := ie.QueryIteratorEx(ctx, queryInfo, nil,
it, err := ie.QueryIteratorEx(ctx, opName, nil,
sessiondata.NodeUserSessionDataOverride, query, args...)
if err != nil {
return it, srverrors.ServerError(ctx, err)
Expand Down Expand Up @@ -917,7 +918,7 @@ GROUP BY
var err error

if activityTableHasAllData {
it, err = ie.QueryIteratorEx(ctx, "stmts-activity-for-txn", nil,
it, err = ie.QueryIteratorEx(ctx, "console-combined-stmts-activity-for-txn", nil,
sessiondata.NodeUserSessionDataOverride, fmt.Sprintf(`
SELECT fingerprint_id,
transaction_fingerprint_id,
Expand Down Expand Up @@ -948,7 +949,7 @@ GROUP BY
queryFormat,
"crdb_internal.statement_statistics_persisted"+tableSuffix,
whereClause)
it, err = ie.QueryIteratorEx(ctx, "stmts-persisted-for-txn", nil,
it, err = ie.QueryIteratorEx(ctx, "console-combined-stmts-persisted-for-txn", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)

if err != nil {
Expand All @@ -965,7 +966,7 @@ GROUP BY
}
query = fmt.Sprintf(queryFormat, "crdb_internal.statement_statistics", whereClause)

it, err = ie.QueryIteratorEx(ctx, "stmts-with-memory-for-txn", nil,
it, err = ie.QueryIteratorEx(ctx, "console-combined-stmts-with-memory-for-txn", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)

if err != nil {
Expand Down Expand Up @@ -1345,7 +1346,7 @@ LIMIT $%d`
args = append(args, limit)

if activityTableHasAllData {
it, err = ie.QueryIteratorEx(ctx, "combined-stmts-activity-details-by-aggregated-timestamp", nil,
it, err = ie.QueryIteratorEx(ctx, "console-combined-stmts-activity-details-by-aggregated-timestamp", nil,
sessiondata.NodeUserSessionDataOverride,
fmt.Sprintf(`
SELECT aggregated_ts,
Expand Down Expand Up @@ -1375,7 +1376,7 @@ LIMIT $%d`, whereClause, len(args)),
whereClause,
len(args))

it, err = ie.QueryIteratorEx(ctx, "combined-stmts-persisted-details-by-aggregated-timestamp", nil,
it, err = ie.QueryIteratorEx(ctx, "console-combined-stmts-persisted-details-by-aggregated-timestamp", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)

if err != nil {
Expand All @@ -1388,7 +1389,7 @@ LIMIT $%d`, whereClause, len(args)),
if !it.HasResults() {
err = closeIterator(it, err)
query = fmt.Sprintf(queryFormat, "crdb_internal.statement_statistics", whereClause, len(args))
it, err = ie.QueryIteratorEx(ctx, "combined-stmts-details-by-aggregated-timestamp-with-memory", nil,
it, err = ie.QueryIteratorEx(ctx, "console-combined-stmts-details-by-aggregated-timestamp-with-memory", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)
if err != nil {
return nil, srverrors.ServerError(ctx, err)
Expand Down Expand Up @@ -1444,7 +1445,7 @@ func getExplainPlanFromGist(ctx context.Context, ie *sql.InternalExecutor, planG
const query = `SELECT crdb_internal.decode_plan_gist($1)`
args = append(args, planGist)

it, err := ie.QueryIteratorEx(ctx, "combined-stmts-details-get-explain-plan", nil,
it, err := ie.QueryIteratorEx(ctx, "console-combined-stmts-details-get-explain-plan", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)

if err != nil {
Expand Down Expand Up @@ -1543,7 +1544,7 @@ LIMIT $%d`
}()

if activityTableHasAllData {
it, iterErr = ie.QueryIteratorEx(ctx, "combined-stmts-activity-details-by-plan-hash", nil,
it, iterErr = ie.QueryIteratorEx(ctx, "console-combined-stmts-activity-details-by-plan-hash", nil,
sessiondata.NodeUserSessionDataOverride, fmt.Sprintf(`
SELECT plan_hash,
(statistics -> 'statistics' -> 'planGists' ->> 0) AS plan_gist,
Expand Down Expand Up @@ -1572,7 +1573,7 @@ LIMIT $%d`, whereClause, len(args)), args...)
"crdb_internal.statement_statistics_persisted"+tableSuffix,
whereClause,
len(args))
it, iterErr = ie.QueryIteratorEx(ctx, "combined-stmts-persisted-details-by-plan-hash", nil,
it, iterErr = ie.QueryIteratorEx(ctx, "console-combined-stmts-persisted-details-by-plan-hash", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)
if iterErr != nil {
return nil, srverrors.ServerError(ctx, err)
Expand All @@ -1584,7 +1585,7 @@ LIMIT $%d`, whereClause, len(args)), args...)
if !it.HasResults() {
err = closeIterator(it, err)
query = fmt.Sprintf(queryFormat, "crdb_internal.statement_statistics", whereClause, len(args))
it, iterErr = ie.QueryIteratorEx(ctx, "combined-stmts-details-by-plan-hash-with-memory", nil,
it, iterErr = ie.QueryIteratorEx(ctx, "console-combined-stmts-details-by-plan-hash-with-memory", nil,
sessiondata.NodeUserSessionDataOverride, query, args...)
if iterErr != nil {
return nil, srverrors.ServerError(ctx, err)
Expand Down
14 changes: 10 additions & 4 deletions pkg/sql/exec_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ package sql
import (
"context"
"sort"
"strings"
"time"

"github.com/cockroachdb/cockroach/pkg/settings"
Expand Down Expand Up @@ -162,11 +163,13 @@ func (p *planner) maybeLogStatementInternal(
slowInternalQueryLogEnabled := slowInternalQueryLogEnabled.Get(&p.execCfg.Settings.SV)
auditEventsDetected := len(p.curPlan.auditEventBuilders) != 0
maxEventFrequency := TelemetryMaxEventFrequency.Get(&p.execCfg.Settings.SV)
logConsoleQuery := telemetryInternalConsoleQueriesEnabled.Get(&p.execCfg.Settings.SV) &&
strings.HasPrefix(p.SessionData().ApplicationName, "$ internal-console")

// We only consider non-internal SQL statements for telemetry logging unless
// the telemetryInternalQueriesEnabled is true.
telemetryLoggingEnabled := telemetryLoggingEnabled.Get(&p.execCfg.Settings.SV) &&
(execType == executorTypeExec || telemetryInternalQueriesEnabled.Get(&p.execCfg.Settings.SV))
(execType == executorTypeExec || telemetryInternalQueriesEnabled.Get(&p.execCfg.Settings.SV) || logConsoleQuery)

// If hasAdminRoleCache IsSet is true iff AdminAuditLog is enabled.
shouldLogToAdminAuditLog := hasAdminRoleCache.IsSet && hasAdminRoleCache.HasAdminRole
Expand Down Expand Up @@ -278,9 +281,12 @@ func (p *planner) maybeLogStatementInternal(
// the last event emission.
requiredTimeElapsed := 1.0 / float64(maxEventFrequency)
tracingEnabled := telemetryMetrics.isTracing(p.curPlan.instrumentation.Tracing())
// Always sample if the current statement is not of type DML or tracing
// is enabled for this statement.
if p.stmt.AST.StatementType() != tree.TypeDML || tracingEnabled {
// Always sample if one of the scenarios is true:
// - the current statement is not of type DML
// - tracing is enabled for this statement
// - this is a query emitted by our console (application_name starts with `$ internal-console`) and
// the cluster setting to log console queries is enabled
if p.stmt.AST.StatementType() != tree.TypeDML || tracingEnabled || logConsoleQuery {
requiredTimeElapsed = 0
}
if telemetryMetrics.maybeUpdateLastEmittedTime(telemetryMetrics.timeNow(), requiredTimeElapsed) {
Expand Down
8 changes: 8 additions & 0 deletions pkg/sql/telemetry_logging.go
Original file line number Diff line number Diff line change
Expand Up @@ -42,6 +42,14 @@ var telemetryInternalQueriesEnabled = settings.RegisterBoolSetting(
false,
).WithPublic()

var telemetryInternalConsoleQueriesEnabled = settings.RegisterBoolSetting(
settings.TenantWritable,
"sql.telemetry.query_sampling.internal_console.enabled",
"when set to true, all internal queries used to populated the UI Console"+
"will be logged into telemetry",
true,
)

// TelemetryLoggingMetrics keeps track of the last time at which an event
// was logged to the telemetry channel, and the number of skipped queries
// since the last logged event.
Expand Down
99 changes: 99 additions & 0 deletions pkg/sql/telemetry_logging_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -792,6 +792,105 @@ func TestTelemetryLoggingInternalEnabled(t *testing.T) {
}
}

// TestTelemetryLoggingInternalConsoleEnabled verifies that setting the cluster setting to send
// internal console queries to telemetry works as intended.
func TestTelemetryLoggingInternalConsoleEnabled(t *testing.T) {
defer leaktest.AfterTest(t)()
sc := log.ScopeWithoutShowLogs(t)
defer sc.Close(t)

cleanup := logtestutils.InstallLogFileSink(sc, t, logpb.Channel_TELEMETRY)
defer cleanup()

st := logtestutils.StubTime{}
sts := logtestutils.StubTracingStatus{}

s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{
Knobs: base.TestingKnobs{
EventLog: &EventLogTestingKnobs{
// The sampling checks below need to have a deterministic
// number of statements run by internal executor.
SyncWrites: true,
},
TelemetryLoggingKnobs: &TelemetryLoggingTestingKnobs{
getTimeNow: st.TimeNow,
getTracingStatus: sts.TracingStatus,
},
},
})
stubTime := timeutil.FromUnixMicros(int64(1e6))
st.SetTime(stubTime)
defer s.Stopper().Stop(context.Background())

db := sqlutils.MakeSQLRunner(sqlDB)
db.Exec(t, `SET CLUSTER SETTING sql.telemetry.query_sampling.enabled = true;`)
// Set query internal to `false` to guarantee that if an entry qith `internal-console` is showing
// is because of the setting `sql.telemetry.query_sampling.internal_console.enabled` and not
// being sampled as a regular internal.
db.Exec(t, `SET CLUSTER SETTING sql.telemetry.query_sampling.internal.enabled = false;`)

testData := []struct {
appName string
logInternalConsole bool
errorMessage string
}{
{
"$ internal-console",
false,
"query from internal-console found on logs with internal_console cluster setting disabled",
},
{
"$ internal-console-extra-name",
false,
"query from internal-console-extra-name found on logs with internal_console cluster setting disabled",
},
{
"$ internal-console",
true,
"query from internal-console not found on logs with internal_console cluster setting enabled",
},
{
"$ internal-console-extra-name",
true,
"query from internal-console-extra-name not found on logs with internal_console cluster setting enabled",
},
}

query := `SELECT count(*) FROM crdb_internal.statement_statistics`
for _, tc := range testData {
db.Exec(t, `SET application_name = $1`, tc.appName)
db.Exec(t, `SET CLUSTER SETTING sql.telemetry.query_sampling.internal_console.enabled = $1;`, tc.logInternalConsole)
db.Exec(t, query)
log.Flush()

entries, err := log.FetchEntriesFromFiles(
0,
math.MaxInt64,
10000,
regexp.MustCompile(`"EventType":"sampled_query"`),
log.WithMarkedSensitiveData,
)
if err != nil {
t.Fatal(err)
}
if len(entries) == 0 {
t.Fatal(errors.Newf("no entries found"))
}

found := false
for _, e := range entries {
if strings.Contains(e.Message, tc.appName) && strings.Contains(e.Message, query) {
found = true
break
}
}

if found != tc.logInternalConsole {
t.Errorf(tc.errorMessage)
}
}
}

func TestNoTelemetryLogOnTroubleshootMode(t *testing.T) {
defer leaktest.AfterTest(t)()
sc := log.ScopeWithoutShowLogs(t)
Expand Down
2 changes: 1 addition & 1 deletion pkg/ui/workspaces/cluster-ui/src/api/sqlApi.ts
Original file line number Diff line number Diff line change
Expand Up @@ -107,7 +107,7 @@ export const FALLBACK_DB = "system";
export function executeInternalSql<RowType>(
req: SqlExecutionRequest,
): Promise<SqlExecutionResponse<RowType>> {
if (!req.application_name) {
if (!req.application_name || req.application_name === INTERNAL_SQL_API_APP) {
req.application_name = INTERNAL_SQL_API_APP;
} else {
req.application_name = `$ internal-${req.application_name}`;
Expand Down

0 comments on commit d819b9c

Please sign in to comment.