Hi, Sorry if I missed this somewhere, is this any known behaviour on HAProxy? Please help pointing me in the right direction…
Thanks so much... Pedro. On 20 Mar 2014, at 11:47, Pedro Mata-Mouros <[email protected]> wrote: > 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. >
