HTTP logs report very high processing time

Hello,
I am using haproxy 1.7 from debian (1.7.5-2~bpo8+1 2017/05/27) as a HTTP front server.

While reading the logs, I noticed that some requests are consistently reported with a high total processing time (around 10 seconds) despite being served very fast to the browser (20-40ms according to firefox network tab) :

[21/Aug/2018:10:33:16.964] HTTP-443~ bck_admin/PRD_20082 0/0/0/16/10000 200 169 - - ---- 67/16/6/7/0 0/0 "GET ...

I am talking about this part specifically :

TR '/' Tw '/' Tc '/' Tr '/' Ta*
0    /   0   /   0   /16  /10000

According to the documentation

Ta (here 10 seconds) is the total processing time in haproxy. Quoting the doc :

  • “Ta” is the time the request remained active in haproxy, which is the total time in milliseconds elapsed between the first byte of the request was received and the last byte of response was sent. It covers all possible processing except the handshake (see Th) and idle time (see Ti). There is one exception, if “option logasap” was specified, then the time counting stops at the moment the log is emitted. In this case, a ‘+’ sign is prepended before the value, indicating that the final one will be larger. See “Timers” below for more details.

What could cause the ‘Ta’ to be so high in haproxy while the total duration measured in the browser is only a few dozen of ms?

Further down in the docs, in the section 8.4. Timing events a few common cases are explained, including the following which I believe applies to your situation (it’s about a keep-alive sessions not closing right after the transaction):

If "Ta" is large even for small byte counts, it generally is because
neither the client nor the server decides to close the connection while
haproxy is running in tunnel mode and both have agreed on a keep-alive
connection mode. In order to solve this issue, it will be needed to specify
one of the HTTP options to manipulate keep-alive or close options on either
the frontend or the backend. Having the smallest possible 'Ta' or 'Tt' is
important when connection regulation is used with the "maxconn" option on
the servers, since no new connection will be sent to the server until
another one is released.

Hello,
Thanks for pointing out this part of the documentation, I missed it. That also explains why the total time is so close to 10 seconds.

Kind regards

5 posts were split to a new topic: Troubleshooting cL termination cause

Hi, I’m also facing this problem. Clients also feel random slow requests. I’ve tried to change keep-alive settings but it did not help. Random slow requests do not depend on server loads or so. The processing times are different so I cannot find what the limits are. Any more stuff to debug this issue?

From tcpdump I see that lag generating Haproxy server after client sends ACK.

cef::2 Haproxy server
c0de::b Client