Welcome! Log In Create A New Profile

Advanced

Re: Sporadic long response times with upstream server

February 22, 2019 04:08PM
Thank you for your response, and for your patience with my delays. I have set up a tcpdump log, to see if this may be problem, but it'll have to wait until the next time the glitch happens to get a reading.

I have admin access to all servers, and host box. I had added timing logs consistent with (https://www.lunchbadger.com/blog/tra
cking-the-performance-of-express-js-routes-and-middleware) to the Node.js scripts. So the timeline for the requests seems to be:

2019-02-20T13:36:09.276959Z - Timestamp on load balancer access log (presumably, this timestamp is on receipt of the request, even though it logs the timing of of the response. The docs here (https://docs.aws.amazon.com/elasticloadbalancing/latest/application/load-balancer-access-logs.html#access-log-entry-format) seem to imply it is the end of the response, but this doesn't make much sense with the values provided)
[13:36:12.328]
[13:36:12.329]
[13:36:12.330]
[13:36:12.359] - Timestamps in Node.js logs. There are several logs entries during the fulfillment of the request, written live, so there is no cconfusion about whether the timestamp reflects the receipt of the request or end of the response. (For weird reasons I don't think are relevant, the third one is when the response is sent and the fourth one is when additional processing for the request is finished after the response is sent. Response back to Nginx is about 2ms; the additional 28 or 29 seconds is not relevant to Nginx)
20/Feb/2019:13:36:12 +0000 - Timestamp in Nginx describing the 3.052 second fulfillment time. Does not have millisecond resolution, but is consistent with the 3 second reported duration, the timestamp from the load balancer, and the timing information from Node.js.

The conclusion I have is that the delay is somewhere between the load balancer receiving the request and Nginx dispatching the request to Node.js, and Nginx is returning the response from Node.js immediately.

I do not have an explanation for why the timestamp on the load balancer seems to for the time of the receipt of the request, and not for the time of finished fulfillment.

All clients are actually the same kind of device. This application is being hosted by the manufacturer of an RTOS embedded system, and in support of features for clients running "in the wild". This endpoint is connected to every 15 minutes by clients running the new release of their OS, and the same client connected with no problems at 2019-02-20T13:21:08.136315Z, 15 minutes before. It's also why a single response of 3 seconds is being treated as a big deal, and why we have done so much to ensure fast response times. The feature can be deactivated, of course, but if it is running, fast response is very important.
Subject Author Posted

Sporadic long response times with upstream server

joncard February 20, 2019 07:57PM

Re: Sporadic long response times with upstream server

joncard February 21, 2019 02:51AM

Re: Sporadic long response times with upstream server

Peter Booth via nginx February 21, 2019 03:52AM

Re: Sporadic long response times with upstream server

joncard February 22, 2019 04:08PM

Re: Sporadic long response times with upstream server

Igor A. Ippolitov February 21, 2019 05:06AM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 73
Record Number of Users: 6 on February 13, 2018
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready