Skip to content

Commit 2cf2af0

Browse files
HenryCaiHaiyingHenryCaiHaiying
authored
Add support for querylog-time-threshold duration flag for query logging (vitessio#18520) (#693)
Signed-off-by: Henry Cai <[email protected]>
1 parent d7c7e40 commit 2cf2af0

File tree

8 files changed

+134
-61
lines changed

8 files changed

+134
-61
lines changed

‎go/flags/endtoend/vtcombo.txt‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -282,6 +282,7 @@ Flags:
282282
--querylog-format string format for query logs ("text" or "json") (default "text")
283283
--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.
284284
--querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)
285+
--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.
285286
--queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables).
286287
--queryserver-config-annotate-queries prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type
287288
--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

‎go/flags/endtoend/vtgate.txt‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,7 @@ Flags:
179179
--querylog-format string format for query logs ("text" or "json") (default "text")
180180
--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.
181181
--querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)
182+
--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.
182183
--redact-debug-ui-queries redact full queries and bind variables from debug UI
183184
--remote_operation_timeout duration time to wait for a remote operation (default 15s)
184185
--retry-count int retry count (default 2)

‎go/flags/endtoend/vttablet.txt‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -272,6 +272,7 @@ Flags:
272272
--querylog-format string format for query logs ("text" or "json") (default "text")
273273
--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.
274274
--querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)
275+
--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.
275276
--queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables).
276277
--queryserver-config-annotate-queries prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type
277278
--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

‎go/streamlog/streamlog.go‎

Lines changed: 18 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ import (
2626
"os"
2727
"strings"
2828
"sync"
29+
"time"
2930

3031
"github.com/spf13/pflag"
3132

@@ -48,11 +49,12 @@ var (
4849
)
4950

5051
var (
51-
redactDebugUIQueries bool
52-
queryLogFilterTag string
53-
queryLogRowThreshold uint64
54-
queryLogFormat = "text"
55-
queryLogSampleRate float64
52+
redactDebugUIQueries bool
53+
queryLogFilterTag string
54+
queryLogRowThreshold uint64
55+
queryLogTimeThreshold time.Duration
56+
queryLogFormat = "text"
57+
queryLogSampleRate float64
5658
)
5759

5860
func GetRedactDebugUIQueries() bool {
@@ -71,6 +73,10 @@ func SetQueryLogRowThreshold(newQueryLogRowThreshold uint64) {
7173
queryLogRowThreshold = newQueryLogRowThreshold
7274
}
7375

76+
func SetQueryLogTimeThreshold(newQueryLogTimeThreshold time.Duration) {
77+
queryLogTimeThreshold = newQueryLogTimeThreshold
78+
}
79+
7480
func SetQueryLogSampleRate(sampleRate float64) {
7581
queryLogSampleRate = sampleRate
7682
}
@@ -102,6 +108,9 @@ func registerStreamLogFlags(fs *pflag.FlagSet) {
102108
// QueryLogRowThreshold only log queries returning or affecting this many rows
103109
fs.Uint64Var(&queryLogRowThreshold, "querylog-row-threshold", queryLogRowThreshold, "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.")
104110

111+
// QueryLogTimeThreshold only log queries with execution time over the time duration threshold
112+
fs.DurationVar(&queryLogTimeThreshold, "querylog-time-threshold", queryLogTimeThreshold, "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.")
113+
105114
// QueryLogSampleRate causes a sample of queries to be logged
106115
fs.Float64Var(&queryLogSampleRate, "querylog-sample-rate", queryLogSampleRate, "Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)")
107116
}
@@ -269,13 +278,16 @@ func shouldSampleQuery() bool {
269278

270279
// ShouldEmitLog returns whether the log with the given SQL query
271280
// should be emitted or filtered
272-
func ShouldEmitLog(sql string, rowsAffected, rowsReturned uint64) bool {
281+
func ShouldEmitLog(sql string, rowsAffected, rowsReturned uint64, totalTime time.Duration) bool {
273282
if shouldSampleQuery() {
274283
return true
275284
}
276285
if queryLogRowThreshold > max(rowsAffected, rowsReturned) && queryLogFilterTag == "" {
277286
return false
278287
}
288+
if queryLogTimeThreshold > totalTime && queryLogTimeThreshold > 0 && queryLogFilterTag == "" {
289+
return false
290+
}
279291
if queryLogFilterTag != "" {
280292
return strings.Contains(sql, queryLogFilterTag)
281293
}

‎go/streamlog/streamlog_test.go‎

Lines changed: 90 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -293,77 +293,114 @@ func TestShouldEmitLog(t *testing.T) {
293293
}()
294294

295295
tests := []struct {
296-
sql string
297-
qLogFilterTag string
298-
qLogRowThreshold uint64
299-
qLogSampleRate float64
300-
rowsAffected uint64
301-
rowsReturned uint64
302-
ok bool
296+
sql string
297+
qLogFilterTag string
298+
qLogRowThreshold uint64
299+
qLogTimeThreshold time.Duration
300+
qLogSampleRate float64
301+
rowsAffected uint64
302+
rowsReturned uint64
303+
totalTime time.Duration
304+
ok bool
303305
}{
304306
{
305-
sql: "queryLogThreshold smaller than affected and returned",
306-
qLogFilterTag: "",
307-
qLogRowThreshold: 2,
308-
qLogSampleRate: 0.0,
309-
rowsAffected: 7,
310-
rowsReturned: 7,
311-
ok: true,
307+
sql: "queryLogRowThreshold smaller than affected and returned",
308+
qLogFilterTag: "",
309+
qLogRowThreshold: 2,
310+
qLogTimeThreshold: 0,
311+
qLogSampleRate: 0.0,
312+
rowsAffected: 7,
313+
rowsReturned: 7,
314+
totalTime: 1000,
315+
ok: true,
312316
},
313317
{
314-
sql: "queryLogThreshold greater than affected and returned",
315-
qLogFilterTag: "",
316-
qLogRowThreshold: 27,
317-
qLogSampleRate: 0.0,
318-
rowsAffected: 7,
319-
rowsReturned: 17,
320-
ok: false,
318+
sql: "queryLogRowThreshold greater than affected and returned",
319+
qLogFilterTag: "",
320+
qLogRowThreshold: 27,
321+
qLogTimeThreshold: 0,
322+
qLogSampleRate: 0.0,
323+
rowsAffected: 7,
324+
rowsReturned: 17,
325+
totalTime: 1000,
326+
ok: false,
321327
},
322328
{
323-
sql: "this doesn't contains queryFilterTag: TAG",
324-
qLogFilterTag: "special tag",
325-
qLogRowThreshold: 10,
326-
qLogSampleRate: 0.0,
327-
rowsAffected: 7,
328-
rowsReturned: 17,
329-
ok: false,
329+
sql: "queryLogTimeThreshold smaller than total time and returned",
330+
qLogFilterTag: "",
331+
qLogRowThreshold: 0,
332+
qLogTimeThreshold: 10,
333+
qLogSampleRate: 0.0,
334+
rowsAffected: 7,
335+
rowsReturned: 7,
336+
totalTime: 1000,
337+
ok: true,
330338
},
331339
{
332-
sql: "this contains queryFilterTag: TAG",
333-
qLogFilterTag: "TAG",
334-
qLogRowThreshold: 0,
335-
qLogSampleRate: 0.0,
336-
rowsAffected: 7,
337-
rowsReturned: 17,
338-
ok: true,
340+
sql: "queryLogTimeThreshold greater than total time and returned",
341+
qLogFilterTag: "",
342+
qLogRowThreshold: 0,
343+
qLogTimeThreshold: 10000,
344+
qLogSampleRate: 0.0,
345+
rowsAffected: 7,
346+
rowsReturned: 17,
347+
totalTime: 1000,
348+
ok: false,
339349
},
340350
{
341-
sql: "this contains querySampleRate: 1.0",
342-
qLogFilterTag: "",
343-
qLogRowThreshold: 0,
344-
qLogSampleRate: 1.0,
345-
rowsAffected: 7,
346-
rowsReturned: 17,
347-
ok: true,
351+
sql: "this doesn't contains queryFilterTag: TAG",
352+
qLogFilterTag: "special tag",
353+
qLogRowThreshold: 10,
354+
qLogTimeThreshold: 0,
355+
qLogSampleRate: 0.0,
356+
rowsAffected: 7,
357+
rowsReturned: 17,
358+
totalTime: 1000,
359+
ok: false,
348360
},
349361
{
350-
sql: "this contains querySampleRate: 1.0 without expected queryFilterTag",
351-
qLogFilterTag: "TAG",
352-
qLogRowThreshold: 0,
353-
qLogSampleRate: 1.0,
354-
rowsAffected: 7,
355-
rowsReturned: 17,
356-
ok: true,
362+
sql: "this contains queryFilterTag: TAG",
363+
qLogFilterTag: "TAG",
364+
qLogRowThreshold: 0,
365+
qLogTimeThreshold: 0,
366+
qLogSampleRate: 0.0,
367+
rowsAffected: 7,
368+
rowsReturned: 17,
369+
totalTime: 1000,
370+
ok: true,
371+
},
372+
{
373+
sql: "this contains querySampleRate: 1.0",
374+
qLogFilterTag: "",
375+
qLogRowThreshold: 0,
376+
qLogTimeThreshold: 0,
377+
qLogSampleRate: 1.0,
378+
rowsAffected: 7,
379+
rowsReturned: 17,
380+
totalTime: 1000,
381+
ok: true,
382+
},
383+
{
384+
sql: "this contains querySampleRate: 1.0 without expected queryFilterTag",
385+
qLogFilterTag: "TAG",
386+
qLogRowThreshold: 0,
387+
qLogTimeThreshold: 0,
388+
qLogSampleRate: 1.0,
389+
rowsAffected: 7,
390+
rowsReturned: 17,
391+
totalTime: 1000,
392+
ok: true,
357393
},
358394
}
359395

360396
for _, tt := range tests {
361397
t.Run(tt.sql, func(t *testing.T) {
362398
SetQueryLogFilterTag(tt.qLogFilterTag)
363399
SetQueryLogRowThreshold(tt.qLogRowThreshold)
400+
SetQueryLogTimeThreshold(tt.qLogTimeThreshold)
364401
SetQueryLogSampleRate(tt.qLogSampleRate)
365402

366-
require.Equal(t, tt.ok, ShouldEmitLog(tt.sql, tt.rowsAffected, tt.rowsReturned))
403+
require.Equal(t, tt.ok, ShouldEmitLog(tt.sql, tt.rowsAffected, tt.rowsReturned, tt.totalTime))
367404
})
368405
}
369406
}
@@ -372,22 +409,22 @@ func BenchmarkShouldEmitLog(b *testing.B) {
372409
b.Run("default", func(b *testing.B) {
373410
SetQueryLogSampleRate(0.0)
374411
for i := 0; i < b.N; i++ {
375-
ShouldEmitLog("select * from test where user='someone'", 0, 123)
412+
ShouldEmitLog("select * from test where user='someone'", 0, 123, 0)
376413
}
377414
})
378415
b.Run("filter_tag", func(b *testing.B) {
379416
SetQueryLogSampleRate(0.0)
380417
SetQueryLogFilterTag("LOG_QUERY")
381418
defer SetQueryLogFilterTag("")
382419
for i := 0; i < b.N; i++ {
383-
ShouldEmitLog("select /* LOG_QUERY=1 */ * from test where user='someone'", 0, 123)
420+
ShouldEmitLog("select /* LOG_QUERY=1 */ * from test where user='someone'", 0, 123, 0)
384421
}
385422
})
386423
b.Run("50%_sample_rate", func(b *testing.B) {
387424
SetQueryLogSampleRate(0.5)
388425
defer SetQueryLogSampleRate(0.0)
389426
for i := 0; i < b.N; i++ {
390-
ShouldEmitLog("select * from test where user='someone'", 0, 123)
427+
ShouldEmitLog("select * from test where user='someone'", 0, 123, 0)
391428
}
392429
})
393430
}

‎go/vt/vtgate/logstats/logstats.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -124,7 +124,7 @@ func (stats *LogStats) RemoteAddrUsername() (string, string) {
124124
// Logf formats the log record to the given writer, either as
125125
// tab-separated list of logged fields or as JSON.
126126
func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
127-
if !streamlog.ShouldEmitLog(stats.SQL, stats.RowsAffected, stats.RowsReturned) {
127+
if !streamlog.ShouldEmitLog(stats.SQL, stats.RowsAffected, stats.RowsReturned, stats.TotalTime()) {
128128
return nil
129129
}
130130

‎go/vt/vtgate/logstats/logstats_test.go‎

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -192,6 +192,27 @@ func TestLogStatsRowThreshold(t *testing.T) {
192192
assert.Empty(t, got)
193193
}
194194

195+
func TestLogStatsTimeThreshold(t *testing.T) {
196+
logStats := NewLogStats(context.Background(), "test", "sql1 /* LOG_THIS_QUERY */", "", map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)})
197+
// Query total time is 1 second and 1234 nanosecond
198+
logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC)
199+
logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC)
200+
params := map[string][]string{"full": {}}
201+
202+
got := testFormat(t, logStats, params)
203+
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 */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
204+
assert.Equal(t, want, got)
205+
206+
got = testFormat(t, logStats, params)
207+
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 */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n"
208+
assert.Equal(t, want, got)
209+
210+
// Set Query threshold more than query duration: 1 second and 1234 nanosecond
211+
streamlog.SetQueryLogTimeThreshold(2 * 1024 * 1024 * 1024)
212+
got = testFormat(t, logStats, params)
213+
assert.Empty(t, got)
214+
}
215+
195216
func TestLogStatsContextHTML(t *testing.T) {
196217
html := "HtmlContext"
197218
callInfo := &fakecallinfo.FakeCallInfo{

‎go/vt/vttablet/tabletserver/tabletenv/logstats.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -177,7 +177,7 @@ func (stats *LogStats) CallInfo() (string, string) {
177177
// Logf formats the log record to the given writer, either as
178178
// tab-separated list of logged fields or as JSON.
179179
func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
180-
if !streamlog.ShouldEmitLog(stats.OriginalSQL, uint64(stats.RowsAffected), uint64(len(stats.Rows))) {
180+
if !streamlog.ShouldEmitLog(stats.OriginalSQL, uint64(stats.RowsAffected), uint64(len(stats.Rows)), stats.TotalTime()) {
181181
return nil
182182
}
183183

0 commit comments

Comments
 (0)