From 3e3bb00265f8fa0dd8ff3d33ce901776fd689f32 Mon Sep 17 00:00:00 2001 From: Francis Lavoie Date: Mon, 11 Apr 2022 15:04:05 -0400 Subject: reverseproxy: Add `_ms` placeholders for proxy durations (#4666) * reverseproxy: Add `_ms` placeholders for proxy durations * Add http.request.duration_ms Also add comments, and change duration_sec to duration_ms * Add response.duration_ms for consistency * Add missing godoc comment Co-authored-by: Matthew Holt --- modules/caddyhttp/app.go | 1 + modules/caddyhttp/replacer.go | 3 +++ modules/caddyhttp/reverseproxy/reverseproxy.go | 6 ++++++ modules/caddyhttp/server.go | 1 + 4 files changed, 11 insertions(+) diff --git a/modules/caddyhttp/app.go b/modules/caddyhttp/app.go index d81f556..d886b88 100644 --- a/modules/caddyhttp/app.go +++ b/modules/caddyhttp/app.go @@ -49,6 +49,7 @@ func init() { // `{http.request.body}` | The request body (⚠️ inefficient; use only for debugging) // `{http.request.cookie.*}` | HTTP request cookie // `{http.request.duration}` | Time up to now spent handling the request (after decoding headers from client) +// `{http.request.duration_ms}` | Same as 'duration', but in milliseconds. // `{http.request.uuid}` | The request unique identifier // `{http.request.header.*}` | Specific request header field // `{http.request.host.labels.*}` | Request host labels (0-based from right); e.g. for foo.example.com: 0=com, 1=example, 2=foo diff --git a/modules/caddyhttp/replacer.go b/modules/caddyhttp/replacer.go index d3fa891..2fa6517 100644 --- a/modules/caddyhttp/replacer.go +++ b/modules/caddyhttp/replacer.go @@ -148,6 +148,9 @@ func addHTTPVarsToReplacer(repl *caddy.Replacer, req *http.Request, w http.Respo case "http.request.duration": start := GetVar(req.Context(), "start_time").(time.Time) return time.Since(start), true + case "http.request.duration_ms": + start := GetVar(req.Context(), "start_time").(time.Time) + return time.Since(start).Seconds() * 1e3, true // multiply seconds to preserve decimal (see #4666) case "http.request.uuid": id := GetVar(req.Context(), "uuid").(*requestID) return id.String(), true diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go index 2131a91..d69b04e 100644 --- a/modules/caddyhttp/reverseproxy/reverseproxy.go +++ b/modules/caddyhttp/reverseproxy/reverseproxy.go @@ -58,8 +58,11 @@ func init() { // `{http.reverse_proxy.upstream.max_requests}` | The maximum approximate number of requests allowed to the upstream // `{http.reverse_proxy.upstream.fails}` | The number of recent failed requests to the upstream // `{http.reverse_proxy.upstream.latency}` | How long it took the proxy upstream to write the response header. +// `{http.reverse_proxy.upstream.latency_ms}` | Same as 'latency', but in milliseconds. // `{http.reverse_proxy.upstream.duration}` | Time spent proxying to the upstream, including writing response body to client. +// `{http.reverse_proxy.upstream.duration_ms}` | Same as 'upstream.duration', but in milliseconds. // `{http.reverse_proxy.duration}` | Total time spent proxying, including selecting an upstream, retries, and writing response. +// `{http.reverse_proxy.duration_ms}` | Same as 'duration', but in milliseconds. type Handler struct { // Configures the method of transport for the proxy. A transport // is what performs the actual "round trip" to the backend. @@ -400,6 +403,7 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyht defer func() { // total proxying duration, including time spent on LB and retries repl.Set("http.reverse_proxy.duration", time.Since(start)) + repl.Set("http.reverse_proxy.duration_ms", time.Since(start).Seconds()*1e3) // multiply seconds to preserve decimal (see #4666) }() // in the proxy loop, each iteration is an attempt to proxy the request, @@ -724,6 +728,7 @@ func (h *Handler) reverseProxy(rw http.ResponseWriter, req *http.Request, repl * // duration until upstream wrote response headers (roundtrip duration) repl.Set("http.reverse_proxy.upstream.latency", duration) + repl.Set("http.reverse_proxy.upstream.latency_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666) // update circuit breaker on current conditions if di.Upstream.cb != nil { @@ -909,6 +914,7 @@ func (h Handler) finalizeResponse( // total duration spent proxying, including writing response body repl.Set("http.reverse_proxy.upstream.duration", time.Since(start)) + repl.Set("http.reverse_proxy.upstream.duration_ms", time.Since(start).Seconds()*1e3) if len(res.Trailer) == announcedTrailers { copyHeader(rw.Header(), res.Trailer) diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go index 6ab77df..a4a976f 100644 --- a/modules/caddyhttp/server.go +++ b/modules/caddyhttp/server.go @@ -190,6 +190,7 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { repl.Set("http.response.status", wrec.Status()) repl.Set("http.response.size", wrec.Size()) repl.Set("http.response.duration", duration) + repl.Set("http.response.duration_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666) logger := accLog if s.Logs != nil { -- cgit v1.2.3