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 <[EMAIL PROTECTED]> 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 [EMAIL PROTECTED]:/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 > -- To unsubscribe from this list go to the following URL and read the instructions: https://lists.samba.org/mailman/listinfo/samba