[Samba] Re: Very slow file copy performance over a WAN (HELP)
James Lamanna
jlamanna at gmail.com
Sat Oct 6 17:43:22 GMT 2007
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