Re: 2.6.15 localhost performance hit
Rick Jones wrote: It _would_ be very interesting to see if disabling tcp_abc does workaround the problem. Yes it does, we tried that first. Then we reenabled tcp_abc and increased the toolkit keep_alive. Either method works around the issue from our point of view. --- John - To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: 2.6.15 localhost performance hit
Rick Jones wrote: Skunk Worx wrote: Rick Jones wrote: From strace : 15:27:04.568800 recv(3, "555, ) = 555 <0.000121> vs. 15:18:24.515891 recv(3, "566, ) = 566 <0.038414> Will watch replies and post more when I know more. Kinda new at this. Do you have the strace from the sending side? 15:18:23.625316 recv(4, "POST / HTTP/1.1\r\nHost: localhost"..., 32768, 0) = 593 <0.18> 15:18:23.625542 send(4, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 129, 0) = 129 <0.000114> 15:18:23.625787 send(4, "236\r\n", 5, 0) = 5 <0.76> 15:18:23.625937 send(4, "0) = 566 <0.000117> 15:18:23.626133 send(4, "\r\n0\r\n\r\n", 7, 0) = 7 <0.000167> And there you have it - four separate sends for logically associated data, when there should have been just the one sendmsg or writev call. Given the sizes involved, that is roughly three to four times as much CPU consumed to send that data is should have been - for "small" packets you can handwave that the CPU cost is "per-packet" rather than "per-byte" (OK, not _strictly_ true for say that 566 byte chunk, but for the rest basically true) We're kind of stuck using gsoap. We like the toolkit and have a lot of code using it. Fortunately, none of our packets will be going on the internet. The same problem exists using the latest version of gsoap, so they are still utilizing small packets. I am planning on mentioning this to them occasionally on their list. We noticed an interesting dynamic in the way the TCP ACK delay is applied to our transactions. The gsoap toolkit has an internal "keep_alive" variable that regulates the number of transactions a client can make to the server on a given connection. We've always used the default of 100. In the tcpdump, we see that the first 40 ms. ACK delay is applied just after the TCP window ramps up on a new connection. We get additional ACK delays applied for the next 22 transactions, then it stops--no more delays are seen in the remaining 77 transactions. Then the keep_alive has counted to zero, and the client is forced to reconnect to the server, and the process repeats--23 ACK delays, then 77 unmolested transactions. Changing the keep_alive to 10,000 (we write all our clients, not worried about abuse) drops the ACK delay count to about 27/13,000 transactions, much better than the 3000 delays originally seen. Another option is to sysctl tcp_abc off, if we have to. I wonder if client applications are being charged for the initial SYN packets, or something else odd is happening in the ABC algorithm as the TCP window is growing? --- John - To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: 2.6.15 localhost performance hit
Stephen Hemminger wrote: On Wed, 15 Mar 2006 20:13:01 -0800 Skunk Worx <[EMAIL PROTECTED]> wrote: Hello, I've taken a performance hit over localhost between kernels 2.6.14 and 2.6.15 in my client/server application. This came up with java debugging already. The problem is when the sender writes a message in separate write() system calls, each one becomes a separate packet. In 2.6.15 we do a new thing called Appropriate Byte Count and that penalizes stupid applications, but provides better fairness over the internet by accounting for packets better. I am curious about why this is seen only on loopback. Over ether, with client and server on two machines, there is no 40ms. ack penalty. If anything, I would expect to see things the other way around--penalty on ether, no penalty on loopback. --- John - To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: 2.6.15 localhost performance hit
Rick Jones wrote:
From strace :
15:27:04.568800 recv(3, ") = 555 <0.000121>
vs.
15:18:24.515891 recv(3, ") = 566 <0.038414>
Will watch replies and post more when I know more. Kinda new at this.
Do you have the strace from the sending side?
Yes...I hope I'm not posting too much info but here goes. It's worth
mentioning that this data is never on the internet, only isolated lan or
loopback. We are using an older version of the GSOAP toolkit (a
sourceforge project) and are in the process of porting to their latest
version.
In addition to the straces below, I have ethereal screencaps in jpeg
format if anyone wants to see those...2 x ~400k. ea.
Thanks everyone for pondering this. I tried to get the socket setup and
several full transactions from each side of loopback.
---
John
Server side:
15:15:11.267781 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3 <0.33>
15:15:11.267885 setsockopt(3, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
<0.15>
15:15:11.267970 setsockopt(3, SOL_SOCKET, SO_SNDBUF, [32768], 4) = 0
<0.14>
15:15:11.268051 setsockopt(3, SOL_SOCKET, SO_RCVBUF, [32768], 4) = 0
<0.14>
15:15:11.268133 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.16>
15:15:11.268216 bind(3, {sa_family=AF_INET, sin_port=htons(8080),
sin_addr=inet_addr("0.0.0.0")}, 16) = 0 <0.20>
15:15:11.268318 listen(3, 100) = 0 <0.43>
15:15:11.268433 getsockname(3, {sa_family=AF_INET, sin_port=htons(8080),
sin_addr=inet_addr("0.0.0.0")}, [16]) = 0 <0.15>
15:18:23.624649 fcntl64(3, F_GETFL) = 0x2 (flags O_RDWR) <0.14>
15:18:23.624724 fcntl64(3, F_SETFL, O_RDWR) = 0 <0.13>
15:18:23.624799 accept(3, {sa_family=AF_INET, sin_port=htons(57058),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 4 <0.23>
15:18:23.624939 setsockopt(4, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
<0.15>
15:18:23.625021 setsockopt(4, SOL_SOCKET, SO_SNDBUF, [32768], 4) = 0
<0.14>
15:18:23.625101 setsockopt(4, SOL_SOCKET, SO_RCVBUF, [32768], 4) = 0
<0.14>
15:18:23.625180 setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.14>
15:18:23.625316 recv(4, "POST / HTTP/1.1\r\nHost: localhost"..., 32768,
0) = 593 <0.18>
15:18:23.625542 send(4, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 129, 0)
= 129 <0.000114>
15:18:23.625787 send(4, "236\r\n", 5, 0) = 5 <0.76>
15:18:23.625937 send(4, "0) = 566 <0.000117>
15:18:23.626133 send(4, "\r\n0\r\n\r\n", 7, 0) = 7 <0.000167>
15:18:23.627215 recv(4, "POST / HTTP/1.1\r\nHost: localhost"..., 32768,
0) = 593 <0.17>
15:18:23.627438 send(4, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 129, 0)
= 129 <0.000196>
15:18:23.627761 send(4, "236\r\n", 5, 0) = 5 <0.000147>
15:18:23.627978 send(4, "0) = 566 <0.17>
15:18:23.628074 send(4, "\r\n0\r\n\r\n", 7, 0) = 7 <0.15>
15:18:23.628217 recv(4, "POST / HTTP/1.1\r\nHost: localhost"..., 32768,
0) = 593 <0.038687>
15:18:23.667206 send(4, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 129, 0)
= 129 <0.78>
15:18:23.667466 send(4, "236\r\n", 5, 0) = 5 <0.000107>
15:18:23.667682 send(4, "0) = 566 <0.68>
15:18:23.667828 send(4, "\r\n0\r\n\r\n", 7, 0) = 7 <0.15>
15:18:23.667973 recv(4, "POST / HTTP/1.1\r\nHost: localhost"..., 32768,
0) = 593 <0.043338>
15:18:23.711654 send(4, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 129, 0)
= 129 <0.81>
15:18:23.711929 send(4, "236\r\n", 5, 0) = 5 <0.000112>
15:18:23.712149 send(4, "0) = 566 <0.67>
15:18:23.712297 send(4, "\r\n0\r\n\r\n", 7, 0) = 7 <0.15>
15:18:23.712442 recv(4, "POST / HTTP/1.1\r\nHost: localhost"..., 32768,
0) = 593 <0.038666>
15:18:23.751433 send(4, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 129, 0)
= 129 <0.80>
Client side :
15:16:05.012862 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3 <0.29>
15:16:05.012960 setsockopt(3, SOL_SOCKET, SO_SNDBUF, [32768], 4) = 0
<0.16>
15:16:05.013045 setsockopt(3, SOL_SOCKET, SO_RCVBUF, [32768], 4) = 0
<0.15>
15:16:05.013125 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.17>
15:16:05.019312 fcntl64(3, F_GETFL) = 0x2 (flags O_RDWR) <0.14>
15:16:05.019388 fcntl64(3, F_SETFL, O_RDWR) = 0 <0.14>
15:16:05.019463 connect(3, {sa_family=AF_INET, sin_port=htons(8080),
sin_addr=inet_addr("127.0.0.1")}, 16) = 0 <0.000815>
15:18:23.624100 send(3, "POST / HTTP/1.1\r\nHost: localhost"..., 593, 0)
= 593 <0.87>
15:18:23.624313 recv(3, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 32768,
0) = 129 <0.002025>
15:18:23.626445 recv(3, "236\r\n32768, 0) = 578 <0.20>
15:18:23.626639 gettimeofday({1142464703, 626676}, NULL) = 0 <0.17>
15:18:23.626771 select(4, [3], [3], [3], {0, 0}) = 1 (out [3], left {0,
0}) <0.16>
15:18:23.626901 send(3, "POST / HTTP/1.1\r\nHost: localhost"..., 593, 0)
= 593 <0.70>
15:18:23.627088 recv(3, "HTTP/1.1 200 OK\r\nServer: gSOAP/2"..., 32768,
0) = 129 <0.000445>
15:18:23.627635 recv(3, "236\r\n", 32768, 0) = 5 <0.000190>
15:18:23.627900 recv(3, "0) = 566 <0.038382>
15:18:23.666432 recv(3, "\r\n0\r\n\r\n", 32768,
2.6.15 localhost performance hit
Hello, I've taken a performance hit over localhost between kernels 2.6.14 and 2.6.15 in my client/server application. I'm trying to gut things down to a simple test case, in the meantime, this is what I've been discussing with the people at the fedora test list : This is only over localhost (lo). Two machines running client/server 2.6.15 over ether seem fine, as was 2.6.14. 2.6.14 : about one or two recv() calls out of 48,000 take nearly 40 ms. (no big deal--might add 80 ms. to a 20 second operation). 2.6.15 : about 3,000 recv() calls out of 48,000 take nearly 40 ms. (adds almost two minutes) From strace : 15:27:04.568800 recv(3, "= 555 <0.000121> vs. 15:18:24.515891 recv(3, "= 566 <0.038414> Will watch replies and post more when I know more. Kinda new at this. -- SW - To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
