From df53182aa49cbc5a70cb73e446aa84c27b82ce01 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kamil=20Trzci=C5=84ski?= Date: Mon, 12 Oct 2020 15:29:50 +0200 Subject: [PATCH 1/4] Add time to the first byte --- log/access_logger.go | 7 +++++++ log/access_logger_fields.go | 4 ++++ 2 files changed, 11 insertions(+) diff --git a/log/access_logger.go b/log/access_logger.go index b131ed24..d3b8691d 100644 --- a/log/access_logger.go +++ b/log/access_logger.go @@ -57,6 +57,7 @@ type loggingResponseWriter struct { wroteHeader bool written int64 started time.Time + ttfb time.Duration config *accessLoggerConfig contentType string } @@ -82,6 +83,8 @@ func (l *loggingResponseWriter) WriteHeader(status int) { l.wroteHeader = true l.status = status l.contentType = l.Header().Get("Content-Type") + t.ttfb = time.Since(l.started) + l.rw.WriteHeader(status) } @@ -149,6 +152,10 @@ func (l *loggingResponseWriter) accessLogFields(r *http.Request) logrus.Fields { fields[requestDurationField] = int64(duration / time.Millisecond) } + if fieldsBitMask&RequestTTFB != 0 && t.ttfb > 0 { + fields[requestTTFBField] = t.ttfb.Seconds() + } + if fieldsBitMask&System != 0 { fields[systemField] = "http" } diff --git a/log/access_logger_fields.go b/log/access_logger_fields.go index 39765dad..4505b987 100644 --- a/log/access_logger_fields.go +++ b/log/access_logger_fields.go @@ -45,6 +45,9 @@ const ( // HTTPResponseContentType field will record the response content-type in the access log. HTTPResponseContentType + + // RequestTTFB field will record the time to the first byte in the access log. + RequestTTFB ) const defaultEnabledFields = ^AccessLogField(0) // By default, all fields are enabled @@ -63,6 +66,7 @@ const ( httpRequestReferrerField = "referrer" // ESC: http.request.referrer httpUserAgentField = "user_agent" // ESC: user_agent.original requestDurationField = "duration_ms" // ESC: no mapping + requestTTFBField = "ttfb_s" // ESC: no mapping systemField = "system" // ESC: no mapping httpResponseContentTypeField = "content_type" // ESC: no mapping ) -- GitLab From 811dfde5c386adffe8eb591155dc40e0a5f89f33 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kamil=20Trzci=C5=84ski?= Date: Mon, 12 Oct 2020 15:35:38 +0200 Subject: [PATCH 2/4] Add time to the first byte --- log/access_logger.go | 6 +++--- log/access_logger_fields.go | 2 +- log/access_logger_test.go | 7 +++++++ 3 files changed, 11 insertions(+), 4 deletions(-) diff --git a/log/access_logger.go b/log/access_logger.go index d3b8691d..a74af2fb 100644 --- a/log/access_logger.go +++ b/log/access_logger.go @@ -83,7 +83,7 @@ func (l *loggingResponseWriter) WriteHeader(status int) { l.wroteHeader = true l.status = status l.contentType = l.Header().Get("Content-Type") - t.ttfb = time.Since(l.started) + l.ttfb = time.Since(l.started) l.rw.WriteHeader(status) } @@ -152,8 +152,8 @@ func (l *loggingResponseWriter) accessLogFields(r *http.Request) logrus.Fields { fields[requestDurationField] = int64(duration / time.Millisecond) } - if fieldsBitMask&RequestTTFB != 0 && t.ttfb > 0 { - fields[requestTTFBField] = t.ttfb.Seconds() + if fieldsBitMask&RequestTTFB != 0 && l.ttfb > 0 { + fields[requestTTFBField] = l.ttfb.Milliseconds() } if fieldsBitMask&System != 0 { diff --git a/log/access_logger_fields.go b/log/access_logger_fields.go index 4505b987..b6c39af1 100644 --- a/log/access_logger_fields.go +++ b/log/access_logger_fields.go @@ -66,7 +66,7 @@ const ( httpRequestReferrerField = "referrer" // ESC: http.request.referrer httpUserAgentField = "user_agent" // ESC: user_agent.original requestDurationField = "duration_ms" // ESC: no mapping - requestTTFBField = "ttfb_s" // ESC: no mapping + requestTTFBField = "ttfb_ms" // ESC: no mapping systemField = "system" // ESC: no mapping httpResponseContentTypeField = "content_type" // ESC: no mapping ) diff --git a/log/access_logger_test.go b/log/access_logger_test.go index 9268e50a..db4193b2 100644 --- a/log/access_logger_test.go +++ b/log/access_logger_test.go @@ -114,6 +114,13 @@ func TestAccessLogger(t *testing.T) { `\bcontent_type=text/plain`, }, }, + { + name: "time to the first byte", + body: "hello", + logMatchers: []string{ + `\bttfb_ms=\d+`, + }, + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { -- GitLab From a16e893d493229fc388999e6e7db632503746720 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kamil=20Trzci=C5=84ski?= Date: Mon, 12 Oct 2020 15:37:06 +0200 Subject: [PATCH 3/4] TTFB measure since a first byte of the response --- log/access_logger.go | 1 - log/access_logger_fields.go | 4 +++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/log/access_logger.go b/log/access_logger.go index a74af2fb..6a9439ea 100644 --- a/log/access_logger.go +++ b/log/access_logger.go @@ -83,7 +83,6 @@ func (l *loggingResponseWriter) WriteHeader(status int) { l.wroteHeader = true l.status = status l.contentType = l.Header().Get("Content-Type") - l.ttfb = time.Since(l.started) l.rw.WriteHeader(status) } diff --git a/log/access_logger_fields.go b/log/access_logger_fields.go index b6c39af1..f542353d 100644 --- a/log/access_logger_fields.go +++ b/log/access_logger_fields.go @@ -46,7 +46,9 @@ const ( // HTTPResponseContentType field will record the response content-type in the access log. HTTPResponseContentType - // RequestTTFB field will record the time to the first byte in the access log. + // RequestTTFB field will record the time to the first byte being written (HTTP Header effectively) + // in the access log. Time is recorded before an actual Write happens to ensure that this metric + // is not affected by a slow client receiving data. RequestTTFB ) -- GitLab From 02596b9ca11cfb936de5638c37fd09f6aa4d1b24 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kamil=20Trzci=C5=84ski?= Date: Tue, 13 Oct 2020 17:23:12 +0200 Subject: [PATCH 4/4] Improve timings and descriptions --- log/access_logger.go | 1 + log/access_logger_test.go | 68 ++++++++++++++++++++++++++++++++------- 2 files changed, 57 insertions(+), 12 deletions(-) diff --git a/log/access_logger.go b/log/access_logger.go index 6a9439ea..a74af2fb 100644 --- a/log/access_logger.go +++ b/log/access_logger.go @@ -83,6 +83,7 @@ func (l *loggingResponseWriter) WriteHeader(status int) { l.wroteHeader = true l.status = status l.contentType = l.Header().Get("Content-Type") + l.ttfb = time.Since(l.started) l.rw.WriteHeader(status) } diff --git a/log/access_logger_test.go b/log/access_logger_test.go index db4193b2..316240aa 100644 --- a/log/access_logger_test.go +++ b/log/access_logger_test.go @@ -7,6 +7,7 @@ import ( "net/http" "net/http/httptest" "testing" + "time" "github.com/stretchr/testify/require" ) @@ -20,6 +21,7 @@ func TestAccessLogger(t *testing.T) { options []AccessLoggerOption requestHeaders map[string]string responseHeaders map[string]string + handler http.Handler }{ { name: "trivial", @@ -116,11 +118,50 @@ func TestAccessLogger(t *testing.T) { }, { name: "time to the first byte", - body: "hello", + body: "ok", logMatchers: []string{ `\bttfb_ms=\d+`, }, }, + { + name: "time to the first byte, with long delay", + body: "yo", + logMatchers: []string{ + // we expect the delay to be around `10ms` + `\bttfb_ms=1\d\b`, + }, + handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(10 * time.Millisecond) + fmt.Fprint(w, "yo") + }), + }, + { + name: "time to the first byte, with a slow data transfer", + body: "yo", + logMatchers: []string{ + // we expect the delay to be lower than `10ms` + `\bttfb_ms=\d\b`, + }, + handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + time.Sleep(10 * time.Millisecond) + fmt.Fprint(w, "yo") + }), + }, + { + name: "time to the first byte, with a long processing and slow data transfer", + body: "yo", + logMatchers: []string{ + // we expect the delay to be around `10ms` + `\bttfb_ms=1\d\b`, + }, + handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(10 * time.Millisecond) + w.WriteHeader(http.StatusInternalServerError) + time.Sleep(20 * time.Millisecond) + fmt.Fprint(w, "yo") + }), + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { @@ -130,17 +171,20 @@ func TestAccessLogger(t *testing.T) { _, err := Initialize(WithLogger(logger), WithWriter(buf)) require.NoError(t, err) - var handler http.Handler - handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - for k, v := range tt.responseHeaders { - w.Header().Add(k, v) - } - // This if-statement provides test coverage for the case where the - // handler never calls Write or WriteHeader. - if len(tt.body) > 0 { - fmt.Fprint(w, tt.body) - } - }) + handler := tt.handler + + if handler == nil { + handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + for k, v := range tt.responseHeaders { + w.Header().Add(k, v) + } + // This if-statement provides test coverage for the case where the + // handler never calls Write or WriteHeader. + if len(tt.body) > 0 { + fmt.Fprint(w, tt.body) + } + }) + } opts := []AccessLoggerOption{WithAccessLogger(logger)} opts = append(opts, tt.options...) -- GitLab