I have an nginx used mainly as a reverse proxy for a couple of upstream services. This nginx has a simple endpoint used for health checks:

location /ping { return 200 '{"ping":"successful"}'; }

The problem I'm having is that this ping takes too long to be responded:

$ cat /proc/loadavg; date ; httpstat localhost/ping?foo=bar
2.93 1.98 1.94 8/433 16725
Thu Jul 15 15:25:08 UTC 2021
Connected to 127.0.0.1:80 from 127.0.0.1:42946

HTTP/1.1 200 OK
Date: Thu, 15 Jul 2021 15:26:24 GMT
X-Request-ID: b8d276b0b3828113cfee3bf2daa01293

DNS Lookup TCP Connection Server Processing Content Transfer
[ 4ms | 0ms | 76032ms | 0ms ]
namelookup:4ms
connect:4ms
starttransfer:76036ms
total:76036ms

That ^ is telling me that the average load is low at the time of the request (2.93 the 1m average load for an 8-core server is ok)

Curl/httpstat initiated the request at 15:25:08 and response was obtained 15:26:24. Connection was stablished fast, request sent, then it took 76s for the server to respond.

If I look at the access log for this ping I see "req_time":"0.000" (this is the $request_time variable).

{"t":"2021-07-15T15:26:24+00:00","id":"b8d276b0b3828113cfee3bf2daa01293","cid":"18581172","pid":"13631","host":"localhost","req":"GET /ping?foo=bar HTTP/1.1","scheme":"","status":"200","req_time":"0.000","body_sent":"21","bytes_sent":"373","content_length":"","request_length":"85","stats":"","upstream":{"status":"","sent":"","received":"","addr":"","conn_time":"","resp_time":""},"client":{"id":"#","agent":"curl/7.58.0","addr":",127.0.0.1:42946"},"limit_status":{"conn":"","req":""}}

This is the access log format in case anybody wonders what are the rest of the values:

'{"t":"$time_iso8601","id":"$ring_request_id","cid":"$connection","pid":"$pid","host":"$http_host","req":"$request","scheme":"$http_x_forwarded_proto","status":"$status","req_time":"$request_time","body_sent":"$body_bytes_sent","bytes_sent":"$bytes_sent","content_length":"$content_length","request_length":"$request_length","stats":"$location_tag","upstream":{"status":"$upstream_status","sent":"$upstream_bytes_sent","received":"$upstream_bytes_received","addr":"$upstream_addr","conn_time":"$upstream_connect_time","resp_time":"$upstream_response_time"},"client":{"id":"$http_x_auth_appid$http_x_ringdevicetype#$remote_user$http_x_auth_userid","agent":"$http_user_agent","addr":"$http_x_forwarded_for,$remote_addr:$remote_port"},"limit_status":{"conn":"$limit_conn_status","req":"$limit_req_status"}}';

My question is: where could nginx have spent these 76s if the request just took 0s to be processed and responded?

Something special to mention is that the server is timing out a lof of connections with the upstreams at that moment as well: we see a lot of upstream timed out (110: Connection timed out) while reading response header from upstream and upstream server temporarily disabled while reading response header from upstream.

So, these two are related, what I can't see is why upstream timeouts would lead to a /ping taking 76s to be attended and responded when both cpu and load are low/acceptable.

Any idea?
Thanks
Alejandro