James Lamanna
2007-Oct-05 18:35 UTC
[Samba] Very slow file copy performance over a WAN (HELP)
Hi, I've noticed that over a WAN (T1) I'm getting incredibly slow file copy performance. Using smbclient on a linux machine on one size of the WAN, As you can imagine, this makes all of our file shares unusable over the WAN. It's not an issue with WAN performance, because using scp to transfer the same file, I get speeds of ~145k/s. A tcpdump of the file copy of ~2MB file that actually times out with the following error is up at: http://emagiccards.com/james/copyfileusingsmbclient.tar.bz2 -- Timeout Error -- Short read when getting file \Finance\monthly_reports\Aug07.xls. Only got 967680 bytes. Error Call timed out: server did not respond after 20000 milliseconds closing remote file -- Scp Results -- scp root@fs0:/export/data/Finance/Monthly_reports/Aug07.xls . Aug07.xls 100% 2269KB 174.5KB/s 00:13 -- File server samba config -- workgroup = XXXXXXXXX netbios name = FS0 enable privileges = yes server string = FS0 log file = /var/log/samba/log.%m max log size = 50 #log level = 3 passdb:5 auth:10 log level = 10 hosts allow = 10.20.0.0/16 192.168.0.0/16 127.0.0.0/8 map to guest = Bad User guest account = nobody security = user encrypt passwords = yes smb passwd file = /etc/samba/private/smbpasswd wins server = 10.20.100.45 wins support = no name resolve order = wins lmhosts host bcast wins support = no dns proxy = no use sendfile = yes max xmit = 16644 socket options = IPTOS_LOWDELAY TCP_NODELAY SO_SNDBUF=8192 interfaces = lo eth1 hide unreadable = yes hide dot files = yes [TTData] path = /export/data browseable = yes writeable = yes default case = lower preserve case = yes show preserve case = yes case sensitive = no write list = @"Domain Users" @root create mask = 0775 directory mask = 0775 oplocks = no level2 oplocks = no
James Lamanna
2007-Oct-06 17:43 UTC
[Samba] Re: Very slow file copy performance over a WAN (HELP)
Some more forensics: Looking at a log file I notice there is an 8s delay between send_file of a block of 16k and any further processing. What would cause this? There's something really, really strange going on. Thanks. -- James [2007/10/06 10:31:02, 3] smbd/reply.c:send_file_readX(2618) send_file_readX: sendfile fnum=4574 max=15360 nread=15423 ---- 8 second delay to transfer 16k??????? ---- [2007/10/06 10:31:10, 10] lib/util_sock.c:read_smb_length_return_keepalive(623) got smb length of 55 [2007/10/06 10:31:10, 6] smbd/process.c:process_smb(1067) got message type 0x0 of len 0x37 [2007/10/06 10:31:10, 3] smbd/process.c:process_smb(1068) Transaction 53 of length 59 [2007/10/06 10:31:10, 5] lib/util.c:show_msg(484) [2007/10/06 10:31:10, 5] lib/util.c:show_msg(494) size=55 smb_com=0x2e smb_rcls=0 smb_reh=0 smb_err=0 smb_flg=8 smb_flg2=51201 smb_tid=1 smb_pid=28073 smb_uid=101 smb_mid=54 smt_wct=10 smb_vwv[ 0]= 255 (0xFF) smb_vwv[ 1]= 0 (0x0) smb_vwv[ 2]= 4574 (0x11DE) smb_vwv[ 3]=56320 (0xDC00) smb_vwv[ 4]= 8 (0x8) smb_vwv[ 5]=16384 (0x4000) smb_vwv[ 6]=16384 (0x4000) smb_vwv[ 7]= 0 (0x0) smb_vwv[ 8]= 0 (0x0) smb_vwv[ 9]= 0 (0x0) smb_bcc=0 [2007/10/06 10:31:10, 3] smbd/process.c:switch_message(926) switch message SMBreadX (pid 1307) conn 0x555555ad4480 [2007/10/06 10:31:10, 4] smbd/uid.c:change_to_user(183) change_to_user: Skipping user change - already user [2007/10/06 10:31:10, 10] locking/brlock.c:brl_get_locks_internal(1648) brl_get_locks_internal: 0 current locks on dev=64769, inode=550024983 [2007/10/06 10:31:10, 4] smbd/uid.c:change_to_user(183) change_to_user: Skipping user change - already user [2007/10/06 10:31:10, 10] locking/brlock.c:brl_get_locks_internal(1648) brl_get_locks_internal: 0 current locks on dev=64769, inode=550024983 [2007/10/06 10:31:10, 10] locking/posix.c:is_posix_locked(285) is_posix_locked: File Finance/Monthly_reports/Aug07.xls, offset 580608, count = 16384, type = READ [2007/10/06 10:31:10, 10] locking/posix.c:posix_lock_in_range(173) posix_lock_in_range: offset_out = 580608, count_out = 16384 [2007/10/06 10:31:10, 8] locking/posix.c:posix_fcntl_getlock(235) posix_fcntl_getlock 28 580608 16384 0 [2007/10/06 10:31:10, 8] lib/util.c:fcntl_getlock(2028) fcntl_getlock fd=28 offset=580608 count=16384 type=0 [2007/10/06 10:31:10, 3] lib/util.c:fcntl_getlock(2052) fcntl_getlock: fd 28 is returned info 2 pid 0 [2007/10/06 10:31:10, 8] locking/posix.c:posix_fcntl_getlock(265) posix_fcntl_getlock: Lock query call successful [2007/10/06 10:31:10, 10] locking/brlock.c:brl_locktest(1133) brl_locktest: posix start=580608 len=16384 unlocked for fnum 4574 file Finance/Monthly_reports/Aug07.xls [2007/10/06 10:31:10, 10] locking/locking.c:is_locked(137) is_locked: flavour = WINDOWS_LOCK brl start=580608 len=16384 unlocked for fnum 4574 file Finance/Monthly_reports/Aug07.xls -- TCPDump Log ---- 10:31:11.036969 IP (tos 0x0, ttl 64, id 19011, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 3993:3993(0) ack 698305 win 3072 <nop,nop,timestamp 86477455 615322904> 10:31:11.037001 IP (tos 0x0, ttl 64, id 19012, offset 0, flags [DF], length: 111) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: P 3993:4052(59) ack 698305 win 3072 <nop,nop,timestamp 86477455 615322904> 10:31:11.321918 IP (tos 0x0, ttl 64, id 19013, offset 0, flags [DF], length: 111) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: P 3993:4052(59) ack 698305 win 3072 <nop,nop,timestamp 86477526 615322904> 10:31:11.329388 IP (tos 0x0, ttl 60, id 60434, offset 0, flags [DF], length: 64) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 699753:699753(0) ack 4052 win 2520 <nop,nop,timestamp 615322978 86477526,nop,nop,[|tcp]> 10:31:12.594715 IP (tos 0x0, ttl 60, id 60436, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 698305:699753(1448) ack 4052 win 2520 <nop,nop,timestamp 615323292 86477526> 10:31:12.633854 IP (tos 0x0, ttl 64, id 19014, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 699753 win 3072 <nop,nop,timestamp 86477854 615323292> 10:31:12.648924 IP (tos 0x0, ttl 60, id 60437, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 699753:701201(1448) ack 4052 win 2520 <nop,nop,timestamp 615323306 86477854> 10:31:12.648961 IP (tos 0x0, ttl 64, id 19015, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 701201 win 3072 <nop,nop,timestamp 86477858 615323306> 10:31:12.671920 IP (tos 0x0, ttl 60, id 60439, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 702649:704097(1448) ack 4052 win 2520 <nop,nop,timestamp 615323310 86477858> 10:31:12.671954 IP (tos 0x0, ttl 64, id 19016, offset 0, flags [DF], length: 64) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . 4052:4052(0) ack 701201 win 3072 <nop,nop,timestamp 86477864 615323306,nop,nop,[|tcp]> 10:31:12.886614 IP (tos 0x0, ttl 60, id 60441, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 701201:702649(1448) ack 4052 win 2520 <nop,nop,timestamp 615323365 86477864> 10:31:12.886656 IP (tos 0x0, ttl 64, id 19017, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 704097 win 2731 <nop,nop,timestamp 86477917 615323365> 10:31:12.901704 IP (tos 0x0, ttl 60, id 60442, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 704097:705545(1448) ack 4052 win 2520 <nop,nop,timestamp 615323369 86477917> 10:31:12.901737 IP (tos 0x0, ttl 64, id 19018, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 705545 win 3072 <nop,nop,timestamp 86477921 615323369> 10:31:13.138582 IP (tos 0x0, ttl 60, id 60444, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 705545:706993(1448) ack 4052 win 2520 <nop,nop,timestamp 615323428 86477921> 10:31:13.138617 IP (tos 0x0, ttl 64, id 19019, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 706993 win 3072 <nop,nop,timestamp 86477980 615323428> 10:31:13.153675 IP (tos 0x0, ttl 60, id 60445, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 706993:708441(1448) ack 4052 win 2520 <nop,nop,timestamp 615323432 86477980> 10:31:13.193828 IP (tos 0x0, ttl 64, id 19020, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 708441 win 3072 <nop,nop,timestamp 86477994 615323432> 10:31:13.216789 IP (tos 0x0, ttl 60, id 60447, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 709889:711337(1448) ack 4052 win 2520 <nop,nop,timestamp 615323446 86477994> 10:31:13.216828 IP (tos 0x0, ttl 64, id 19021, offset 0, flags [DF], length: 64) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . 4052:4052(0) ack 708441 win 3072 <nop,nop,timestamp 86478000 615323432,nop,nop,[|tcp]> 10:31:14.778329 IP (tos 0x0, ttl 60, id 60451, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: P 708441:709889(1448) ack 4052 win 2520 <nop,nop,timestamp 615323838 86478000> 10:31:14.778406 IP (tos 0x0, ttl 64, id 19022, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 711337 win 2731 <nop,nop,timestamp 86478390 615323838> 10:31:18.153746 IP (tos 0x0, ttl 60, id 60456, offset 0, flags [DF], length: 1500) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: . 711337:712785(1448) ack 4052 win 2520 <nop,nop,timestamp 615324682 86478390> 10:31:18.153820 IP (tos 0x0, ttl 64, id 19023, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 712785 win 3072 <nop,nop,timestamp 86479234 615324682> 10:31:18.166113 IP (tos 0x0, ttl 60, id 60457, offset 0, flags [DF], length: 995) 10.20.100.30.microsoft-ds > 10.20.200.15.41344: P 712785:713728(943) ack 4052 win 2520 <nop,nop,timestamp 615324686 86479234> 10:31:18.166148 IP (tos 0x0, ttl 64, id 19024, offset 0, flags [DF], length: 52) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: . [tcp sum ok] 4052:4052(0) ack 713728 win 3072 <nop,nop,timestamp 86479237 615324686> 10:31:18.166374 IP (tos 0x0, ttl 64, id 19025, offset 0, flags [DF], length: 111) 10.20.200.15.41344 > 10.20.100.30.microsoft-ds: P 4052:4111(59) ack 713728 win 3072 <nop,nop,timestamp 86479237 615324686> On 10/5/07, James Lamanna <jlamanna@gmail.com> wrote:> Hi, > I've noticed that over a WAN (T1) I'm getting incredibly slow file > copy performance. > Using smbclient on a linux machine on one size of the WAN, > As you can imagine, this makes all of our file shares unusable over the WAN. > It's not an issue with WAN performance, because using scp to transfer > the same file, I get speeds of ~145k/s. > A tcpdump of the file copy of ~2MB file that actually > times out with the following error is up at: > http://emagiccards.com/james/copyfileusingsmbclient.tar.bz2 > > -- Timeout Error -- > > Short read when getting file \Finance\monthly_reports\Aug07.xls. Only > got 967680 bytes. > Error Call timed out: server did not respond after 20000 milliseconds > closing remote file > > -- Scp Results -- > scp root@fs0:/export/data/Finance/Monthly_reports/Aug07.xls . > Aug07.xls 100% 2269KB 174.5KB/s 00:13 > > > -- File server samba config -- > > workgroup = XXXXXXXXX > netbios name = FS0 > enable privileges = yes > server string = FS0 > > log file = /var/log/samba/log.%m > max log size = 50 > #log level = 3 passdb:5 auth:10 > log level = 10 > > hosts allow = 10.20.0.0/16 192.168.0.0/16 127.0.0.0/8 > > map to guest = Bad User > guest account = nobody > security = user > encrypt passwords = yes > smb passwd file = /etc/samba/private/smbpasswd > wins server = 10.20.100.45 > wins support = no > > name resolve order = wins lmhosts host bcast > wins support = no > dns proxy = no > > use sendfile = yes > max xmit = 16644 > socket options = IPTOS_LOWDELAY TCP_NODELAY SO_SNDBUF=8192 > interfaces = lo eth1 > > hide unreadable = yes > hide dot files = yes > > [TTData] > path = /export/data > browseable = yes > writeable = yes > default case = lower > preserve case = yes > show preserve case = yes > case sensitive = no > write list = @"Domain Users" @root > create mask = 0775 > directory mask = 0775 > oplocks = no > level2 oplocks = no >