Re: dev 2.2 High CPU Constantly

2020-07-02 Thread Igor Pav
Hi William, Tried but still the same ;(

On Fri, Jul 3, 2020 at 2:35 AM William Dauchy  wrote:
>
> Hi Igor,
>
> On Thu, Jul 2, 2020 at 9:57 AM Igor Pav  wrote:
> > By using dev11, the CPU consumption drops a lot, but when connections
> > reach ~1000, the CPU would still go high, remove the 0rtt-rejected
> > from conf, the CPU becomes normal...
>
> if you have the opportunity to test the last HEAD of the repo it could
> be useful.
> I believe this could be fixed by last Willy commit:
> https://git.haproxy.org/?p=haproxy.git;a=commit;h=18ed789ae262382e3fe89288132d709c114575aa
> --
> William



Re: dev 2.2 High CPU Constantly

2020-07-02 Thread William Dauchy
Hi Igor,

On Thu, Jul 2, 2020 at 9:57 AM Igor Pav  wrote:
> By using dev11, the CPU consumption drops a lot, but when connections
> reach ~1000, the CPU would still go high, remove the 0rtt-rejected
> from conf, the CPU becomes normal...

if you have the opportunity to test the last HEAD of the repo it could
be useful.
I believe this could be fixed by last Willy commit:
https://git.haproxy.org/?p=haproxy.git;a=commit;h=18ed789ae262382e3fe89288132d709c114575aa
-- 
William



Re: dev 2.2 High CPU Constantly

2020-07-02 Thread Willy Tarreau
Hi Igor,

On Thu, Jul 02, 2020 at 03:54:37PM +0800, Igor Pav wrote:
> Hi Willy,
> 
> By using dev11, the CPU consumption drops a lot, but when connections
> reach ~1000, the CPU would still go high, remove the 0rtt-rejected
> from conf, the CPU becomes normal...

Thank your for the report, that is useful. At the moment I have no idea
how 0-rtt is related to this, nor do I know the exact sequence that is
executed in this case. But given that it's one of the retry-on settings,
I'm suspecting that something prevents from getting away from the connect
loop.

I know that Christopher has already rechecked the retry code recently
and didn't find a case where a retry could be performed without being
decremented. So there's definitely something odd there.

Note that we've addresses a number of remaining issues around CPU usage
and connection reuse since dev11 but I don't see how they could be affected
by your case above, and be careful if you test latest HEAD as apparently we
broke something that I still can't reproduce :-/

Cheers,
Willy



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: dev 2.2 High CPU Constantly

2020-07-02 Thread Igor Pav
Hi Willy,

By using dev11, the CPU consumption drops a lot, but when connections
reach ~1000, the CPU would still go high, remove the 0rtt-rejected
from conf, the CPU becomes normal...

On Fri, Jun 26, 2020 at 5:48 PM Willy Tarreau  wrote:
>
> Hi Igor,
>
> On Fri, Jun 12, 2020 at 03:00:31PM +0800, Igor Pav wrote:
> > Hi, are those log lines both in syslog? I didn't see it there. I'm
> > using this simple setup for a forward HTTP proxy, sooner and later,
> > CPU goes crazy.
>
> Sorry for this late reply. The "bogus stream" message William was talking
> about is sent to stderr, so possibly it's logged by your service manager.
>
> Please note that the bug that caused this for William was addressed in dev10
> but that there's still a CPU usage issue floating around. So it would be
> cool if you could try latest master (dev10+latest fixes) to check if you're
> still facing this problem. If so, more info about your workload could help
> us.
>
> Thanks!
> Willy