Hi everyone,
I’ve been seeing abnormally high client request times, up to anywhere below
8000 ms (that’s when we timeout the client request). To cut the story short I
setup a backend that just replies a short string with the URL back at the
client, and on my own laptop started accessing it:
http://<domain_handled_by_haproxy>/url1,
http://<domain_handled_by_haproxy>/url2,
http://<domain_handled_by_haproxy>/url3…
*All* the responses literally *immediately* showed up on the browser:
helloworld_url1, helloworld_url2, helloworld_3…
But turns out that some of these requests are logged by HAProxy with abnormally
high Tq (and consequently Tt), that just don’t correspond to the experience I’m
seeing in my browser doing this test. An example with 10 requests I’ve done:
Mar 20 11:36:46 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2CC-0011
[20/Mar/2014:11:36:44.569] internet clientapp/lighty-3 1709/0/0/1/1710 200 200
- - ---- 1/1/0/1/0 0/0 {} "GET /url10 HTTP/1.1"
Mar 20 11:36:44 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2CA-0010
[20/Mar/2014:11:36:42.851] internet clientapp/lighty-2 1717/0/1/1/1719 200 199
- - ---- 1/1/0/1/0 0/0 {} "GET /url9 HTTP/1.1"
Mar 20 11:36:42 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2C8-000F
[20/Mar/2014:11:36:40.638] internet clientapp/lighty-3 2210/0/1/1/2212 200 199
- - ---- 1/1/0/1/0 0/0 {} "GET /url8 HTTP/1.1"
Mar 20 11:36:40 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2C6-000E
[20/Mar/2014:11:36:38.827] internet clientapp/lighty-2 1810/0/1/1/1812 200 199
- - ---- 1/1/0/1/0 0/0 {} "GET /url7 HTTP/1.1"
Mar 20 11:36:38 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2C5-000D
[20/Mar/2014:11:36:37.209] internet clientapp/lighty-3 1615/0/1/1/1617 200 199
- - ---- 1/1/0/1/0 0/0 {} "GET /url6 HTTP/1.1"
Mar 20 11:36:37 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2C3-000C
[20/Mar/2014:11:36:35.681] internet clientapp/lighty-2 1527/0/0/2/1529 200 199
- - ---- 1/1/0/1/0 0/0 {} "GET /url5 HTTP/1.1"
Mar 20 11:36:35 ha-2.proxy haproxy[9031]: <CLIENT_IP>:3959 2347-532AD2C3-000B
[20/Mar/2014:11:36:35.678] internet clientapp/lighty-3 1/0/0/2/3 200 199 - -
---- 1/1/0/1/0 0/0 {} "GET /url4 HTTP/1.1"
Mar 20 11:34:56 ha-2.proxy haproxy[9031]: <CLIENT_IP>:33161 2347-532AD25E-0009
[20/Mar/2014:11:34:54.581] internet clientapp/lighty-2 2349/0/0/2/2351 200 199
- - ---- 1/1/0/1/0 0/0 {} "GET /url3 HTTP/1.1"
Mar 20 11:34:54 ha-2.proxy haproxy[9031]: <CLIENT_IP>:33161 2347-532AD25E-0008
[20/Mar/2014:11:34:54.579] internet clientapp/lighty-3 0/0/0/2/2 200 199 - -
---- 1/1/0/1/0 0/0 {} "GET /url2 HTTP/1.1"
Mar 20 11:34:42 ha-2.proxy haproxy[9031]: <CLIENT_IP>:48491 2347-532AD252-0006
[20/Mar/2014:11:34:42.784] internet clientapp/lighty-2 0/0/0/2/2 200 199 - -
---- 1/1/0/1/0 0/0 {} "GET /url1 HTTP/1.1”
I can show you another one that logged 5588 ms:
Mar 20 11:41:36 ha-2.proxy haproxy[9031]: <CLIENT_IP>:55502 2347-532AD3EA-0014
[20/Mar/2014:11:41:30.974] internet clientapp/lighty-3 5588/0/1/1/5590 200 200
- - ---- 1/1/0/1/0 0/0 {} "GET /url12 HTTP/1.1”
I initially thought this could be something to do with keep alive between
client and HAProxy (wasn't sure how HAProxy would handle logging in this
situation) but I believe I turned off keep alive just before I ran these tests.
I was using "option http-server-close" in the defaults section and I commented
that out and put in "no option http-keep-alive”.
Any thoughts on this?
Thank you,
Pedro.
