[Samba] Re: Very slow file copy performance over a WAN (HELP)
James Lamanna
jlamanna at gmail.com
Sat Oct 6 17:52:46 GMT 2007
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
> >
>
More information about the samba
mailing list