[Samba] ArcView + Samba: Performance nightmare under Linux,ok
under Solaris or HP-UX
Andreas Haumer
andreas at xss.co.at
Tue Jul 11 11:13:19 GMT 2006
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Hi Tobias,
thank you for reply!
Tobias Bluhm schrieb:
> Another shot in the dark . . . .
>
> and I don't believe you've stated what fs type your using, but have you
> tried storing the data using other fs types or playing with the mount
> options?
For the Linux server, I have tested with the following filesystems:
*) ext2
*) ext3
*) reiserfs
*) xfs
In my tests, all filesystems were mounted with standard
mount-options:
mount -t <fstype> /dev/data/test /mountpoint
On the kernel 2.4 based systems I did not use enhanced
features like ACL or XATTR. On the kernel 2.6 based system
(SuSE Linux) I did also test with an ACL and XATTR enabled
reiserfs.
None of my tests with these different filesystem types
showed any significant application performance difference.
With all of these different filesystems I get the same strange
file access pattern.
The data files are not very big: the whole share has about
250MB of size and the files which take longest to load
(e.g. "arc.adf" or "pal.adf") are about 2MB of size, each.
Under Solaris, all these files are loaded by the application
in about 12 seconds alltogether: the application loads them
with a blocksize of 4K, block by block sequentially. There is
a short peak in filesystem I/O and network traffic when files
are loaded from the Solaris server by the application.
With the various Linux samba servers, the same action
takes several minutes: the applications reads the files
with a blocksize of 512 Bytes and seems to read each
single block several times, not sequentially but
intermixed with other blocks like this:
[...]
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1536, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 2048, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1536, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1024, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 2048, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1536, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1024, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 2048, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1024, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 2048, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1024, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 2048, size = 512, returned 512
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 1536, size = 512, returned 512
[...]
I can see very low filesystem I/O (about 40kB/s) and some network
traffic (a few 100kB/s, but that's a rough estimation from what I
can see with tcpdump) between the windows client and the Linux
server, but that goes on for several minutes.
Note: it's the _application_ (Windows XP + ArcView) which does
request the files in that strange way. You can see that if you
look at the SMB read request messages in the samba logfiles.
Example:
[...]
[2006/07/10 11:28:25, 10] smbd/process.c:setup_select_timeout(1372)
change_notify_timeout: -1
[2006/07/10 11:28:25, 10] smbd/process.c:run_events(299)
run_events: No events
[2006/07/10 11:28:25, 10] lib/util_sock.c:read_smb_length_return_keepalive(618)
got smb length of 59
[2006/07/10 11:28:25, 6] smbd/process.c:process_smb(1193)
got message type 0x0 of len 0x3b
[2006/07/10 11:28:25, 3] smbd/process.c:process_smb(1194)
Transaction 3815 of length 63
[2006/07/10 11:28:25, 5] lib/util.c:show_msg(454)
[2006/07/10 11:28:25, 5] lib/util.c:show_msg(464)
size=59
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=24
smb_flg2=51207
smb_tid=2
smb_pid=65279
smb_uid=105
smb_mid=44611
smt_wct=12
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]=57054 (0xDEDE)
smb_vwv[ 2]= 6251 (0x186B)
smb_vwv[ 3]=53248 (0xD000)
smb_vwv[ 4]= 0 (0x0)
smb_vwv[ 5]= 512 (0x200)
smb_vwv[ 6]= 512 (0x200)
smb_vwv[ 7]= 0 (0x0)
smb_vwv[ 8]= 0 (0x0)
smb_vwv[ 9]= 512 (0x200)
smb_vwv[10]= 0 (0x0)
smb_vwv[11]= 0 (0x0)
smb_bcc=0
[2006/07/10 11:28:25, 3] smbd/process.c:switch_message(993)
switch message SMBreadX (pid 2689) conn 0x844ae08
[2006/07/10 11:28:25, 4] smbd/uid.c:change_to_user(222)
change_to_user: Skipping user change - already user
[2006/07/10 11:28:25, 10] locking/locking.c:is_locked(109)
is_locked: brl start=53248 len=512 unlocked for file daten/covers/dhm_offset/o1000c/arc.adf
[2006/07/10 11:28:25, 10] locking/posix.c:is_posix_locked(706)
is_posix_locked: File daten/covers/dhm_offset/o1000c/arc.adf, offset = 53248, count = 512, type = READ
[2006/07/10 11:28:25, 10] locking/posix.c:posix_lock_in_range(642)
posix_lock_in_range: offset_out = 53248, count_out = 512
[2006/07/10 11:28:25, 8] locking/posix.c:posix_fcntl_lock(659)
posix_fcntl_lock 33 12 53248 512 0
[2006/07/10 11:28:25, 8] lib/util.c:fcntl_lock(1820)
fcntl_lock 33 12 53248 512 0
[2006/07/10 11:28:25, 8] locking/posix.c:posix_fcntl_lock(689)
posix_fcntl_lock: Lock call failed
[2006/07/10 11:28:25, 10] locking/locking.c:is_locked(121)
is_locked: posix start=53248 len=512 unlocked for file daten/covers/dhm_offset/o1000c/arc.adf
[2006/07/10 11:28:25, 10] smbd/aio.c:schedule_aio_read_and_X(213)
schedule_aio_read_and_X: read size (512) too small for minimum aio_read of 0
[2006/07/10 11:28:25, 10] smbd/fileio.c:read_file(105)
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 53248, size = 512, returned 512
[2006/07/10 11:28:25, 3] smbd/reply.c:send_file_readX(2613)
send_file_readX fnum=6251 max=512 nread=512
[2006/07/10 11:28:25, 5] lib/util.c:show_msg(454)
[2006/07/10 11:28:25, 5] lib/util.c:show_msg(464)
size=571
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=136
smb_flg2=51201
smb_tid=2
smb_pid=65279
smb_uid=105
smb_mid=44611
smt_wct=12
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]= 0 (0x0)
smb_vwv[ 2]=65535 (0xFFFF)
smb_vwv[ 3]= 0 (0x0)
smb_vwv[ 4]= 0 (0x0)
smb_vwv[ 5]= 512 (0x200)
smb_vwv[ 6]= 59 (0x3B)
smb_vwv[ 7]= 0 (0x0)
smb_vwv[ 8]= 0 (0x0)
smb_vwv[ 9]= 0 (0x0)
smb_vwv[10]= 0 (0x0)
smb_vwv[11]= 0 (0x0)
smb_bcc=512
[2006/07/10 11:28:25, 10] lib/util.c:dump_data(2058)
[000] 00 00 02 51 00 00 02 22 00 00 01 F4 00 00 01 F5 ...Q..." ........
[010] 00 00 00 02 4A 57 45 60 4A AE 12 80 4A 57 45 60 ....JWE` J...JWE`
[020] 4A AE 1A 50 00 00 04 42 00 00 00 14 00 00 5A 8B J..P...B ......Z.
[030] 00 00 02 51 00 00 02 50 00 00 02 1F 00 00 01 F4 ...Q...P ........
[040] 00 00 00 02 4A 57 45 60 4A AE 12 80 4A 57 35 C0 ....JWE` J...JW5.
[050] 4A AE 12 80 00 00 04 43 00 00 00 14 00 00 5A C4 J......C ......Z.
[060] 00 00 02 52 00 00 02 23 00 00 01 F5 00 00 01 F6 ...R...# ........
[070] 00 00 00 02 4A 57 55 00 4A AE 12 80 4A 57 55 00 ....JWU. J...JWU.
[080] 4A AE 1A 50 00 00 04 44 00 00 00 14 00 00 5A 8C J..P...D ......Z.
[090] 00 00 02 52 00 00 02 51 00 00 02 20 00 00 01 F5 ...R...Q ... ....
[0A0] 00 00 00 02 4A 57 55 00 4A AE 12 80 4A 57 45 60 ....JWU. J...JWE`
[0B0] 4A AE 12 80 00 00 04 45 00 00 00 14 00 00 5A C5 J......E ......Z.
[0C0] 00 00 02 53 00 00 02 24 00 00 01 F6 00 00 01 F7 ...S...$ ........
[0D0] 00 00 00 02 4A 57 64 A0 4A AE 12 80 4A 57 64 A0 ....JWd. J...JWd.
[0E0] 4A AE 1A 50 00 00 04 46 00 00 00 14 00 00 5A 8D J..P...F ......Z.
[0F0] 00 00 02 53 00 00 02 52 00 00 02 21 00 00 01 F6 ...S...R ...!....
[100] 00 00 00 02 4A 57 64 A0 4A AE 12 80 4A 57 55 00 ....JWd. J...JWU.
[110] 4A AE 12 80 00 00 04 47 00 00 00 14 00 00 5A C6 J......G ......Z.
[120] 00 00 02 54 00 00 02 25 00 00 01 F7 00 00 01 F8 ...T...% ........
[130] 00 00 00 02 4A 57 74 40 4A AE 12 80 4A 57 74 40 ....JWt@ J...JWt@
[140] 4A AE 1A 50 00 00 04 48 00 00 00 14 00 00 5A 8E J..P...H ......Z.
[150] 00 00 02 54 00 00 02 53 00 00 02 22 00 00 01 F7 ...T...S ..."....
[160] 00 00 00 02 4A 57 74 40 4A AE 12 80 4A 57 64 A0 ....JWt@ J...JWd.
[170] 4A AE 12 80 00 00 04 49 00 00 00 14 00 00 5A C7 J......I ......Z.
[180] 00 00 02 55 00 00 02 26 00 00 01 F8 00 00 01 F9 ...U...& ........
[190] 00 00 00 02 4A 57 83 E0 4A AE 12 80 4A 57 83 E0 ....JW.. J...JW..
[1A0] 4A AE 1A 50 00 00 04 4A 00 00 00 14 00 00 5A 8F J..P...J ......Z.
[1B0] 00 00 02 55 00 00 02 54 00 00 02 23 00 00 01 F8 ...U...T ...#....
[1C0] 00 00 00 02 4A 57 83 E0 4A AE 12 80 4A 57 74 40 ....JW.. J...JWt@
[1D0] 4A AE 12 80 00 00 04 4B 00 00 00 14 00 00 5A C8 J......K ......Z.
[1E0] 00 00 02 56 00 00 02 27 00 00 01 F9 00 00 01 FA ...V...' ........
[1F0] 00 00 00 02 4A 57 93 80 4A AE 12 80 4A 57 93 80 ....JW.. J...JW..
[...]
Under Solaris, it looks like this (same file, same file offset 53248,
but different blocksize):
[...]
[2006/06/21 04:16:44, 10] smbd/process.c:setup_select_timeout(1372)
change_notify_timeout: 60
[2006/06/21 04:16:44, 10] smbd/process.c:run_events(299)
run_events: No events
[2006/06/21 04:16:44, 10] lib/util_sock.c:read_smb_length_return_keepalive(618)
got smb length of 59
[2006/06/21 04:16:44, 6] smbd/process.c:process_smb(1193)
got message type 0x0 of len 0x3b
[2006/06/21 04:16:44, 3] smbd/process.c:process_smb(1194)
Transaction 8834 of length 63
[2006/06/21 04:16:44, 5] lib/util.c:show_msg(454)
[2006/06/21 04:16:44, 5] lib/util.c:show_msg(464)
size=59
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=24
smb_flg2=59399
smb_tid=2
smb_pid=65279
smb_uid=104
smb_mid=33090
smt_wct=12
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]=57054 (0xDEDE)
smb_vwv[ 2]= 8303 (0x206F)
smb_vwv[ 3]=53248 (0xD000)
smb_vwv[ 4]= 0 (0x0)
smb_vwv[ 5]= 4096 (0x1000)
smb_vwv[ 6]= 4096 (0x1000)
smb_vwv[ 7]= 0 (0x0)
smb_vwv[ 8]= 0 (0x0)
smb_vwv[ 9]= 4096 (0x1000)
smb_vwv[10]= 0 (0x0)
smb_vwv[11]= 0 (0x0)
smb_bcc=0
[2006/06/21 04:16:44, 3] smbd/process.c:switch_message(993)
switch message SMBreadX (pid 25093) conn 0x8350a28
[2006/06/21 04:16:44, 4] smbd/uid.c:change_to_user(222)
change_to_user: Skipping user change - already user
[2006/06/21 04:16:44, 10] locking/locking.c:is_locked(109)
is_locked: brl start=53248 len=4096 unlocked for file daten/covers/dhm_offset/o1000c/arc.adf
[2006/06/21 04:16:44, 10] locking/posix.c:is_posix_locked(706)
is_posix_locked: File daten/covers/dhm_offset/o1000c/arc.adf, offset = 53248, count = 4096, type = WRITE
[2006/06/21 04:16:44, 10] locking/posix.c:posix_lock_in_range(642)
posix_lock_in_range: offset_out = 53248, count_out = 4096
[2006/06/21 04:16:44, 8] locking/posix.c:posix_fcntl_lock(659)
posix_fcntl_lock 27 33 53248 4096 1
[2006/06/21 04:16:44, 8] lib/util.c:fcntl_lock(1820)
fcntl_lock 27 33 53248 4096 1
[2006/06/21 04:16:44, 8] locking/posix.c:posix_fcntl_lock(689)
posix_fcntl_lock: Lock call failed
[2006/06/21 04:16:44, 10] locking/locking.c:is_locked(121)
is_locked: posix start=53248 len=4096 unlocked for file daten/covers/dhm_offset/o1000c/arc.adf
[2006/06/21 04:16:44, 10] smbd/fileio.c:read_file(105)
read_file (daten/covers/dhm_offset/o1000c/arc.adf): pos = 53248, size = 4096, returned 4096
[2006/06/21 04:16:44, 3] smbd/reply.c:send_file_readX(2613)
send_file_readX fnum=8303 max=4096 nread=4096
[2006/06/21 04:16:44, 5] lib/util.c:show_msg(454)
[2006/06/21 04:16:44, 5] lib/util.c:show_msg(464)
size=4155
smb_com=0x2e
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=136
smb_flg2=51201
smb_tid=2
smb_pid=65279
smb_uid=104
smb_mid=33090
smt_wct=12
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]= 0 (0x0)
smb_vwv[ 2]=65535 (0xFFFF)
smb_vwv[ 3]= 0 (0x0)
smb_vwv[ 4]= 0 (0x0)
smb_vwv[ 5]= 4096 (0x1000)
smb_vwv[ 6]= 59 (0x3B)
smb_vwv[ 7]= 0 (0x0)
smb_vwv[ 8]= 0 (0x0)
smb_vwv[ 9]= 0 (0x0)
smb_vwv[10]= 0 (0x0)
smb_vwv[11]= 0 (0x0)
smb_bcc=4096
[2006/06/21 04:16:44, 10] lib/util.c:dump_data(2058)
[000] 00 00 02 51 00 00 02 22 00 00 01 F4 00 00 01 F5 ...Q..." ........
[010] 00 00 00 02 4A 57 45 60 4A AE 12 80 4A 57 45 60 ....JWE` J...JWE`
[020] 4A AE 1A 50 00 00 04 42 00 00 00 14 00 00 5A 8B J..P...B ......Z.
[030] 00 00 02 51 00 00 02 50 00 00 02 1F 00 00 01 F4 ...Q...P ........
[040] 00 00 00 02 4A 57 45 60 4A AE 12 80 4A 57 35 C0 ....JWE` J...JW5.
[050] 4A AE 12 80 00 00 04 43 00 00 00 14 00 00 5A C4 J......C ......Z.
[060] 00 00 02 52 00 00 02 23 00 00 01 F5 00 00 01 F6 ...R...# ........
[070] 00 00 00 02 4A 57 55 00 4A AE 12 80 4A 57 55 00 ....JWU. J...JWU.
[080] 4A AE 1A 50 00 00 04 44 00 00 00 14 00 00 5A 8C J..P...D ......Z.
[090] 00 00 02 52 00 00 02 51 00 00 02 20 00 00 01 F5 ...R...Q ... ....
[0A0] 00 00 00 02 4A 57 55 00 4A AE 12 80 4A 57 45 60 ....JWU. J...JWE`
[0B0] 4A AE 12 80 00 00 04 45 00 00 00 14 00 00 5A C5 J......E ......Z.
[0C0] 00 00 02 53 00 00 02 24 00 00 01 F6 00 00 01 F7 ...S...$ ........
[0D0] 00 00 00 02 4A 57 64 A0 4A AE 12 80 4A 57 64 A0 ....JWd. J...JWd.
[0E0] 4A AE 1A 50 00 00 04 46 00 00 00 14 00 00 5A 8D J..P...F ......Z.
[0F0] 00 00 02 53 00 00 02 52 00 00 02 21 00 00 01 F6 ...S...R ...!....
[100] 00 00 00 02 4A 57 64 A0 4A AE 12 80 4A 57 55 00 ....JWd. J...JWU.
[110] 4A AE 12 80 00 00 04 47 00 00 00 14 00 00 5A C6 J......G ......Z.
[120] 00 00 02 54 00 00 02 25 00 00 01 F7 00 00 01 F8 ...T...% ........
[130] 00 00 00 02 4A 57 74 40 4A AE 12 80 4A 57 74 40 ....JWt@ J...JWt@
[140] 4A AE 1A 50 00 00 04 48 00 00 00 14 00 00 5A 8E J..P...H ......Z.
[150] 00 00 02 54 00 00 02 53 00 00 02 22 00 00 01 F7 ...T...S ..."....
[160] 00 00 00 02 4A 57 74 40 4A AE 12 80 4A 57 64 A0 ....JWt@ J...JWd.
[170] 4A AE 12 80 00 00 04 49 00 00 00 14 00 00 5A C7 J......I ......Z.
[180] 00 00 02 55 00 00 02 26 00 00 01 F8 00 00 01 F9 ...U...& ........
[190] 00 00 00 02 4A 57 83 E0 4A AE 12 80 4A 57 83 E0 ....JW.. J...JW..
[1A0] 4A AE 1A 50 00 00 04 4A 00 00 00 14 00 00 5A 8F J..P...J ......Z.
[1B0] 00 00 02 55 00 00 02 54 00 00 02 23 00 00 01 F8 ...U...T ...#....
[1C0] 00 00 00 02 4A 57 83 E0 4A AE 12 80 4A 57 74 40 ....JW.. J...JWt@
[1D0] 4A AE 12 80 00 00 04 4B 00 00 00 14 00 00 5A C8 J......K ......Z.
[1E0] 00 00 02 56 00 00 02 27 00 00 01 F9 00 00 01 FA ...V...' ........
[1F0] 00 00 00 02 4A 57 93 80 4A AE 12 80 4A 57 93 80 ....JW.. J...JW..
[...]
Note the difference:
* read blocksize (Linux = 512, Solaris = 4096)
* locking count (Linux = 512, Solaris = 4096)
* locking type (Linux = READ, Solaris = WRITE)
* Under Linux, there is a "schedule_aio_read_and_X" error message,
which is missing under Solaris
Can anyone explain these differences?
The main question IMHO still ist: why does the application
request the files differently when changing the Samba server
operating system (and the Samba servers itself are configured
identically)?
IMHO the client shouldn't even know the server's operating system,
should it?
Is there some sort of handshake between SMB server and client
which tells the client how to read the files? What could lead
to different results in such a handshake which then could explain
the symptoms? Operating system functionality?
Any ideas, anyone?
- - andreas
- --
Andreas Haumer | mailto:andreas at xss.co.at
*x Software + Systeme | http://www.xss.co.at/
Karmarschgasse 51/2/20 | Tel: +43-1-6060114-0
A-1100 Vienna, Austria | Fax: +43-1-6060114-71
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.3 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org
iD8DBQFEs4fLxJmyeGcXPhERAoK7AKCWlXYpT8BdWR7GNaCR5crZpnQR7wCgsAB0
E7Laofi5zKAK1dbl1O1pAFI=
=2LVN
-----END PGP SIGNATURE-----
More information about the samba
mailing list