Add TTFB to all APIs and enable for responses without body (minio#20479)

Add TTFB for all requests in metrics-v3 in addition to the existing
GetObject. Also for the requests that do not return a body in the
response, calculate TTFB as the HTTP status code and the headers are
sent.

Author: vadmeste

cmd/http-stats.go

@@ -133,7 +133,7 @@ func (bh *bucketHTTPStats) updateHTTPStats(bucket, api string, w *xhttp.Response
 		bucketHTTPRequestsDuration.With(prometheus.Labels{
 			"api":    api,
 			"bucket": bucket,
-		}).Observe(w.TimeToFirstByte.Seconds())
+		}).Observe(w.TTFB().Seconds())
 	}
 
 	bh.Lock()
@@ -433,7 +433,7 @@ func (st *HTTPStats) updateStats(api string, w *xhttp.ResponseRecorder) {
 	st.totalS3Requests.Inc(api)
 
 	// Increment the prometheus http request response histogram with appropriate label
-	httpRequestsDuration.With(prometheus.Labels{"api": api}).Observe(w.TimeToFirstByte.Seconds())
+	httpRequestsDuration.With(prometheus.Labels{"api": api}).Observe(w.TTFB().Seconds())
 
 	code := w.StatusCode
 

cmd/http-tracer.go

@@ -164,7 +164,7 @@ func httpTracerMiddleware(h http.Handler) http.Handler {
 					Latency:         reqEndTime.Sub(respRecorder.StartTime),
 					InputBytes:      inputBytes,
 					OutputBytes:     respRecorder.Size(),
-					TimeToFirstByte: respRecorder.TimeToFirstByte,
+					TimeToFirstByte: respRecorder.TTFB(),
 				},
 			},
 		}

cmd/metrics-v3-api.go

@@ -129,7 +129,7 @@ func loadAPIRequestsHTTPMetrics(ctx context.Context, m MetricValues, _ *metricsC
 // This is a `MetricsLoaderFn`.
 func loadAPIRequestsTTFBMetrics(ctx context.Context, m MetricValues, _ *metricsCache) error {
 	renameLabels := map[string]string{"api": "name"}
-	labelsFilter := map[string]set.StringSet{"api": set.CreateStringSet("GetObject")}
+	labelsFilter := map[string]set.StringSet{}
 	m.SetHistogram(apiRequestsTTFBSecondsDistribution, httpRequestsDuration, labelsFilter, renameLabels, nil,
 		"type", "s3")
 	return nil
@@ -217,7 +217,7 @@ func loadBucketAPIHTTPMetrics(ctx context.Context, m MetricValues, _ *metricsCac
 // This is a `MetricsLoaderFn`.
 func loadBucketAPITTFBMetrics(ctx context.Context, m MetricValues, _ *metricsCache, buckets []string) error {
 	renameLabels := map[string]string{"api": "name"}
-	labelsFilter := map[string]set.StringSet{"api": set.CreateStringSet("GetObject")}
+	labelsFilter := map[string]set.StringSet{}
 	m.SetHistogram(apiRequestsTTFBSecondsDistribution, bucketHTTPRequestsDuration, labelsFilter, renameLabels,
 		buckets, "type", "s3")
 	return nil

internal/http/response-recorder.go

@@ -41,8 +41,10 @@ type ResponseRecorder struct {
 	// Log body of all responses
 	LogAllBody bool
 
-	TimeToFirstByte time.Duration
-	StartTime       time.Time
+	ttfbHeader time.Duration
+	ttfbBody   time.Duration
+
+	StartTime time.Time
 	// number of bytes written
 	bytesWritten int
 	// number of bytes of response headers written
@@ -63,6 +65,15 @@ func (lrw *ResponseRecorder) Hijack() (net.Conn, *bufio.ReadWriter, error) {
 	return hj.Hijack()
 }
 
+// TTFB of the request - this function needs to be called
+// when the request is finished to provide accurate data
+func (lrw *ResponseRecorder) TTFB() time.Duration {
+	if lrw.ttfbBody != 0 {
+		return lrw.ttfbBody
+	}
+	return lrw.ttfbHeader
+}
+
 // NewResponseRecorder - returns a wrapped response writer to trap
 // http status codes for auditing purposes.
 func NewResponseRecorder(w http.ResponseWriter) *ResponseRecorder {
@@ -97,8 +108,8 @@ func (lrw *ResponseRecorder) Write(p []byte) (int, error) {
 	}
 	n, err := lrw.ResponseWriter.Write(p)
 	lrw.bytesWritten += n
-	if lrw.TimeToFirstByte == 0 {
-		lrw.TimeToFirstByte = time.Now().UTC().Sub(lrw.StartTime)
+	if lrw.ttfbBody == 0 {
+		lrw.ttfbBody = time.Now().UTC().Sub(lrw.StartTime)
 	}
 
 	if (lrw.LogErrBody && lrw.StatusCode >= http.StatusBadRequest) || lrw.LogAllBody {
@@ -159,6 +170,7 @@ func (lrw *ResponseRecorder) Body() []byte {
 // WriteHeader - writes http status code
 func (lrw *ResponseRecorder) WriteHeader(code int) {
 	if !lrw.headersLogged {
+		lrw.ttfbHeader = time.Now().UTC().Sub(lrw.StartTime)
 		lrw.StatusCode = code
 		lrw.writeHeaders(&lrw.headers, code, lrw.ResponseWriter.Header())
 		lrw.headersLogged = true

internal/logger/audit.go

@@ -100,7 +100,7 @@ func AuditLog(ctx context.Context, w http.ResponseWriter, r *http.Request, reqCl
 			outputBytes = int64(tc.ResponseRecorder.Size())
 			headerBytes = int64(tc.ResponseRecorder.HeaderSize())
 			timeToResponse = time.Now().UTC().Sub(tc.ResponseRecorder.StartTime)
-			timeToFirstByte = tc.ResponseRecorder.TimeToFirstByte
+			timeToFirstByte = tc.ResponseRecorder.TTFB()
 		}
 
 		entry.AccessKey = reqInfo.Cred.AccessKey