diff --git a/go/flags/endtoend/vtcombo.txt b/go/flags/endtoend/vtcombo.txt index c2667b9d288..436b84a6216 100644 --- a/go/flags/endtoend/vtcombo.txt +++ b/go/flags/endtoend/vtcombo.txt @@ -272,6 +272,7 @@ Flags: --querylog-mode string Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged. (default "all") --querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged. --querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries) + --querylog-time-threshold duration Execution time duration a query needs to run over before being logged; time duration expressed in the form recognized by time.ParseDuration; not useful for streaming queries. --queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables). --queryserver-config-annotate-queries prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type --queryserver-config-enable-table-acl-dry-run If this flag is enabled, tabletserver will emit monitoring metrics and let the request pass regardless of table acl check results diff --git a/go/flags/endtoend/vtgate.txt b/go/flags/endtoend/vtgate.txt index dd79a2e8226..cb7c82eee04 100644 --- a/go/flags/endtoend/vtgate.txt +++ b/go/flags/endtoend/vtgate.txt @@ -181,6 +181,7 @@ Flags: --querylog-mode string Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged. (default "all") --querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged. --querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries) + --querylog-time-threshold duration Execution time duration a query needs to run over before being logged; time duration expressed in the form recognized by time.ParseDuration; not useful for streaming queries. --redact-debug-ui-queries redact full queries and bind variables from debug UI --remote-operation-timeout duration time to wait for a remote operation (default 15s) --retry-count int retry count (default 2) diff --git a/go/flags/endtoend/vttablet.txt b/go/flags/endtoend/vttablet.txt index a425f3efc7e..8bf6999bc93 100644 --- a/go/flags/endtoend/vttablet.txt +++ b/go/flags/endtoend/vttablet.txt @@ -264,6 +264,7 @@ Flags: --querylog-mode string Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged. (default "all") --querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged. --querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries) + --querylog-time-threshold duration Execution time duration a query needs to run over before being logged; time duration expressed in the form recognized by time.ParseDuration; not useful for streaming queries. --queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables). --queryserver-config-annotate-queries prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type --queryserver-config-enable-table-acl-dry-run If this flag is enabled, tabletserver will emit monitoring metrics and let the request pass regardless of table acl check results diff --git a/go/streamlog/streamlog.go b/go/streamlog/streamlog.go index 00fc4dd4478..ab8ed12f9d2 100644 --- a/go/streamlog/streamlog.go +++ b/go/streamlog/streamlog.go @@ -26,6 +26,7 @@ import ( "os" "strings" "sync" + "time" "github.com/spf13/pflag" @@ -67,6 +68,7 @@ type QueryLogConfig struct { Format string Mode string RowThreshold uint64 + TimeThreshold time.Duration sampleRate float64 } @@ -104,6 +106,9 @@ func registerStreamLogFlags(fs *pflag.FlagSet) { // QueryLogRowThreshold only log queries returning or affecting this many rows fs.Uint64Var(&queryLogConfigInstance.RowThreshold, "querylog-row-threshold", queryLogConfigInstance.RowThreshold, "Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.") + // QueryLogTimeThreshold only log queries with execution time over the time duration threshold + fs.DurationVar(&queryLogConfigInstance.TimeThreshold, "querylog-time-threshold", queryLogConfigInstance.TimeThreshold, "Execution time duration a query needs to run over before being logged; time duration expressed in the form recognized by time.ParseDuration; not useful for streaming queries.") + // QueryLogSampleRate causes a sample of queries to be logged fs.Float64Var(&queryLogConfigInstance.sampleRate, "querylog-sample-rate", queryLogConfigInstance.sampleRate, "Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)") @@ -266,13 +271,16 @@ func (qlConfig QueryLogConfig) shouldSampleQuery() bool { // ShouldEmitLog returns whether the log with the given SQL query // should be emitted or filtered -func (qlConfig QueryLogConfig) ShouldEmitLog(sql string, rowsAffected, rowsReturned uint64, hasError bool) bool { +func (qlConfig QueryLogConfig) ShouldEmitLog(sql string, rowsAffected, rowsReturned uint64, totalTime time.Duration, hasError bool) bool { if qlConfig.shouldSampleQuery() { return true } if qlConfig.RowThreshold > max(rowsAffected, rowsReturned) && qlConfig.FilterTag == "" { return false } + if qlConfig.TimeThreshold > totalTime && qlConfig.TimeThreshold > 0 && qlConfig.FilterTag == "" { + return false + } if qlConfig.FilterTag != "" { return strings.Contains(sql, qlConfig.FilterTag) } diff --git a/go/streamlog/streamlog_test.go b/go/streamlog/streamlog_test.go index 8256ada479e..d516229bc4f 100644 --- a/go/streamlog/streamlog_test.go +++ b/go/streamlog/streamlog_test.go @@ -281,69 +281,105 @@ func TestShouldSampleQuery(t *testing.T) { func TestShouldEmitLog(t *testing.T) { tests := []struct { - sql string - qLogFilterTag string - qLogRowThreshold uint64 - qLogSampleRate float64 - qLogMode string - rowsAffected uint64 - rowsReturned uint64 - errored bool - ok bool + sql string + qLogFilterTag string + qLogRowThreshold uint64 + qLogTimeThreshold time.Duration + qLogSampleRate float64 + qLogMode string + rowsAffected uint64 + rowsReturned uint64 + totalTime time.Duration + errored bool + ok bool }{ { - sql: "queryLogThreshold smaller than affected and returned", - qLogFilterTag: "", - qLogRowThreshold: 2, - qLogSampleRate: 0.0, - rowsAffected: 7, - rowsReturned: 7, - ok: true, + sql: "queryLogRowThreshold smaller than affected and returned", + qLogFilterTag: "", + qLogRowThreshold: 2, + qLogTimeThreshold: 0, + qLogSampleRate: 0.0, + rowsAffected: 7, + rowsReturned: 7, + totalTime: 1000, + ok: true, }, { - sql: "queryLogThreshold greater than affected and returned", - qLogFilterTag: "", - qLogRowThreshold: 27, - qLogSampleRate: 0.0, - rowsAffected: 7, - rowsReturned: 17, - ok: false, + sql: "queryLogRowThreshold greater than affected and returned", + qLogFilterTag: "", + qLogRowThreshold: 27, + qLogTimeThreshold: 0, + qLogSampleRate: 0.0, + rowsAffected: 7, + rowsReturned: 17, + totalTime: 1000, + ok: false, }, { - sql: "this doesn't contains queryFilterTag: TAG", - qLogFilterTag: "special tag", - qLogRowThreshold: 10, - qLogSampleRate: 0.0, - rowsAffected: 7, - rowsReturned: 17, - ok: false, + sql: "queryLogTimeThreshold smaller than total time and returned", + qLogFilterTag: "", + qLogRowThreshold: 0, + qLogTimeThreshold: 10, + qLogSampleRate: 0.0, + rowsAffected: 7, + rowsReturned: 7, + totalTime: 1000, + ok: true, }, { - sql: "this contains queryFilterTag: TAG", - qLogFilterTag: "TAG", - qLogRowThreshold: 0, - qLogSampleRate: 0.0, - rowsAffected: 7, - rowsReturned: 17, - ok: true, + sql: "queryLogTimeThreshold greater than total time and returned", + qLogFilterTag: "", + qLogRowThreshold: 0, + qLogTimeThreshold: 10000, + qLogSampleRate: 0.0, + rowsAffected: 7, + rowsReturned: 17, + totalTime: 1000, + ok: false, }, { - sql: "this contains querySampleRate: 1.0", - qLogFilterTag: "", - qLogRowThreshold: 0, - qLogSampleRate: 1.0, - rowsAffected: 7, - rowsReturned: 17, - ok: true, + sql: "this doesn't contains queryFilterTag: TAG", + qLogFilterTag: "special tag", + qLogRowThreshold: 10, + qLogTimeThreshold: 0, + qLogSampleRate: 0.0, + rowsAffected: 7, + rowsReturned: 17, + totalTime: 1000, + ok: false, }, { - sql: "this contains querySampleRate: 1.0 without expected queryFilterTag", - qLogFilterTag: "TAG", - qLogRowThreshold: 0, - qLogSampleRate: 1.0, - rowsAffected: 7, - rowsReturned: 17, - ok: true, + sql: "this contains queryFilterTag: TAG", + qLogFilterTag: "TAG", + qLogRowThreshold: 0, + qLogTimeThreshold: 0, + qLogSampleRate: 0.0, + rowsAffected: 7, + rowsReturned: 17, + totalTime: 1000, + ok: true, + }, + { + sql: "this contains querySampleRate: 1.0", + qLogFilterTag: "", + qLogRowThreshold: 0, + qLogTimeThreshold: 0, + qLogSampleRate: 1.0, + rowsAffected: 7, + rowsReturned: 17, + totalTime: 1000, + ok: true, + }, + { + sql: "this contains querySampleRate: 1.0 without expected queryFilterTag", + qLogFilterTag: "TAG", + qLogRowThreshold: 0, + qLogTimeThreshold: 0, + qLogSampleRate: 1.0, + rowsAffected: 7, + rowsReturned: 17, + totalTime: 1000, + ok: true, }, { sql: "log only error - no error", @@ -362,12 +398,13 @@ func TestShouldEmitLog(t *testing.T) { for _, tt := range tests { t.Run(tt.sql, func(t *testing.T) { qlConfig := QueryLogConfig{ - FilterTag: tt.qLogFilterTag, - RowThreshold: tt.qLogRowThreshold, - sampleRate: tt.qLogSampleRate, - Mode: tt.qLogMode, + FilterTag: tt.qLogFilterTag, + RowThreshold: tt.qLogRowThreshold, + TimeThreshold: tt.qLogTimeThreshold, + sampleRate: tt.qLogSampleRate, + Mode: tt.qLogMode, } - require.Equal(t, tt.ok, qlConfig.ShouldEmitLog(tt.sql, tt.rowsAffected, tt.rowsReturned, tt.errored)) + require.Equal(t, tt.ok, qlConfig.ShouldEmitLog(tt.sql, tt.rowsAffected, tt.rowsReturned, tt.totalTime, tt.errored)) }) } } diff --git a/go/vt/vtgate/logstats/logstats.go b/go/vt/vtgate/logstats/logstats.go index 3ad75d07722..c4e6ea382a8 100644 --- a/go/vt/vtgate/logstats/logstats.go +++ b/go/vt/vtgate/logstats/logstats.go @@ -133,7 +133,7 @@ func (stats *LogStats) MirrorTargetErrorStr() string { // Logf formats the log record to the given writer, either as // tab-separated list of logged fields or as JSON. func (stats *LogStats) Logf(w io.Writer, params url.Values) error { - if !stats.Config.ShouldEmitLog(stats.SQL, stats.RowsAffected, stats.RowsReturned, stats.Error != nil) { + if !stats.Config.ShouldEmitLog(stats.SQL, stats.RowsAffected, stats.RowsReturned, stats.TotalTime(), stats.Error != nil) { return nil } diff --git a/go/vt/vtgate/logstats/logstats_test.go b/go/vt/vtgate/logstats/logstats_test.go index 78b27342a7e..df1df92cf89 100644 --- a/go/vt/vtgate/logstats/logstats_test.go +++ b/go/vt/vtgate/logstats/logstats_test.go @@ -185,6 +185,28 @@ func TestLogStatsRowThreshold(t *testing.T) { assert.Empty(t, got) } +func TestLogStatsTimeThreshold(t *testing.T) { + logStats := NewLogStats(context.Background(), "test", "sql1 /* LOG_THIS_QUERY */", "", + map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}, streamlog.NewQueryLogConfigForTest()) + // Query total time is 1 second and 1234 nanosecond + logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC) + logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC) + params := map[string][]string{"full": {}} + + got := testFormat(t, logStats, params) + want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\t0.000000\t0.000000\t\"\"\n" + assert.Equal(t, want, got) + + got = testFormat(t, logStats, params) + want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\t0.000000\t0.000000\t\"\"\n" + assert.Equal(t, want, got) + + // Set Query threshold more than query duration: 1 second and 1234 nanosecond + logStats.Config.TimeThreshold = 2 * 1024 * 1024 * 1024 + got = testFormat(t, logStats, params) + assert.Empty(t, got) +} + func TestLogStatsContextHTML(t *testing.T) { html := "HtmlContext" callInfo := &fakecallinfo.FakeCallInfo{ diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats.go b/go/vt/vttablet/tabletserver/tabletenv/logstats.go index 40156f3bcdc..b4c3099552e 100644 --- a/go/vt/vttablet/tabletserver/tabletenv/logstats.go +++ b/go/vt/vttablet/tabletserver/tabletenv/logstats.go @@ -180,7 +180,7 @@ func (stats *LogStats) CallInfo() (string, string) { // Logf formats the log record to the given writer, either as // tab-separated list of logged fields or as JSON. func (stats *LogStats) Logf(w io.Writer, params url.Values) error { - if !stats.Config.ShouldEmitLog(stats.OriginalSQL, uint64(stats.RowsAffected), uint64(len(stats.Rows)), stats.Error != nil) { + if !stats.Config.ShouldEmitLog(stats.OriginalSQL, uint64(stats.RowsAffected), uint64(len(stats.Rows)), stats.TotalTime(), stats.Error != nil) { return nil }