Re: Monitoring the total request time in haproxy 1.7.5 HTTP logs - More logs, better explanation

2020-07-02 Thread Paul Belloc
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 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 :
>>>

Re: Monitoring the total request time in haproxy 1.7.5 HTTP logs

2020-06-30 Thread Paul Belloc
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

2020-06-30 Thread Илья Шипицин
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

2020-06-30 Thread 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

2020-06-30 Thread Илья Шипицин
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

2020-06-30 Thread 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