On Sun, Jan 24, 2016 at 07:29:36PM +0100, Cyril Bonté wrote: > I'm also testing on my laptop on localhost to avoid some network side > effects. Here, the tests are consistent, I always have the same > performance for a given version.
OK fine. > >Under stace, it's even worse. The number of calls to sendto() for > >a single run varies between 1000 and 199000, without any error nor > >EAGAIN. And the number of recvfrom() varies from 129001 to 519011, > >which really doesn't make sense. read() and write() are perfectly > >stable though, at 3030 and 65005 respectively. They're called from > >openssl. > > Using ltrace, I see an interesting pattern : > > With haproxy 1.5, I get : > 1453658897.664685 recv(7, 0xec50b4, 8192, 0) = 8192 > 1453658897.664847 __errno_location() = 0x7fa04fdd1690 > 1453658897.664957 recv(7, 0xec70b4, 8192, 0) = 8192 > 1453658897.665115 SSL_write(0xeb83d0, 0xec50b4, 0x4000, 0x4000 > <unfinished ...> > 1453658897.665221 malloc(16472) = 0xec90d0 > 1453658897.665375 free(0xec90d0) = <void> > 1453658897.665486 <... SSL_write resumed> ) = 0x4000 > 1453658897.665519 gettimeofday(0x7217d0, 0) = 0 > 1453658897.665634 epoll_wait(3, 0xeac440, 200, 0) = 0 > > Where haproxy 1.7 gives : > 1453658760.290096 recv(7, 0x173ae84, 0x3c08, 0) = 0x3c08 > 1453658760.290271 __errno_location() = 0x7fcabf9fa690 > 1453658760.290382 recv(7, 0x173ea8c, 1024, 0) = 1024 > 1453658760.290545 SSL_write(0x17768b0, 0x173ae84, 0x4008, 0x4008 > <unfinished ...> > 1453658760.290654 malloc(16472) = 0x17773c0 > 1453658760.290818 <... SSL_write resumed> ) = 0x4000 > 1453658760.290868 SSL_write(0x17768b0, 0x173ee84, 8, 8 <unfinished ...> > 1453658760.291012 free(0x17773c0) = <void> > 1453658760.291129 <... SSL_write resumed> ) = 8 > 1453658760.291162 gettimeofday(0x76b340, 0) = 0 > 1453658760.291287 epoll_wait(3, 0x1775f40, 200, 0) = 0 > > Here we have 2 consecutive recv of 0x3c08 (15368) bytes then 1024 bytes > = 15392 bytes. > SSl_Write then is able to send 16384 bytes and needs to send the 8 > remaining bytes in a 2nd call. Yes I've noticed this as well and discovered several issues, I don't know yet which ones are linked together : - in 1.6/1.7 with dynamic buffers, we also provide the rounded up buffer size as free space. Hence if you request 16384 bytes for bufsize, you get 16392. Usually this is nice, but here it causes a problem : openssl cannot digest more than 16384 bytes, so feeding it with 16392 causes the two calls you've seen above, one of which is only made for 8 bytes, and this is the counter-productive effect. The simplest workaround is to slightly lower the bufsize, but I'd like to address this more elegantly in the code, possibly with different pool creation strategies (strict vs lose size). - when I tried to lower the buffer size, I entered exactly 16000. For a reason I ignore, the transfer hangs after the end of the first transfer. I have not investigated this and it could be my server (a hacked haproxy 1.6 modified to implement the good old httpterm). So I don't consider this a real issue until investigated for real. - the multiple recvfrom() I'm seeing are caused by a bug in channel_reserved(). It calls channel_limit() to know the amount of bytes that are supposed to leave, but it does this without considering channel->to_forward. The net effect is that once the buffer is empty, it limits itself to the buffer size minus maxrewrite (1024). So that causes two reads to happen, a 15kB one and a 1kB one. Thus in the worst case which happens to be the default one, for large files we'll always see two recvfrom() per 16kB and two SSL_write(). That's ugly. I'm now working on this. > commit 5506e3f8 behaves like haproxy-1.5 > commit e583ea58 like haproxy-1.7 OK that's definitely useful to compare if there's something else to consider. Cheers, Willy
