Improve performance of http access logs

Fixes:
* Don't call LogArgs if log will not be written due low verbosity
* Create separate slice for hijacked to avoid append on main path
* Shorten log message as this log is to common to be verbose

name           old time/op    new time/op    delta
WithLogging-4    4.95µs ± 3%    3.52µs ± 1%  -28.80%  (p=0.000 n=10+8)

name           old alloc/op   new alloc/op   delta
WithLogging-4    2.93kB ± 0%    1.22kB ± 0%  -58.45%  (p=0.000 n=10+9)

name           old allocs/op  new allocs/op  delta
WithLogging-4      32.0 ± 0%      20.0 ± 0%  -37.50%  (p=0.000 n=10+10)
This commit is contained in:
Marek Siarkowicz 2020-06-23 13:56:01 +02:00
parent db8a88721e
commit 303e1c1922

View File

@ -85,7 +85,9 @@ func WithLogging(handler http.Handler, pred StacktracePred) http.Handler {
rl := newLogged(req, w).StacktraceWhen(pred)
req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl))
defer func() { klog.V(3).InfoS("Received HTTP request", rl.LogArgs()...) }()
if klog.V(3).Enabled() {
defer func() { klog.InfoS("HTTP", rl.LogArgs()...) }()
}
handler.ServeHTTP(rl, req)
})
}
@ -155,24 +157,30 @@ func (rl *respLogger) Addf(format string, data ...interface{}) {
func (rl *respLogger) LogArgs() []interface{} {
latency := time.Since(rl.startTime)
if rl.hijacked {
return []interface{}{
"verb", rl.req.Method,
"URI", rl.req.RequestURI,
"latency", latency,
"userAgent", rl.req.UserAgent(),
"srcIP", rl.req.RemoteAddr,
"hijacked", true,
}
}
args := []interface{}{
"verb", rl.req.Method,
"URI", rl.req.RequestURI,
"latency", latency,
"userAgent", rl.req.UserAgent(),
"srcIP", rl.req.RemoteAddr,
"resp", rl.status,
}
if len(rl.statusStack) > 0 {
args = append(args, "statusStack", rl.statusStack)
}
if rl.hijacked {
args = append(args, "hijacked", true)
} else {
args = append(args, "resp", rl.status)
if len(rl.statusStack) > 0 {
args = append(args, "statusStack", rl.statusStack)
}
if len(rl.addedInfo) > 0 {
args = append(args, "addedInfo", rl.addedInfo)
}
if len(rl.addedInfo) > 0 {
args = append(args, "addedInfo", rl.addedInfo)
}
return args
}