bizarre network timing problem

[Felix von Leitner <felix-linuxkernel@fefe.de>]

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/