Additional logs because I feel my first mail maybe was not clear. TEST ONE: Making three curl from my linux directly to my backend, request going through haproxy
Command ran three times: curl -s -w 'Testing Website Response Time for :%{url_effective}\n\nLookup Time:\t\t%{time_namelookup}\nConnect Time:\t\t%{time_connect}\nPre-transfer Time:\t%{time_pretransfer}\nStart-transfer Time:\t%{time_starttransfer}\n\nTotal Time:\t\t%{time_total}\n' -o /dev/null [M](https://data.perfmaker.net/website/5be174f9a9403/tag.js)Y.BACKEND.COM Resulting curl logs, on the CLIENT SIDE: One : Lookup Time: 0,004153 Connect Time: 0,007826 Pre-transfer Time: 0,026363 Start-transfer Time: 0,031714 Total Time: 0,031744 Two: Lookup Time: 0,004148 Connect Time: 0,008135 Pre-transfer Time: 0,027791 Start-transfer Time: 0,033603 Total Time: 0,033636 Three: Lookup Time: 0,004149 Connect Time: 0,007733 Pre-transfer Time: 0,027447 Start-transfer Time: 0,034511 Total Time: 0,034572 Resulting haproxy logs, on the HAPROXY SIDE: One: Jul 2 10:53:19 sd-130610 haproxy[8513]: IP:PORT [02/Jul/2020:10:53:19.147] frontend backend 18/0/0/1/19 200 1993 - - --NI 377/377/0/1/0 0/0 "GET URL HTTP/1.1" Two: Jul 2 10:53:24 sd-130610 haproxy[8521]: IP:PORT [02/Jul/2020:10:53:24.684] frontend backend 19/0/0/2/21 200 1993 - - --NI 777/777/0/1/0 0/0 "GET URL HTTP/1.1" Three: Jul 2 10:53:32 sd-130610 haproxy[8522]: IP:PORT [02/Jul/2020:10:53:32.005] frontend backend 19/0/0/3/22 200 1993 - - --NI 1030/1030/0/1/0 0/0 "GET URL HTTP/1.1" Conclusions from this first curl requests test: Using curl, without trying to leverage keep-alive the results are coherent: the requests are fast, and stay similar. The small difference between haproxy total time and curl (client side) total time must be explained by the client-side DNS lookup + ssl client side compute time. We also see the cookie-status code in haproxy logs is always equals to "NI" because curl won't keep a cookie. TEST TWO: Now let's test using a client that leverages keepalive (or http-server-close, in my case): my web browser. We will make three requests too. Same URL, https too, only difference is my web browser uses keepalive by default, unlike curl. Web browser logged times: One: 39ms 11:05:12 Two: 10ms 11:05:29 Three: 9ms 11:05:39 Resulting haproxy logs, on the HAPROXY SIDE: One: Jul 2 11:05:12 sd-130610 haproxy[8514]: IP:PORT [02/Jul/2020:11:05:12.237] frontend backend 25/0/1/2/28 304 205 - - --NI 442/442/0/1/0 0/0 "GET URL HTTP/1.1" Two: Jul 2 11:05:29 sd-130610 haproxy[8514]: IP:PORT [02/Jul/2020:11:05:12.564] frontend backend 16967/0/0/2/16969 304 205 - - --VN 438/438/0/1/0 0/0 "GET URL HTTP/1.1" Three: Jul 2 11:05:39 sd-130610 haproxy[8514]: IP:PORT [02/Jul/2020:11:05:29.532] frontend backend 9648/0/0/4/9652 304 205 - - --VN 439/438/0/1/0 0/0 "GET URL HTTP/1.1" Conclusions from this web browser with keep alive requests test: We see that the first request is cookie status NI, we don't have a cookie yet and we open new tcp to haproxy. Then the other two are VN because we have cookie, and we're probably on the same TCP. We see that on the web-browser client side, the first request is 40 ms and the two other 10ms. This is coherent with the cookie-status. Then, on the haproxy side, the timers raise some question. The three timers logged are: - 11:05:12 25/0/1/2/28 - 11:05:29 16967/0/0/2/16969 - 11:05:39 9648/0/0/4/9652 The first request timer seems logical: it fast, 28ms, while the web browser client side said 39 ms, probably dns + ssl client side explain 11 ms difference, like for curl. For the other two requests we see 16969ms or 17 seconds and 9652ms or 10 seconds. But when I used my web browser, it was really fast (10ms and 9ms if you remember). Why is that ? Look at the time the requests were logged: there is (11:05:29 - 11:05:12 = 17) seconds between request one and request two. -> and the response time in ms is... 16969 -> approximately the same. That leads me to think the response time logged is counting from the opening of the TCP connection, and I can't know the real HTTP total time from HAPROXY logs right now. If any of you can tell me if this reasonning is correct, and how to obtain the HTTP total time and not the TCP total time, thanks big time. Paul ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ Le mercredi 1 juillet 2020 01:04, Paul Belloc <paul.bel...@protonmail.com> a écrit : > There is no overhead on the client side, only on the server time logged > > Sent from ProtonMail mobile > > -------- Original Message -------- > On Jun 30, 2020, 20:14, Илья Шипицин < chipits...@gmail.com> wrote: > >> is that https publicly available? can you say it's url ? >> >> otherwise, https might add some overhead. can you compare http <-- > https >> performance ? >> >> вт, 30 июн. 2020 г. в 21:32, Paul Belloc <paul.bel...@protonmail.com>: >> >>> it is https, I am not sure if ocsp stapling is enabled, how can I know ? >>> >>> ‐‐‐‐‐‐‐ Original Message ‐‐‐‐‐‐‐ >>> Le mardi 30 juin 2020 17:26, Илья Шипицин <chipits...@gmail.com> a écrit : >>> >>>> is it https ? is ocsp stapling enabled ? >>>> >>>> вт, 30 июн. 2020 г. в 20:24, Paul Belloc <paul.bel...@protonmail.com>: >>>> >>>>> Hello, I have been struggling on this issue for some time. >>>>> >>>>> I am trying to monitor the total request time in haproxy 1.7.5 HTTP logs. >>>>> My usecase is customers want to know the exact overhead of calling our >>>>> service. Sometime we have complaints that we are adding overhead, and we >>>>> know that our backend is fast, but we don't have the data to show the >>>>> total overhead from the last end user point of view. >>>>> >>>>> So I started saving all haproxy HTTP logs in an ELK cluster. >>>>> >>>>> At this point I must say: we use http-server-close and option httplog. >>>>> >>>>> What I see is the Tr and Tt seem to depend on the TCP opening timer. The >>>>> consequence is the logged time is good only for the first http request of >>>>> a tcp connection, i.e the request that has a NI cookie-status. >>>>> >>>>> To show that, I can show the difference between querying the backend >>>>> through haproxy using >>>>> >>>>> 1) CURL (no keep alive) >>>>> >>>>> Jun 30 17:18:23 19/0/0/3/22 200 1993 - - --NI 567/567/0/1/0 0/0 "GET >>>>> /website/5be174f9a9403/tag.js HTTP/1.1" >>>>> Jun 30 17:18:25 18/0/0/2/20 200 1993 - - --NI 449/449/0/1/0 0/0 "GET >>>>> /website/5be174f9a9403/tag.js HTTP/1.1" >>>>> Jun 30 17:18:28 19/0/0/2/21 200 1993 - - --NI 605/605/0/1/0 0/0 "GET >>>>> /website/5be174f9a9403/tag.js HTTP/1.1" >>>>> >>>>> We see that there is 1 seconds between my two first curls, and that the >>>>> Tr and Tt are similar. We see both are NI. Then there is 3 seconds >>>>> between the 2 last curls, but the Tr and Tt is still similar. >>>>> >>>>> 2) Web browser (keep-alive) >>>>> >>>>> Jun 30 17:14:49 190305/0/0/4/190309 304 205 - - --VN 963/963/0/0/0 0/0 >>>>> "GET /website/5be174f9a9403/tag.js HTTP/1.1" >>>>> Jun 30 17:14:51 1940/0/0/1/1941 304 205 - - --VN 966/966/0/1/0 0/0 "GET >>>>> /website/5be174f9a9403/tag.js HTTP/1.1" >>>>> >>>>> We see the first request has crazy Tt and Tr even if it was really fast >>>>> on the client side. This is, I guess because of the idle time on the TCP >>>>> connection. >>>>> We see the second request has 2000 ms Tt / Tr, this is the time elapsed >>>>> since the first request, plus the 'real' http response time. >>>>> >>>>> Now I wonder if this is normal behaviour and what are my options. >>>>> >>>>> I see: >>>>> >>>>> - Disable all form of keepalive, with a big performance cost >>>>> - Monitor only the NI requests, with a risk of inconsistencies >>>>> >>>>> Is there another way ? Do I understand correctly what is going on ? >>>>> >>>>> Thank you