[Samba] Re: Very slow file copy performance over a WAN (HELP)

Sat Oct 6 19:09:33 GMT 2007

Locking does not appear to be the problem.
Testing with:

kernel oplocks = no
posix locking = no

has no affect.
So I'm pretty much dead in the water here.
How do people serve files to Windows clients over a WAN?

-- James

On 10/6/07, James Lamanna <jlamanna at gmail.com> wrote:
> So, after watching the TCPDump output, I've noticed the following issue:
> The transfer will start, and cruise along for a while, then it will
> pause for several seconds after the client has sent an ack. So for
> some reason, there is a huge delay in getting the next packet to send.
> Is this a locking problem? Oplocks are all off.
>
> -- James
>
> On 10/6/07, James Lamanna <jlamanna at gmail.com> wrote:
> > 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 at 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 at 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
> > >
> >
>