Client keep alive will make request times be reported as longer. My guess is that you didn't get keep-alive turned off for your test. I believe that for requests after the first that the request time is the sum of the keep-alive wait time plus the client request time. If that sum is greater than the client timeout, the client will get disconnected.
-Bryan On Mon, Mar 24, 2014 at 5:48 PM, Pedro Mata-Mouros < [email protected]> wrote: > 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. > > >
