Re: Monitoring the total request time in haproxy 1.7.5 HTTP logs - More logs, better explanation
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 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 :
>>
>>> it is ht
Re: Monitoring the total request time in haproxy 1.7.5 HTTP logs
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, Илья Шипицин 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 : > >> 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, Илья Шипицин a écrit : >> >>> is it https ? is ocsp stapling enabled ? >>> >>> вт, 30 июн. 2020 г. в 20:24, Paul Belloc : >>> >>>> 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
Re: Monitoring the total request time in haproxy 1.7.5 HTTP logs
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, Илья Шипицин a écrit : > is it https ? is ocsp stapling enabled ? > > вт, 30 июн. 2020 г. в 20:24, Paul Belloc : > >> 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
Monitoring the total request time in haproxy 1.7.5 HTTP logs
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
