[Samba] Saving files with MS Word to samba3 server is very slow!
Andreas Haumer
andreas at xss.co.at
Fri Dec 2 08:39:10 GMT 2005
Hi!
Some more infos:
With a samba debug level of 10 I get the following logs
which IMHO are relevant for the problem:
[...]
[2005/12/02 09:12:00, 3] smbd/process.c:switch_message(900)
switch message SMBntcreateX (pid 17354) conn 0x8426cb0
[2005/12/02 09:12:00, 4] smbd/uid.c:change_to_user(217)
change_to_user: Skipping user change - already user
[2005/12/02 09:12:00, 10] smbd/nttrans.c:reply_ntcreate_and_X(506)
reply_ntcreateX: flags = 0x6, access_mask = 0x20181 file_attributes = 0x80,
share_access = 0x7, create_disposition = 0x1 create_options = 0x140 root_dir_fid
= 0x0
[2005/12/02 09:12:00, 5] smbd/filename.c:unix_convert(108)
unix_convert called on file "test/~WRD1676.tmp"
[2005/12/02 09:12:00, 10] smbd/statcache.c:stat_cache_lookup(248)
stat_cache_lookup: lookup succeeded for name [TEST/~WRD1676.TMP] ->
[test/~WRD1676.tmp]
[2005/12/02 09:12:00, 3] smbd/dosmode.c:unix_mode(121)
unix_mode(test/~WRD1676.tmp) returning 0744
[2005/12/02 09:12:00, 10] smbd/open.c:open_file_ntcreate(1236)
open_file_ntcreate: fname=test/~WRD1676.tmp, dos_attrs=0x80
access_mask=0x20181 share_access=0x7 create_disposition = 0x1
create_options=0x140 unix mode=0744 oplock_request=3
[2005/12/02 09:12:00, 8] smbd/dosmode.c:dos_mode(294)
dos_mode: test/~WRD1676.tmp
[2005/12/02 09:12:00, 8] smbd/dosmode.c:dos_mode_from_sbuf(162)
dos_mode_from_sbuf returning a
[2005/12/02 09:12:00, 8] smbd/dosmode.c:dos_mode(328)
dos_mode returning a
[2005/12/02 09:12:00, 10] smbd/open.c:open_file_ntcreate(1409)
open_file_ntcreate: fname=test/~WRD1676.tmp, after mapping access_mask=0x20181
[2005/12/02 09:12:00, 5] smbd/files.c:file_new(139)
allocated file structure 7559, fnum = 11655 (2 used)
[2005/12/02 09:12:00, 10] locking/locking.c:get_share_modes(491)
get_share_modes: delete_on_close: 0
[2005/12/02 09:12:00, 10] locking/locking.c:get_share_modes(516)
get_share_modes: share_mode_entry[0]: pid = 17354, share_access = 0x0,
private_options = 0x40, access_mask = 0x2019f, port = 0x0, type= 0x0, file_id =
1, dev = 0x3a0b, inode = 134217858
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(409)
share_conflict: entry->access_mask = 0x2019f, entry->share_access = 0x0,
entry->private_options = 0x40
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(412)
share_conflict: access_mask = 0x20181, share_access = 0x7
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(463)
share_conflict: [1] am (0x2019f) & right (0x6) = 0x6
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(463)
share_conflict: [1] sa (0x7) & share (0x2) = 0x2
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(465)
share_conflict: [2] am (0x20181) & right (0x6) = 0x0
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(465)
share_conflict: [2] sa (0x0) & share (0x2) = 0x0
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(468)
share_conflict: [3] am (0x2019f) & right (0x21) = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(468)
share_conflict: [3] sa (0x7) & share (0x1) = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(470)
share_conflict: [4] am (0x20181) & right (0x21) = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(470)
share_conflict: [4] sa (0x0) & share (0x1) = 0x0
[2005/12/02 09:12:00, 10] smbd/open.c:share_conflict(470)
share_conflict: check 4 conflict am = 0x20181, right = 0x21, sa = 0x0, share = 0x1
[2005/12/02 09:12:00, 10] smbd/open.c:fd_open(55)
fd_open: name test/~WRD1676.tmp, flags = 00 mode = 0744, fd = 30.
[2005/12/02 09:12:00, 2] smbd/open.c:open_file(372)
wunderli opened file test/~WRD1676.tmp read=Yes write=No (numopen=2)
[2005/12/02 09:12:00, 4] smbd/open.c:open_file_ntcreate(1526)
open_file_ntcreate : share_mode deny - calling open_file with flags=0x0
flags2=0x0 mode=0744 returned 1
[2005/12/02 09:12:00, 10] smbd/open.c:defer_open_sharing_error(873)
defer_open_sharing_error: time [1133511120.559863] adding deferred open entry
for mid 3584, file test/~WRD1676.tmp
[2005/12/02 09:12:00, 10]
smbd/process.c:push_sharing_violation_open_smb_message(275)
push_sharing_violation_open_smb_message: pushing message len 126 mid 3584
timeout time [1133511121.509863]
[2005/12/02 09:12:00, 10] smbd/process.c:push_queued_message(131)
push_message: pushed message length 126 on queue smb_sharing_violation_queue
[2005/12/02 09:12:00, 10] locking/locking.c:add_deferred_open(1224)
add_deferred_open: creating entry for file test/~WRD1676.tmp.
num_deferred_open_entries = 1
[2005/12/02 09:12:00, 10] locking/locking.c:print_deferred_open_table(976)
print_deferred_open_table: deferred_open_entry[0]: pid = 17354, mid = 3584,
dev = 0x3a0b, inode = 134217858, port = 33113, time = [1133511120.559863]
[2005/12/02 09:12:00, 5] smbd/files.c:file_free(459)
freed files structure 11655 (1 used)
[2005/12/02 09:12:00, 10] smbd/process.c:receive_message_or_smb(403)
receive_message_or_smb: select with timeout of [0.949586]
[2005/12/02 09:12:01, 3] smbd/sec_ctx.c:set_sec_ctx(288)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_nt_user_token(452)
NT user token: (NULL)
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_unix_user_token(473)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2005/12/02 09:12:01, 5] smbd/uid.c:change_to_root_user(319)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/12/02 09:12:01, 10] smbd/process.c:receive_message_or_smb(403)
receive_message_or_smb: select with timeout of [0.003326]
[2005/12/02 09:12:01, 3] smbd/sec_ctx.c:set_sec_ctx(288)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_nt_user_token(452)
NT user token: (NULL)
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_unix_user_token(473)
UNIX token of user 0
Primary group is 0 and contains 0 supplementary groups
[2005/12/02 09:12:01, 5] smbd/uid.c:change_to_root_user(319)
change_to_root_user: now uid=(0,0) gid=(0,0)
[2005/12/02 09:12:01, 10] smbd/process.c:receive_message_or_smb(396)
receive_message_or_smb: queued message timed out.
[2005/12/02 09:12:01, 5] smbd/process.c:receive_message_or_smb(412)
receive_message_or_smb: returning deferred open smb message.
[2005/12/02 09:12:01, 6] smbd/process.c:process_smb(1113)
got message type 0x0 of len 0x7a
[2005/12/02 09:12:01, 3] smbd/process.c:process_smb(1114)
Transaction 60 of length 126
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(454)
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(464)
size=122
smb_com=0xa2
smb_rcls=0
smb_reh=0
smb_err=0
smb_flg=24
smb_flg2=32771
smb_tid=2
smb_pid=56576
smb_uid=101
smb_mid=3584
smt_wct=24
smb_vwv[ 0]= 255 (0xFF)
smb_vwv[ 1]= 0 (0x0)
smb_vwv[ 2]= 9216 (0x2400)
smb_vwv[ 3]= 1536 (0x600)
smb_vwv[ 4]= 0 (0x0)
smb_vwv[ 5]= 0 (0x0)
smb_vwv[ 6]= 0 (0x0)
smb_vwv[ 7]=33024 (0x8100)
smb_vwv[ 8]= 513 (0x201)
smb_vwv[ 9]= 0 (0x0)
smb_vwv[10]= 0 (0x0)
smb_vwv[11]= 0 (0x0)
smb_vwv[12]= 0 (0x0)
smb_vwv[13]=32768 (0x8000)
smb_vwv[14]= 0 (0x0)
smb_vwv[15]= 1792 (0x700)
smb_vwv[16]= 0 (0x0)
smb_vwv[17]= 256 (0x100)
smb_vwv[18]= 0 (0x0)
smb_vwv[19]=16384 (0x4000)
smb_vwv[20]= 1 (0x1)
smb_vwv[21]= 512 (0x200)
smb_vwv[22]= 0 (0x0)
smb_vwv[23]= 0 (0x0)
smb_bcc=39
[2005/12/02 09:12:01, 10] lib/util.c:dump_data(2053)
[000] DD 5C 00 74 00 65 00 73 00 74 00 5C 00 7E 00 57 .\.t.e.s .t.\.~.W
[010] 00 52 00 44 00 31 00 36 00 37 00 36 00 2E 00 74 .R.D.1.6 .7.6...t
[020] 00 6D 00 70 00 00 00 .m.p...
[2005/12/02 09:12:01, 3] smbd/process.c:switch_message(900)
switch message SMBntcreateX (pid 17354) conn 0x8426cb0
[2005/12/02 09:12:01, 3] smbd/sec_ctx.c:set_sec_ctx(288)
setting sec ctx (5602, 5600) - sec_ctx_stack_ndx = 0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_nt_user_token(457)
NT user token of user S-1-5-21-4201010128-2403562230-48780307-12204
contains 10 SIDs
SID[ 0]: S-1-5-21-4201010128-2403562230-48780307-12204
SID[ 1]: S-1-5-21-4201010128-2403562230-48780307-12201
SID[ 2]: S-1-1-0
SID[ 3]: S-1-5-2
SID[ 4]: S-1-5-11
SID[ 5]: S-1-5-21-4201010128-2403562230-48780307-544
SID[ 6]: S-1-5-21-4201010128-2403562230-48780307-2985
SID[ 7]: S-1-5-21-4201010128-2403562230-48780307-12001
SID[ 8]: S-1-5-21-4201010128-2403562230-48780307-12203
SID[ 9]: S-1-5-21-4201010128-2403562230-48780307-12601
SE_PRIV 0x0 0x0 0x0 0x0
[2005/12/02 09:12:01, 5] auth/auth_util.c:debug_unix_user_token(473)
UNIX token of user 5602
Primary group is 5600 and contains 6 supplementary groups
Group[ 0]: 5600
Group[ 1]: 544
Group[ 2]: 992
Group[ 3]: 5500
Group[ 4]: 5601
Group[ 5]: 5800
[2005/12/02 09:12:01, 5] smbd/uid.c:change_to_user(304)
change_to_user uid=(5602,5602) gid=(0,5600)
[2005/12/02 09:12:01, 10] smbd/nttrans.c:reply_ntcreate_and_X(506)
reply_ntcreateX: flags = 0x6, access_mask = 0x20181 file_attributes = 0x80,
share_access = 0x7, create_disposition = 0x1 create_options = 0x140 root_dir_fid
= 0x0
[2005/12/02 09:12:01, 5] smbd/filename.c:unix_convert(108)
unix_convert called on file "test/~WRD1676.tmp"
[2005/12/02 09:12:01, 10] smbd/statcache.c:stat_cache_lookup(248)
stat_cache_lookup: lookup succeeded for name [TEST/~WRD1676.TMP] ->
[test/~WRD1676.tmp]
[2005/12/02 09:12:01, 3] smbd/dosmode.c:unix_mode(121)
unix_mode(test/~WRD1676.tmp) returning 0744
[2005/12/02 09:12:01, 10] smbd/open.c:open_file_ntcreate(1236)
open_file_ntcreate: fname=test/~WRD1676.tmp, dos_attrs=0x80
access_mask=0x20181 share_access=0x7 create_disposition = 0x1
create_options=0x140 unix mode=0744 oplock_request=3
[2005/12/02 09:12:01, 10]
smbd/process.c:remove_sharing_violation_open_smb_message(166)
remove_sharing_violation_open_smb_message: deleting mid 3584 len 126
[2005/12/02 09:12:01, 10] locking/locking.c:get_deferred_opens(1044)
get_deferred_opens: deferred_open_entry[0]: pid = 17354, mid = 3584, dev =
0x3a0b, inode = 134217858, port = 33113, time = [1133511120.559863]
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1136)
delete_deferred_open_entry: num_deferred_open_entries = 1
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1141)
delete_deferred_open_entry: deleted deferred_open_entry[0]: pid = 17354, mid =
3584, dev = 0x3a0b, inode = 134217858, port = 33113, time = [1133511120.559863]
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1150)
delete_deferred_open_entry: deleting entry 0
[2005/12/02 09:12:01, 10] locking/locking.c:delete_deferred_open_entry(1172)
delete_deferred_open_entry: Remaining table.
[2005/12/02 09:12:01, 10] smbd/trans2.c:set_bad_path_error(2583)
set_bad_path_error: err = 2 bad_path = 0
[2005/12/02 09:12:01, 3] smbd/error.c:error_packet(147)
error packet at smbd/trans2.c(2589) cmd=162 (SMBntcreateX)
NT_STATUS_SHARING_VIOLATION
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(454)
[2005/12/02 09:12:01, 5] lib/util.c:show_msg(464)
size=35
smb_com=0xa2
smb_rcls=67
smb_reh=0
smb_err=49152
smb_flg=136
smb_flg2=49153
smb_tid=2
smb_pid=56576
smb_uid=101
smb_mid=3584
smt_wct=0
smb_bcc=0
[2005/12/02 09:12:01, 10] lib/util_sock.c:read_smb_length_return_keepalive(615)
[...]
Here you can see the "receive_message_or_smb: select with timeout of [0.949586]"
message. The whole pattern repeats 19 times when saving an empty Word file.
If I set "share modes = no" for the smaba share in question, saving the
Word file is completed almost instantly! But this is IMHO not a real solution
as I think we can not live without this feature.
Does this ring a bell? Anyone?
- andreas
-------------------------------------------------
This mail sent through IMP: http://horde.org/imp/
More information about the samba
mailing list