Update latency timing headers

[itskingori]

Nginx provides a number of built‑in timing variables that we can use to investigate latency. All are measured in seconds with millisecond resolution. These are:

• $request_time – Full request time, starting when Nginx reads the first byte from the client and ending when Nginx sends the last byte of the response body.
• $upstream_connect_time – Time spent establishing a connection with an upstream server.
• $upstream_header_time – Time between establishing a connection to an upstream server and receiving the first byte of the response header.
• $upstream_response_time – Time between establishing a connection to an upstream server and receiving the last byte of the response body.

Another way to put it ...

Variable	Start Time	End Time
$upstream_connect_time	Before Nginx establishes TCP connection with upstream server	Before Nginx sends HTTP request to upstream server
$upstream_header_time	Before Nginx establishes TCP connection with upstream server	After Nginx receives and processes headers in HTTP response from upstream server
$upstream_response_time	Before Nginx establishes TCP connection with upstream server	After Nginx receives and processes HTTP response from upstream server

Testing

Build and run it ...

$ docker-nginx-proxy git:(update_latency_headers) docker-compose build          
[+] Building 2.8s (13/13) FINISHED                                                                                                                                               docker:desktop-linux
 => [proxy internal] load build definition from Dockerfile                                                                                                                                       0.0s
 => => transferring dockerfile: 1.62kB                                                                                                                                                           0.0s
 => [proxy internal] load .dockerignore                                                                                                                                                          0.0s
 => => transferring context: 136B                                                                                                                                                                0.0s
 => [proxy internal] load metadata for docker.io/zappi/nginx:1.25.3                                                                                                                              2.7s
 => [proxy builder 1/6] FROM docker.io/zappi/nginx:1.25.3@sha256:cc2182d1db65e056cd873b8e170b86516fe39623009a0567bca4fc3f69368321                                                                0.0s
 => [proxy internal] load build context                                                                                                                                                          0.0s
 => => transferring context: 5.90kB                                                                                                                                                              0.0s
 => CACHED [proxy builder 2/6] RUN apt-get update -y &&     apt-get install --no-install-recommends -y       build-essential       ca-certificates       libpcre3       libpcre3-dev       wget  0.0s
 => CACHED [proxy builder 3/6] WORKDIR /usr/src/                                                                                                                                                 0.0s
 => CACHED [proxy builder 4/6] RUN wget "http://nginx.org/download/nginx-1.25.3.tar.gz" &&     echo "64c5b975ca287939e828303fa857d22f142b251f17808dfe41733512d9cded86 *nginx-1.25.3.tar.gz" | s  0.0s
 => CACHED [proxy builder 5/6] RUN wget "https://github.com/openresty/headers-more-nginx-module/archive/v0.37.tar.gz" &&     echo "cf6e169d6b350c06d0c730b0eaf4973394026ad40094cddd3b3a5b346577  0.0s
 => CACHED [proxy builder 6/6] RUN cd nginx &&     ./configure --with-compat --add-dynamic-module=/usr/src/headers-more &&     make modules                                                      0.0s
 => CACHED [proxy stage-1 2/3] COPY --from=builder /usr/src/nginx/objs/*_module.so /etc/nginx/modules/                                                                                           0.0s
 => [proxy stage-1 3/3] COPY ./config/ /etc/nginx/                                                                                                                                               0.0s
 => [proxy] exporting to image                                                                                                                                                                   0.0s
 => => exporting layers                                                                                                                                                                          0.0s
 => => writing image sha256:895a679fb6ba96818e5b242ac84747e35f89f89a1fda6dfd5fb163233f5575d9                                                                                                     0.0s
 => => naming to docker.io/library/nginx-proxy:latest                                                                                                                                            0.0s

$ docker-nginx-proxy git:(update_latency_headers) docker-compose up -d
[+] Running 4/4
 ✔ Network docker-nginx-proxy_local                                                                                                                     Cr...                                    0.0s 
 ✔ Container docker-nginx-proxy-app-1                                                                                                                   Started                                  0.0s 
 ✔ Container docker-nginx-proxy-proxy-1                                                                                                                 Started                                  0.0s 

$ docker-compose ps
NAME                         IMAGE                COMMAND                  SERVICE   CREATED          STATUS          PORTS
docker-nginx-proxy-app-1     caddy:2.1.1-alpine   "caddy run --config …"   app       2 minutes ago    Up 11 seconds   80/tcp, 443/tcp, 2019/tcp
docker-nginx-proxy-proxy-1   nginx-proxy:latest   "/docker-entrypoint.…"   proxy     12 seconds ago   Up 11 seconds   80/tcp, 0.0.0.0:8080->8080/tcp

Hit the endpoint and check out the headers ...

$ curl -I  http://127.0.0.1:8080
HTTP/1.1 200 OK
Date: Thu, 18 Jan 2024 12:12:00 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 12226
Connection: keep-alive
Vary: Accept-Encoding
Accept-Ranges: bytes
Etag: "qlgk6n9fm"
Last-Modified: Thu, 17 Dec 2020 00:32:47 GMT
X-Robots-Tag: "noindex, nofollow"
X-Proxy-Backend-Connect-Time: 0.016
X-Proxy-Backend-Header-Time: 0.030
X-Proxy-Backend-Response-Time: -        <<< BLANKED BECAUSE NO RESPONSE SENT
X-Proxy-Request-Time: 0.030

Or you can check the logs ...

$ docker-compose logs proxy
proxy-1  | {"body_bytes_sent":"12226","host":"127.0.0.1","http_connection":"","http_referer":"","http_upgrade":"","http_user_agent":"curl/8.5.0","http_x_amzn_trace_id":"","http_x_forwarded_for":"","http_x_proxy_backend_connect_time":"0.002","http_x_proxy_backend_header_time":"0.007","http_x_proxy_backend_response_time":"0.009","proxy_connection":"","proxy_x_forwarded_port":"8080","proxy_x_forwarded_proto":"http","proxy_x_forwarded_ssl":"off","proxy_x_request_id":"6937b6d8eda772c06341f5fb85d812c9","remote_addr":"192.168.65.1","remote_user":"","request":"GET / HTTP/1.1","request_length":"77","request_time":"0.009","status": "200","time_iso8601":"2024-01-18T12:17:30+00:00"}

Related

• [SRE-3200] Expose $request_time as X-Server-Proxy-Time response header #15
• [SRE-3200] Add X-Proxy-Backend latency headers #16
• [SRE-3200] Log X-Proxy-Backend latency headers #17

References

• https://www.nginx.com/blog/using-nginx-logging-for-application-performance-monitoring/
• https://nginx.org/en/docs/http/ngx_http_upstream_module.html
• https://stackoverflow.com/questions/47270319/when-does-nginx-upstream-response-time-start-stop-specifically
• https://stackoverflow.com/questions/53978695/how-can-request-time-be-less-than-upstream-response-time-in-nginx
• https://serverfault.com/questions/1052317/why-is-upstream-response-time-in-add-header-a-hyphen

[Sithembiso-Mashinini]

We don't seem to have removed http_x_proxy_backend_response_time from logging fields 🤔 , here.

Secondly would we not want to keep the logging and http configuration consistent?
Meaning adding http_x_proxy_request_time.

[itskingori]

We don't seem to have removed http_x_proxy_backend_response_time from logging fields 🤔 , here.

Right, fixed in 977c88b.

Secondly would we not want to keep the logging and http configuration consistent? Meaning adding http_x_proxy_request_time.

Turns out we already do ...

docker-nginx-proxy/config/log.conf

Lines 26 to 28 in facd8e7

	'"request":"$request",'
	'"request_length":"$request_length",'
	'"request_time":"$request_time",'

[Sithembiso-Mashinini]

Ah thanks noted.