Pathological TCP behavior running ls(1) over SSH

To: tech-net%NetBSD.org@localhost
Subject: Pathological TCP behavior running ls(1) over SSH
From: gson%gson.org@localhost (Andreas Gustafsson)
Date: Sun, 27 Jan 2008 23:34:10 +0200
I'm suffering from annoying 1-second pauses in my SSH connections,
often while waiting during the output from ls(1).  This happens when I'm
logged in from one NetBSD-current machine to another NetBSD-current
machine.

The following tcpdump should illustrate the problem.  It was taken
from the server side of the connection and starts at a point in time
when I have typed "ls" on the client keyboard but not yet pressed
return, and ends when the "ls" output has been fully displayed
(including a one-second pause in the middle).  I'm listing my home
directory which contains 352 files, displayed by ls on 118 lines
totaling 6976 bytes of uncompressed data.  The network topology
involved is a simple wireless home network: server - ethernet -
wireless_access_point - wireless - client.

  # tcpdump -n -p -i re0 port 64186
  tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
  listening on re0, link-type EN10MB (Ethernet), capture size 96 bytes
  22:08:46.773481 IP 10.0.1.254.64186 > 91.152.94.125.22: P 
3643051533:3643051565(32) ack 1589485459 win 33580
  22:08:46.774427 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1:33(32) ack 32 win 
33580
  22:08:46.781341 IP 91.152.94.125.22 > 10.0.1.254.64186: P 33:65(32) ack 32 
win 33580
  22:08:46.781483 IP 91.152.94.125.22 > 10.0.1.254.64186: P 65:97(32) ack 32 
win 33580
  22:08:46.781593 IP 91.152.94.125.22 > 10.0.1.254.64186: P 97:129(32) ack 32 
win 33580
  22:08:46.781699 IP 91.152.94.125.22 > 10.0.1.254.64186: P 129:161(32) ack 32 
win 33580
  22:08:46.781799 IP 91.152.94.125.22 > 10.0.1.254.64186: P 161:193(32) ack 32 
win 33580
  22:08:46.781902 IP 91.152.94.125.22 > 10.0.1.254.64186: P 193:225(32) ack 32 
win 33580
  22:08:46.782003 IP 91.152.94.125.22 > 10.0.1.254.64186: P 225:257(32) ack 32 
win 33580
  22:08:46.782106 IP 91.152.94.125.22 > 10.0.1.254.64186: P 257:289(32) ack 32 
win 33580
  22:08:46.782208 IP 91.152.94.125.22 > 10.0.1.254.64186: P 289:321(32) ack 32 
win 33580
  22:08:46.782308 IP 91.152.94.125.22 > 10.0.1.254.64186: P 321:353(32) ack 32 
win 33580
  22:08:46.782413 IP 91.152.94.125.22 > 10.0.1.254.64186: P 353:385(32) ack 32 
win 33580
  22:08:46.782516 IP 91.152.94.125.22 > 10.0.1.254.64186: P 385:417(32) ack 32 
win 33580
  22:08:46.782619 IP 91.152.94.125.22 > 10.0.1.254.64186: P 417:449(32) ack 32 
win 33580
  22:08:46.782722 IP 91.152.94.125.22 > 10.0.1.254.64186: P 449:481(32) ack 32 
win 33580
  22:08:46.782827 IP 91.152.94.125.22 > 10.0.1.254.64186: P 481:513(32) ack 32 
win 33580
  22:08:46.782928 IP 91.152.94.125.22 > 10.0.1.254.64186: P 513:545(32) ack 32 
win 33580
  22:08:46.783029 IP 91.152.94.125.22 > 10.0.1.254.64186: P 545:577(32) ack 32 
win 33580
  22:08:46.783132 IP 91.152.94.125.22 > 10.0.1.254.64186: P 577:609(32) ack 32 
win 33580
  22:08:46.783233 IP 91.152.94.125.22 > 10.0.1.254.64186: P 609:641(32) ack 32 
win 33580
  22:08:46.783333 IP 91.152.94.125.22 > 10.0.1.254.64186: P 641:673(32) ack 32 
win 33580
  22:08:46.783443 IP 91.152.94.125.22 > 10.0.1.254.64186: P 673:705(32) ack 32 
win 33580
  22:08:46.783551 IP 91.152.94.125.22 > 10.0.1.254.64186: P 705:737(32) ack 32 
win 33580
  22:08:46.783656 IP 91.152.94.125.22 > 10.0.1.254.64186: P 737:769(32) ack 32 
win 33580
  22:08:46.783762 IP 91.152.94.125.22 > 10.0.1.254.64186: P 769:801(32) ack 32 
win 33580
  22:08:46.783864 IP 91.152.94.125.22 > 10.0.1.254.64186: P 801:833(32) ack 32 
win 33580
  22:08:46.783991 IP 91.152.94.125.22 > 10.0.1.254.64186: P 833:881(48) ack 32 
win 33580
  22:08:46.784101 IP 91.152.94.125.22 > 10.0.1.254.64186: P 881:929(48) ack 32 
win 33580
  22:08:46.784208 IP 91.152.94.125.22 > 10.0.1.254.64186: P 929:977(48) ack 32 
win 33580
  22:08:46.784316 IP 91.152.94.125.22 > 10.0.1.254.64186: P 977:1025(48) ack 32 
win 33580
  22:08:46.784422 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1025:1073(48) ack 
32 win 33580
  22:08:46.784526 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1073:1121(48) ack 
32 win 33580
  22:08:46.784637 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1121:1169(48) ack 
32 win 33580
  22:08:46.784744 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1169:1217(48) ack 
32 win 33580
  22:08:46.784851 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1217:1265(48) ack 
32 win 33580
  22:08:46.784960 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1265:1313(48) ack 
32 win 33580
  22:08:46.785066 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1313:1361(48) ack 
32 win 33580
  22:08:46.785159 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 65 win 33548
  22:08:46.785245 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1361:1409(48) ack 
32 win 33580
  22:08:46.785357 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1409:1457(48) ack 
32 win 33580
  22:08:46.785465 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1457:1505(48) ack 
32 win 33580
  22:08:46.785574 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1505:1553(48) ack 
32 win 33580
  22:08:46.785684 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1553:1601(48) ack 
32 win 33580
  22:08:46.785786 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1601:1649(48) ack 
32 win 33580
  22:08:46.785898 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1649:1697(48) ack 
32 win 33580
  22:08:46.786004 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1697:1745(48) ack 
32 win 33580
  22:08:46.786112 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1745:1793(48) ack 
32 win 33580
  22:08:46.786221 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1793:1841(48) ack 
32 win 33580
  22:08:46.786327 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1841:1889(48) ack 
32 win 33580
  22:08:46.786437 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1889:1937(48) ack 
32 win 33580
  22:08:46.786547 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1937:1985(48) ack 
32 win 33580
  22:08:46.786653 IP 91.152.94.125.22 > 10.0.1.254.64186: P 1985:2033(48) ack 
32 win 33580
  22:08:46.786764 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2033:2081(48) ack 
32 win 33580
  22:08:46.786867 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2081:2129(48) ack 
32 win 33580
  22:08:46.786975 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2129:2177(48) ack 
32 win 33580
  22:08:46.787079 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2177:2225(48) ack 
32 win 33580
  22:08:46.787183 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2225:2273(48) ack 
32 win 33580
  22:08:46.787287 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2273:2321(48) ack 
32 win 33580
  22:08:46.787397 IP 91.152.94.125.22 > 10.0.1.254.64186: P 2321:2369(48) ack 
32 win 33580
  22:08:46.789724 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 129 win 33548
  22:08:46.792828 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 193 win 33548
  22:08:46.797469 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 257 win 33548
  22:08:46.800948 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 321 win 33484
  22:08:46.804855 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 385 win 33420
  22:08:46.809791 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33548 
<nop,nop,sack 1 {449:481}>
  22:08:46.811619 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 1 {449:513}>
  22:08:46.812758 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 1 {449:545}>
  22:08:46.815403 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 2 {577:609}{449:545}>
  22:08:46.816686 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 2 {577:641}{449:545}>
  22:08:46.818773 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {673:705}{577:641}{449:545}>
  22:08:46.821499 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {673:737}{577:641}{449:545}>
  22:08:46.822713 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {769:801}{673:737}{577:641}>
  22:08:46.826083 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {769:833}{673:737}{577:641}>
  22:08:46.826741 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {881:929}{769:833}{673:737}>
  22:08:46.830789 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {977:1025}{881:929}{769:833}>
  22:08:46.834090 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {977:1073}{881:929}{769:833}>
  22:08:46.834804 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1121:1169}{977:1073}{881:929}>
  22:08:46.838272 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1121:1217}{977:1073}{881:929}>
  22:08:46.838883 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1121:1265}{977:1073}{881:929}>
  22:08:46.841573 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1361}{1121:1265}{977:1073}>
  22:08:46.842755 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1409}{1121:1265}{977:1073}>
  22:08:46.845251 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1457}{1121:1265}{977:1073}>
  22:08:46.846647 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1505}{1121:1265}{977:1073}>
  22:08:46.849678 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1553}{1121:1265}{977:1073}>
  22:08:46.853647 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1601}{1121:1265}{977:1073}>
  22:08:46.854742 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1649}{1121:1265}{977:1073}>
  22:08:46.856660 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1697}{1121:1265}{977:1073}>
  22:08:46.858642 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1745}{1121:1265}{977:1073}>
  22:08:46.860721 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1313:1793}{1121:1265}{977:1073}>
  22:08:46.862679 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1841:1889}{1313:1793}{1121:1265}>
  22:08:46.864690 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1841:1937}{1313:1793}{1121:1265}>
  22:08:46.866639 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1985:2033}{1841:1937}{1313:1793}>
  22:08:46.868653 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {1985:2081}{1841:1937}{1313:1793}>
  22:08:46.870658 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {2129:2177}{1985:2081}{1841:1937}>
  22:08:46.872641 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {2129:2225}{1985:2081}{1841:1937}>
  22:08:46.874649 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {2273:2321}{2129:2225}{1985:2081}>
  22:08:46.876534 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 417 win 33580 
<nop,nop,sack 3 {2273:2369}{2129:2225}{1985:2081}>

  [the one-second pause is here]

  22:08:47.800341 IP 91.152.94.125.22 > 10.0.1.254.64186: . 417:1877(1460) ack 
32 win 33580
  22:08:47.805289 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 1937 win 32060 
<nop,nop,sack 3 {2273:2369}{2129:2225}{1985:2081}>
  22:08:47.805381 IP 91.152.94.125.22 > 10.0.1.254.64186: . 1937:3397(1460) ack 
32 win 33580
  22:08:47.805397 IP 91.152.94.125.22 > 10.0.1.254.64186: P 3397:3889(492) ack 
32 win 33580
  22:08:47.810705 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 3397 win 32120
  22:08:48.009779 IP 10.0.1.254.64186 > 91.152.94.125.22: . ack 3889 win 33580
  ^C
  104 packets captured
  104 packets received by filter
  0 packets dropped by kernel
  #

This looks similar to what Tomas Svensson reported in 2002 in
<http://mail-index.netbsd.org/tech-net/2002/03/15/0000.html>, but
these tinygrams are even smaller, perhaps because I have enabled
compression in my .ssh/config.

Aside from the question of whether sshd should set TCP_NODELAY or not,
could someone explain why the server waits almost a whole second to
retransmit the segment starting at octet 417; why don't the
38 duplicate ACKs cause a fast retransmit?
-- 
Andreas Gustafsson, gson%gson.org@localhost
Follow-Ups:
- Re: Pathological TCP behavior running ls(1) over SSH
  - From: Darren Reed
- Re: Pathological TCP behavior running ls(1) over SSH
  - From: David Young
Prev by Date: Re: Socket options KPI
Next by Date: Re: Revamping optimised in_cksum/in4_cksum/in6_cksum support
Previous by Thread: Warning: bogus HMAC providers in opencrypto about to be fixed
Next by Thread: Re: Pathological TCP behavior running ls(1) over SSH
Indexes:
Home | Main Index | Thread Index | Old Index