Skip to content

Commit 6770eee

Browse files
arthurschreiberarthurschreiber
authored
Merge pull request #126 from github/arthur/backport-logstats
Backport querylog fixes
2 parents bfcb8fd + 7f6d941 commit 6770eee

File tree

7 files changed

+343
-131
lines changed

7 files changed

+343
-131
lines changed

‎go/logstats/logger.go

Lines changed: 217 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,217 @@
1+
/*
2+
Copyright 2024 The Vitess Authors.
3+
4+
Licensed under the Apache License, Version 2.0 (the "License");
5+
you may not use this file except in compliance with the License.
6+
You may obtain a copy of the License at
7+
8+
http://www.apache.org/licenses/LICENSE-2.0
9+
10+
Unless required by applicable law or agreed to in writing, software
11+
distributed under the License is distributed on an "AS IS" BASIS,
12+
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13+
See the License for the specific language governing permissions and
14+
limitations under the License.
15+
*/
16+
17+
package logstats
18+
19+
import (
20+
"io"
21+
"slices"
22+
"strconv"
23+
"strings"
24+
"sync"
25+
"time"
26+
27+
"vitess.io/vitess/go/hack"
28+
"vitess.io/vitess/go/sqltypes"
29+
querypb "vitess.io/vitess/go/vt/proto/query"
30+
)
31+
32+
type logbv struct {
33+
Name string
34+
BVar *querypb.BindVariable
35+
}
36+
37+
// Logger is a zero-allocation logger for logstats.
38+
// It can output logs as JSON or as plaintext, following the commonly used
39+
// logstats format that is shared between the tablets and the gates.
40+
type Logger struct {
41+
b []byte
42+
bvars []logbv
43+
n int
44+
json bool
45+
}
46+
47+
func sortBVars(sorted []logbv, bvars map[string]*querypb.BindVariable) []logbv {
48+
for k, bv := range bvars {
49+
sorted = append(sorted, logbv{k, bv})
50+
}
51+
slices.SortFunc(sorted, func(a, b logbv) int {
52+
return strings.Compare(a.Name, b.Name)
53+
})
54+
return sorted
55+
}
56+
57+
func (log *Logger) appendBVarsJSON(b []byte, bvars map[string]*querypb.BindVariable, full bool) []byte {
58+
log.bvars = sortBVars(log.bvars[:0], bvars)
59+
60+
b = append(b, '{')
61+
for i, bv := range log.bvars {
62+
if i > 0 {
63+
b = append(b, ',', ' ')
64+
}
65+
b = strconv.AppendQuote(b, bv.Name)
66+
b = append(b, `: {"type": `...)
67+
b = strconv.AppendQuote(b, querypb.Type_name[int32(bv.BVar.Type)])
68+
b = append(b, `, "value": `...)
69+
70+
if sqltypes.IsIntegral(bv.BVar.Type) || sqltypes.IsFloat(bv.BVar.Type) {
71+
b = append(b, bv.BVar.Value...)
72+
} else if bv.BVar.Type == sqltypes.Tuple {
73+
b = append(b, '"')
74+
b = strconv.AppendInt(b, int64(len(bv.BVar.Values)), 10)
75+
b = append(b, ` items"`...)
76+
} else {
77+
if full {
78+
b = strconv.AppendQuote(b, hack.String(bv.BVar.Value))
79+
} else {
80+
b = append(b, '"')
81+
b = strconv.AppendInt(b, int64(len(bv.BVar.Values)), 10)
82+
b = append(b, ` bytes"`...)
83+
}
84+
}
85+
b = append(b, '}')
86+
}
87+
return append(b, '}')
88+
}
89+
90+
func (log *Logger) Init(json bool) {
91+
log.n = 0
92+
log.json = json
93+
if log.json {
94+
log.b = append(log.b, '{')
95+
}
96+
}
97+
98+
func (log *Logger) Redacted() {
99+
log.String("[REDACTED]")
100+
}
101+
102+
func (log *Logger) Key(key string) {
103+
if log.json {
104+
if log.n > 0 {
105+
log.b = append(log.b, ',', ' ')
106+
}
107+
log.b = append(log.b, '"')
108+
log.b = append(log.b, key...)
109+
log.b = append(log.b, '"', ':', ' ')
110+
} else {
111+
if log.n > 0 {
112+
log.b = append(log.b, '\t')
113+
}
114+
}
115+
log.n++
116+
}
117+
118+
func (log *Logger) StringUnquoted(value string) {
119+
if log.json {
120+
log.b = strconv.AppendQuote(log.b, value)
121+
} else {
122+
log.b = append(log.b, value...)
123+
}
124+
}
125+
126+
func (log *Logger) TabTerminated() {
127+
if !log.json {
128+
log.b = append(log.b, '\t')
129+
}
130+
}
131+
132+
func (log *Logger) String(value string) {
133+
log.b = strconv.AppendQuote(log.b, value)
134+
}
135+
136+
func (log *Logger) StringSingleQuoted(value string) {
137+
if log.json {
138+
log.b = strconv.AppendQuote(log.b, value)
139+
} else {
140+
log.b = append(log.b, '\'')
141+
log.b = append(log.b, value...)
142+
log.b = append(log.b, '\'')
143+
}
144+
}
145+
146+
func (log *Logger) Time(t time.Time) {
147+
const timeFormat = "2006-01-02 15:04:05.000000"
148+
if log.json {
149+
log.b = append(log.b, '"')
150+
log.b = t.AppendFormat(log.b, timeFormat)
151+
log.b = append(log.b, '"')
152+
} else {
153+
log.b = t.AppendFormat(log.b, timeFormat)
154+
}
155+
}
156+
157+
func (log *Logger) Duration(t time.Duration) {
158+
log.b = strconv.AppendFloat(log.b, t.Seconds(), 'f', 6, 64)
159+
}
160+
161+
func (log *Logger) BindVariables(bvars map[string]*querypb.BindVariable, full bool) {
162+
// the bind variables are printed as JSON in text mode because the original
163+
// printing syntax, which was simply `fmt.Sprintf("%v")`, is not stable or
164+
// safe to parse
165+
log.b = log.appendBVarsJSON(log.b, bvars, full)
166+
}
167+
168+
func (log *Logger) Int(i int64) {
169+
log.b = strconv.AppendInt(log.b, i, 10)
170+
}
171+
172+
func (log *Logger) Uint(u uint64) {
173+
log.b = strconv.AppendUint(log.b, u, 10)
174+
}
175+
176+
func (log *Logger) Bool(b bool) {
177+
log.b = strconv.AppendBool(log.b, b)
178+
}
179+
180+
func (log *Logger) Strings(strs []string) {
181+
log.b = append(log.b, '[')
182+
for i, t := range strs {
183+
if i > 0 {
184+
log.b = append(log.b, ',')
185+
}
186+
log.b = strconv.AppendQuote(log.b, t)
187+
}
188+
log.b = append(log.b, ']')
189+
}
190+
191+
func (log *Logger) Flush(w io.Writer) (err error) {
192+
if log.json {
193+
log.b = append(log.b, '}')
194+
}
195+
log.b = append(log.b, '\n')
196+
_, err = w.Write(log.b)
197+
198+
clear(log.bvars)
199+
log.bvars = log.bvars[:0]
200+
log.b = log.b[:0]
201+
log.n = 0
202+
203+
loggerPool.Put(log)
204+
return err
205+
}
206+
207+
var loggerPool = sync.Pool{New: func() any {
208+
return &Logger{}
209+
}}
210+
211+
// NewLogger returns a new Logger instance to perform logstats logging.
212+
// The logger must be initialized with (*Logger).Init before usage and
213+
// flushed with (*Logger).Flush once all the key-values have been written
214+
// to it.
215+
func NewLogger() *Logger {
216+
return loggerPool.Get().(*Logger)
217+
}

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

Lines changed: 54 additions & 68 deletions
Original file line numberDiff line numberDiff line change
@@ -18,21 +18,16 @@ package logstats
1818

1919
import (
2020
"context"
21-
"encoding/json"
22-
"fmt"
2321
"io"
2422
"net/url"
2523
"time"
2624

2725
"github.com/google/safehtml"
2826

29-
"vitess.io/vitess/go/sqltypes"
27+
"vitess.io/vitess/go/logstats"
3028
"vitess.io/vitess/go/streamlog"
31-
"vitess.io/vitess/go/tb"
3229
"vitess.io/vitess/go/vt/callerid"
3330
"vitess.io/vitess/go/vt/callinfo"
34-
"vitess.io/vitess/go/vt/log"
35-
3631
querypb "vitess.io/vitess/go/vt/proto/query"
3732
)
3833

@@ -128,69 +123,60 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
128123
return nil
129124
}
130125

131-
// FormatBindVariables call might panic so we're going to catch it here
132-
// and print out the stack trace for debugging.
133-
defer func() {
134-
if x := recover(); x != nil {
135-
log.Errorf("Uncaught panic:\n%v\n%s", x, tb.Stack(4))
136-
}
137-
}()
138-
139-
formattedBindVars := "\"[REDACTED]\""
140-
if !streamlog.GetRedactDebugUIQueries() {
141-
_, fullBindParams := params["full"]
142-
formattedBindVars = sqltypes.FormatBindVariables(
143-
stats.BindVariables,
144-
fullBindParams,
145-
streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON,
146-
)
147-
}
148-
149-
// TODO: remove username here we fully enforce immediate caller id
126+
redacted := streamlog.GetRedactDebugUIQueries()
127+
_, fullBindParams := params["full"]
150128
remoteAddr, username := stats.RemoteAddrUsername()
151129

152-
var fmtString string
153-
switch streamlog.GetQueryLogFormat() {
154-
case streamlog.QueryLogFormatText:
155-
fmtString = "%v\t%v\t%v\t'%v'\t'%v'\t%v\t%v\t%.6f\t%.6f\t%.6f\t%.6f\t%v\t%q\t%v\t%v\t%v\t%q\t%q\t%q\t%v\t%v\t%q\n"
156-
case streamlog.QueryLogFormatJSON:
157-
fmtString = "{\"Method\": %q, \"RemoteAddr\": %q, \"Username\": %q, \"ImmediateCaller\": %q, \"Effective Caller\": %q, \"Start\": \"%v\", \"End\": \"%v\", \"TotalTime\": %.6f, \"PlanTime\": %v, \"ExecuteTime\": %v, \"CommitTime\": %v, \"StmtType\": %q, \"SQL\": %q, \"BindVars\": %v, \"ShardQueries\": %v, \"RowsAffected\": %v, \"Error\": %q, \"TabletType\": %q, \"SessionUUID\": %q, \"Cached Plan\": %v, \"TablesUsed\": %v, \"ActiveKeyspace\": %q}\n"
158-
}
159-
160-
tables := stats.TablesUsed
161-
if tables == nil {
162-
tables = []string{}
163-
}
164-
tablesUsed, marshalErr := json.Marshal(tables)
165-
if marshalErr != nil {
166-
return marshalErr
130+
log := logstats.NewLogger()
131+
log.Init(streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON)
132+
log.Key("Method")
133+
log.StringUnquoted(stats.Method)
134+
log.Key("RemoteAddr")
135+
log.StringUnquoted(remoteAddr)
136+
log.Key("Username")
137+
log.StringUnquoted(username)
138+
log.Key("ImmediateCaller")
139+
log.StringSingleQuoted(stats.ImmediateCaller())
140+
log.Key("Effective Caller")
141+
log.StringSingleQuoted(stats.EffectiveCaller())
142+
log.Key("Start")
143+
log.Time(stats.StartTime)
144+
log.Key("End")
145+
log.Time(stats.EndTime)
146+
log.Key("TotalTime")
147+
log.Duration(stats.TotalTime())
148+
log.Key("PlanTime")
149+
log.Duration(stats.PlanTime)
150+
log.Key("ExecuteTime")
151+
log.Duration(stats.ExecuteTime)
152+
log.Key("CommitTime")
153+
log.Duration(stats.CommitTime)
154+
log.Key("StmtType")
155+
log.StringUnquoted(stats.StmtType)
156+
log.Key("SQL")
157+
log.String(stats.SQL)
158+
log.Key("BindVars")
159+
if redacted {
160+
log.Redacted()
161+
} else {
162+
log.BindVariables(stats.BindVariables, fullBindParams)
167163
}
168-
_, err := fmt.Fprintf(
169-
w,
170-
fmtString,
171-
stats.Method,
172-
remoteAddr,
173-
username,
174-
stats.ImmediateCaller(),
175-
stats.EffectiveCaller(),
176-
stats.StartTime.Format("2006-01-02 15:04:05.000000"),
177-
stats.EndTime.Format("2006-01-02 15:04:05.000000"),
178-
stats.TotalTime().Seconds(),
179-
stats.PlanTime.Seconds(),
180-
stats.ExecuteTime.Seconds(),
181-
stats.CommitTime.Seconds(),
182-
stats.StmtType,
183-
stats.SQL,
184-
formattedBindVars,
185-
stats.ShardQueries,
186-
stats.RowsAffected,
187-
stats.ErrorStr(),
188-
stats.TabletType,
189-
stats.SessionUUID,
190-
stats.CachedPlan,
191-
string(tablesUsed),
192-
stats.ActiveKeyspace,
193-
)
194-
195-
return err
164+
log.Key("ShardQueries")
165+
log.Uint(stats.ShardQueries)
166+
log.Key("RowsAffected")
167+
log.Uint(stats.RowsAffected)
168+
log.Key("Error")
169+
log.String(stats.ErrorStr())
170+
log.Key("TabletType")
171+
log.String(stats.TabletType)
172+
log.Key("SessionUUID")
173+
log.String(stats.SessionUUID)
174+
log.Key("Cached Plan")
175+
log.Bool(stats.CachedPlan)
176+
log.Key("TablesUsed")
177+
log.Strings(stats.TablesUsed)
178+
log.Key("ActiveKeyspace")
179+
log.String(stats.ActiveKeyspace)
180+
181+
return log.Flush(w)
196182
}

0 commit comments

Comments
 (0)