From 303e1c19225149868d735b5c876d8ca9d3e1b5c9 Mon Sep 17 00:00:00 2001
From: Marek Siarkowicz <siarkowicz@google.com>
Date: Tue, 23 Jun 2020 13:56:01 +0200
Subject: [PATCH] Improve performance of http access logs
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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)
---
 .../apiserver/pkg/server/httplog/httplog.go   | 30 ++++++++++++-------
 1 file changed, 19 insertions(+), 11 deletions(-)

diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
index a70c081c566..4cb5306672b 100644
--- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
+++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
@@ -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
 }