Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S935722AbXJQU6T (ORCPT ); Wed, 17 Oct 2007 16:58:19 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1759616AbXJQU6L (ORCPT ); Wed, 17 Oct 2007 16:58:11 -0400 Received: from ioctl.codeblau.de ([80.190.240.67]:53428 "EHLO codeblau.de" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1757756AbXJQU6K (ORCPT ); Wed, 17 Oct 2007 16:58:10 -0400 X-Greylist: delayed 399 seconds by postgrey-1.27 at vger.kernel.org; Wed, 17 Oct 2007 16:58:09 EDT Date: Wed, 17 Oct 2007 22:51:27 +0200 From: Felix von Leitner To: linux-kernel@vger.kernel.org Subject: bizarre network timing problem Message-ID: <20071017205127.GA21334@codeblau.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.5.13 (2006-08-11) Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 5518 Lines: 83 I wrote a small read-only SMB server, and wanted to see how fast it was. So I used smbget to download a moderately large file from it via localhost. smbget only got ~70 KB/sec. This is what the view from strace -tt on the server is: 22:44:58.812467 read(8, "\0\0\0007\377SMB.\0\0\0\0\10\1\310\0\0\0\0\0\0\0\0\0\0\0\0\0\0\232\3"..., 8192) = 59 22:44:58.812619 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b46b8e5e000 22:44:58.812729 fcntl(9, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE) 22:44:58.812847 epoll_ctl(7, EPOLL_CTL_DEL, 8, {0, {u32=8, u64=13323248792850399240}}) = 0 22:44:58.812946 epoll_ctl(7, EPOLL_CTL_ADD, 8, {EPOLLOUT, {u32=8, u64=18251433459580936}}) = 0 22:44:58.813039 epoll_wait(7, {{EPOLLOUT, {u32=8, u64=18251433459580936}}}, 100, 442) = 1 22:44:58.813132 setsockopt(8, SOL_TCP, TCP_CORK, [1], 4) = 0 22:44:58.813215 write(8, "\0\0\372<\377SMB.\0\0\0\0\200A\300\0\0\0\0\0\0\0\0\0\0\0\0\0\0\232\3"..., 64) = 64 22:44:58.813323 sendfile(8, 9, [128000], 64000) = 64000 22:44:58.813430 setsockopt(8, SOL_TCP, TCP_CORK, [0], 4) = 0 22:44:58.813511 munmap(0x2b46b8e5e000, 8192) = 0 22:44:58.813600 epoll_wait(7, {{EPOLLOUT, {u32=8, u64=18251433459580936}}}, 100, 442) = 1 22:44:58.813693 epoll_ctl(7, EPOLL_CTL_DEL, 8, {0, {u32=8, u64=8}}) = 0 22:44:58.813778 epoll_ctl(7, EPOLL_CTL_ADD, 8, {EPOLLIN, {u32=8, u64=18252000395264008}}) = 0 22:44:58.813869 epoll_wait(7, {}, 100, 441) = 0 22:44:59.255789 epoll_wait(7, {{EPOLLIN, {u32=8, u64=18252000395264008}}}, 100, 999) = 1 22:44:59.688519 read(8, "\0\0\0007\377SMB.\0\0\0\0\10\1\310\0\0\0\0\0\0\0\0\0\0\0\0\0\0\232\3"..., 8192) = 59 As you can see, the time difference between reading the query and writing the result is very small, but there is a big delay before receiving the next request. This is the view from a sniffer on the lo interface: 1192653899.688385 127.0.0.1 -> 127.0.0.1 SMB Read AndX Request, FID: 0x0001, 64000 bytes at offset 192000 1192653899.688399 127.0.0.1 -> 127.0.0.1 TCP 445 > 42990 [ACK] Seq=192660 Ack=779 Win=33920 Len=0 TSV=359208 TSER=359208 1192653899.895725 127.0.0.1 -> 127.0.0.1 SMB [TCP Window Full] Read AndX Response, FID: 0x0001, 64000 bytes 1192653899.895793 127.0.0.1 -> 127.0.0.1 TCP 42990 > 445 [ACK] Seq=779 Ack=204948 Win=12288 Len=0 TSV=359260 TSER=359260 1192653899.895805 127.0.0.1 -> 127.0.0.1 NBSS NBSS Continuation Message 1192653899.935725 127.0.0.1 -> 127.0.0.1 TCP 42990 > 445 [ACK] Seq=779 Ack=209044 Win=12288 Len=0 TSV=359270 TSER=359260 1192653900.147739 127.0.0.1 -> 127.0.0.1 NBSS [TCP Window Full] NBSS Continuation Message 1192653900.147767 127.0.0.1 -> 127.0.0.1 TCP [TCP ZeroWindow] 42990 > 445 [ACK] Seq=779 Ack=221332 Win=0 Len=0 TSV=359323 TSER=359323 1192653900.147807 127.0.0.1 -> 127.0.0.1 TCP [TCP Window Update] 42990 > 445 [ACK] Seq=779 Ack=221332 Win=12288 Len=0 TSV=359323 TSER=359323 1192653900.147815 127.0.0.1 -> 127.0.0.1 NBSS NBSS Continuation Message 1192653900.147837 127.0.0.1 -> 127.0.0.1 TCP 42990 > 445 [ACK] Seq=779 Ack=225428 Win=12288 Len=0 TSV=359323 TSER=359323 1192653900.355754 127.0.0.1 -> 127.0.0.1 NBSS [TCP Window Full] NBSS Continuation Message 1192653900.355782 127.0.0.1 -> 127.0.0.1 TCP [TCP ZeroWindow] 42990 > 445 [ACK] Seq=779 Ack=237716 Win=0 Len=0 TSV=359375 TSER=359375 1192653900.355820 127.0.0.1 -> 127.0.0.1 TCP [TCP Window Update] 42990 > 445 [ACK] Seq=779 Ack=237716 Win=12288 Len=0 TSV=359375 TSER=359375 1192653900.355829 127.0.0.1 -> 127.0.0.1 NBSS NBSS Continuation Message 1192653900.355849 127.0.0.1 -> 127.0.0.1 TCP 42990 > 445 [ACK] Seq=779 Ack=241812 Win=12288 Len=0 TSV=359375 TSER=359375 1192653900.563766 127.0.0.1 -> 127.0.0.1 NBSS [TCP Window Full] NBSS Continuation Message 1192653900.563794 127.0.0.1 -> 127.0.0.1 TCP [TCP ZeroWindow] 42990 > 445 [ACK] Seq=779 Ack=254100 Win=0 Len=0 TSV=359427 TSER=359427 1192653900.563831 127.0.0.1 -> 127.0.0.1 TCP [TCP Window Update] 42990 > 445 [ACK] Seq=779 Ack=254100 Win=12288 Len=0 TSV=359427 TSER=359427 1192653900.563839 127.0.0.1 -> 127.0.0.1 NBSS NBSS Continuation Message 1192653900.563858 127.0.0.1 -> 127.0.0.1 TCP 42990 > 445 [ACK] Seq=779 Ack=256724 Win=12288 Len=0 TSV=359427 TSER=359427 1192653900.564444 127.0.0.1 -> 127.0.0.1 SMB Read AndX Request, FID: 0x0001, 64000 bytes at offset 256000 Note the delay between sending the response and getting the reply. Also note that there is almost no delay between getting the reply and sending the next request. My understanding of TCP_CORK from the tcp(7) man page is that it should flush out the data immediately, but the network trace seems to suggest that there is a 200 ms delay between the request and the outgoing data. tcp(7) says there is a 200 ms delay for sending out data when the socket is in corked mode, so uncorking does not appear to work. Now for the strange part: the same code works without a 200 ms delay over ethernet. The delay only appears on the loopback interface. Also, on my home desktop, which is also running 2.6.22, there is no delay even on loopback. I tried 2.6.23 on my notebook, but the effect is the same. Any ideas what could cause this? Thanks, Felix - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/