Hi Bryan, Thanks for the insight. I’m still struggling with keep alive I guess… I did check the manual and I missed the last sentence: “Setting "option http-server-close" may display larger request times since "Tq" also measures the time spent waiting for additional requests.”
I have two questions about this then: 1. If using client keep alive “artificially” increases Tq for a given request, then that metric becomes somewhat useless… I’m now considering if I should actually just ditch keep alive completely… Is there any way that the request gets logged only with its proper Tq, instead of this additional time waiting for more requests to come in? I’m guessing that HAProxy nows exactly what time a particular request took to arrive and it could just log that? 2. Is server keep alive subject to the same behaviour? If so, this could be a bit more serious, since server side we would completely lose the capability to tell if a particular delay had just been due to this keep alive or some actual bottleneck on the backend. Any thoughts? Pedro. On 25 Mar 2014, at 05:55, Bryan Talbot <[email protected]> wrote: > 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. >> > >
