Alberto Cavaliere
2018-Oct-16 14:26 UTC
[Samba] high cpu load with share_conflict on browsing and opening files
Hello,
I have a server running samba version 4.7.1 on centos 7.5
1) A series of operations by a windows 10 (up to date) pc client consisting
of searching (or browsing)/opening/modifying/closing a (each time
different) file multiple times on a samba share containing many files (more
than 11000) goes fast for a while.
2) Then the same operation (or just the searching or opening) of the same
user on the same pc on the same dir gets very very slow (up to a minute) and
the cpu of the pid samba process serving the user stays over the 60% load.
3) Restarting the pc client doesnt resolve the problem because it gets
always served by the same (high cpu load) samba pid.
4) The same operations on a different pc (by the same user or not, doesnt
matter) are fast as long a they are served by a different samba process
(otherwise is just as slow).
5) Restarting samba makes the problem go away for a short while, depending
on how many operations described in 1) are made.
Please can sameone give some pointers on why this is happens?
Thanks a lot (I'm in a very tight spot because of this)
--------------------------------------
Smb.conf:
client ipc signing = auto
oplocks=no
level2 oplocks=no
deadtime=30
hide dot files=yes
hide unreadable=yes
unix password sync = no
load printers = no
show add printer wizard = no
printing = bsd
printcap name = /dev/null
disable spoolss = yes
server string=xxx
netbios name = xxx
domain master = yes
local master = yes
preferred master = yes
os level = 65
workgroup=server
server role = standalone server
security = user
log level = 3
log file = /var/log/samba/log.%m
-------------------------------------
Here a little bit of samba logs:
[2018/10/12 12:05:09.532810, 1, pid=3350, effective(1017, 1003), real(1017,
0)] ../librpc/ndr/ndr.c:419(ndr_print_debug)
&open_blob: struct smbXsrv_openB
version : SMBXSRV_VERSION_0 (0)
reserved : 0x00000000 (0)
info : union smbXsrv_openU(case 0)
info0 : *
info0: struct smbXsrv_open
table : *
db_rec : NULL
local_id : 0xdb0729c7 (3674679751)
global : *
global: struct smbXsrv_open_global0
db_rec : NULL
server_id: struct server_id
pid : 0x0000000000000d16
(3350)
task_id : 0x00000000 (0)
vnn : 0xffffffff
(4294967295)
unique_id : 0x304715b8633d5fa0
(3478773118850129824)
open_global_id : 0xb62ba247 (3056312903)
open_persistent_id : 0x00000000b62ba247
(3056312903)
open_volatile_id : 0x00000000db0729c7
(3674679751)
open_owner :
S-1-5-21-717140398-4153742348-3969525143-1000
open_time : ven ott 12 12:05:10
2018 CEST
create_guid :
00000000-0000-0000-0000-000000000000
client_guid :
10c6dc16-cd61-11e8-8418-c85b76eb6959
app_instance_id :
00000000-0000-0000-0000-000000000000
disconnect_time : NTTIME(0)
durable_timeout_msec : 0x00000000 (0)
durable : 0x00 (0)
backend_cookie : DATA_BLOB length=0
channel_sequence : 0x0000000000000000 (0)
status : NT_STATUS_OK
idle_time : ven ott 12 12:05:10 2018 CEST
compat : NULL
flags : 0x00 (0)
0: SMBXSRV_OPEN_NEED_REPLAY_CACHE
0: SMBXSRV_OPEN_HAVE_REPLAY_CACHE
create_action : 0x00000000 (0)
request_count : 0x0000000000000000 (0)
pre_request_count : 0x0000000000000000 (0)
[2018/10/12 12:05:09.532936, 5, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/files.c:128(file_new)
allocated file structure fnum 3674679751 (4 used)
[2018/10/12 12:05:09.532946, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/files.c:754(file_name_hash)
file_name_hash: /home/quality/. hash 0x264a327
[2018/10/12 12:05:09.532959, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=vfs] ../source3/smbd/vfs.c:1283(check_reduced_name)
check_reduced_name: check_reduced_name [.] [/home/quality]
[2018/10/12 12:05:09.532972, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=vfs] ../source3/smbd/vfs.c:1347(check_reduced_name)
check_reduced_name realpath [.] -> [/home/quality]
[2018/10/12 12:05:09.532981, 5, pid=3350, effective(1017, 1003), real(1017,
0), class=vfs] ../source3/smbd/vfs.c:1458(check_reduced_name)
check_reduced_name: . reduced to /home/quality
[2018/10/12 12:05:09.532992, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:767(fd_open)
fd_open: name ., flags = 0200000 mode = 00, fd = 34.
[2018/10/12 12:05:09.533002, 5, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap.c:160(dbwrap_check_lock_order)
check lock order 1 for /var/lib/samba/lock/locking.tdb
[2018/10/12 12:05:09.533010, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
lock order: 1:/var/lib/samba/lock/locking.tdb 2:<none> 3:<none>
[2018/10/12 12:05:09.533022, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
Locking key 02FD00000000000056000020000000000000000000000000
[2018/10/12 12:05:09.533032, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap_tdb.c:143(db_tdb_fetch_locked_internal)
Allocated locked data 0x0x559d3f4db0d0
[2018/10/12 12:05:09.533042, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=locking]
../source3/locking/share_mode_lock.c:285(share_mode_memcache_fetch)
fetched entry for file . seq 0x1141782026507589052 key fd02:20000056:0
[2018/10/12 12:05:09.533052, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=locking]
../source3/locking/locking.c:1226(find_delete_on_close_token)
find_delete_on_close_token: name_hash = 0x264a327
[2018/10/12 12:05:09.533062, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:1424(share_conflict)
share_conflict: entry->access_mask = 0x100081, entry->share_access =
0x7,
entry->private_options = 0x0
[2018/10/12 12:05:09.533070, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:1435(share_conflict)
share_conflict: access_mask = 0x100081, share_access = 0x7
[2018/10/12 12:05:09.533078, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:1484(share_conflict)
share_conflict: [1] am (0x100081) & right (0x6) = 0x0
.....more of the same.....
[2018/10/12 12:05:09.533293, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:1496(share_conflict)
share_conflict: [6] sa (0x7) & share (0x4) = 0x4
[2018/10/12 12:05:09.533300, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:1498(share_conflict)
share_conflict: No conflict.
[2018/10/12 12:05:09.533308, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=locking]
../source3/locking/share_mode_lock.c:368(unparse_share_modes)
unparse_share_modes:
[2018/10/12 12:05:09.533316, 1, pid=3350, effective(1017, 1003), real(1017,
0)] ../librpc/ndr/ndr.c:419(ndr_print_debug)
d: struct share_mode_data
sequence_number : 0x0fd86cb424e915bc
(1141782026507589052)
servicepath : *
servicepath : '/home/quality'
base_name : *
base_name : '.'
stream_name : NULL
num_share_modes : 0x00000004 (4)
share_modes: ARRAY(4)
share_modes: struct share_mode_entry
pid: struct server_id
pid : 0x0000000000000d16 (3350)
task_id : 0x00000000 (0)
vnn : 0xffffffff (4294967295)
unique_id : 0x304715b8633d5fa0
(3478773118850129824)
op_mid : 0x000000000001bc60 (113760)
op_type : 0x0000 (0)
lease_idx : 0xffffffff (4294967295)
access_mask : 0x00100081 (1048705)
share_access : 0x00000007 (7)
private_options : 0x00000000 (0)
time : ven ott 12 11:46:37 2018
CEST.433056
id: struct file_id
devid : 0x000000000000fd02 (64770)
inode : 0x0000000020000056
(536870998)
extid : 0x0000000000000000 (0)
share_file_id : 0x00000000d7f6c6f8 (3623274232)
uid : 0x000003f9 (1017)
flags : 0x0000 (0)
name_hash : 0x0264a327 (40149799)
stale : 0x00 (0)
lease : NULL
share_modes: struct share_mode_entry
pid: struct server_id
pid : 0x0000000000000c5e (3166)
task_id : 0x00000000 (0)
vnn : 0xffffffff (4294967295)
unique_id : 0xbc127b5a7106df15
(-4894714216624759019)
op_mid : 0x000000000000000a (10)
op_type : 0x0000 (0)
lease_idx : 0xffffffff (4294967295)
access_mask : 0x00100080 (1048704)
share_access : 0x00000007 (7)
private_options : 0x00000000 (0)
time : ven ott 12 10:21:59 2018
CEST.457801
id: struct file_id
devid : 0x000000000000fd02 (64770)
inode : 0x0000000020000056
(536870998)
extid : 0x0000000000000000 (0)
share_file_id : 0x00000000e625a3da (3861226458)
uid : 0x000003f2 (1010)
flags : 0x0000 (0)
name_hash : 0x0264a327 (40149799)
stale : 0x00 (0)
lease : NULL
share_modes: struct share_mode_entry
pid: struct server_id
pid : 0x0000000000001108 (4360)
task_id : 0x00000000 (0)
vnn : 0xffffffff (4294967295)
unique_id : 0xa75ff9d8005604eb
(-6386111040474184469)
op_mid : 0x0000000000000433 (1075)
op_type : 0x0000 (0)
lease_idx : 0xffffffff (4294967295)
access_mask : 0x00100081 (1048705)
share_access : 0x00000007 (7)
private_options : 0x00000000 (0)
time : ven ott 12 11:38:42 2018
CEST.598343
id: struct file_id
devid : 0x000000000000fd02 (64770)
inode : 0x0000000020000056
(536870998)
extid : 0x0000000000000000 (0)
share_file_id : 0x00000000a7ad9652 (2813171282)
uid : 0x000003f4 (1012)
flags : 0x0000 (0)
name_hash : 0x0264a327 (40149799)
stale : 0x00 (0)
lease : NULL
share_modes: struct share_mode_entry
pid: struct server_id
pid : 0x0000000000000d16 (3350)
task_id : 0x00000000 (0)
vnn : 0xffffffff (4294967295)
unique_id : 0x304715b8633d5fa0
(3478773118850129824)
op_mid : 0x000000000002d9a4 (186788)
op_type : 0x0000 (0)
lease_idx : 0xffffffff (4294967295)
access_mask : 0x00100081 (1048705)
share_access : 0x00000007 (7)
private_options : 0x00000000 (0)
time : ven ott 12 12:05:09 2018
CEST.532622
id: struct file_id
devid : 0x000000000000fd02 (64770)
inode : 0x0000000020000056
(536870998)
extid : 0x0000000000000000 (0)
share_file_id : 0x000000000ae8aef3 (183021299)
uid : 0x000003f9 (1017)
flags : 0x0000 (0)
name_hash : 0x0264a327 (40149799)
stale : 0x00 (0)
lease : NULL
num_leases : 0x00000000 (0)
leases: ARRAY(0)
num_delete_tokens : 0x00000000 (0)
delete_tokens: ARRAY(0)
old_write_time : gio gen 1 01:00:00 1970 CET.0
changed_write_time : gio gen 1 01:00:00 1970 CET.0
fresh : 0x00 (0)
modified : 0x01 (1)
record : *
id: struct file_id
devid : 0x000000000000fd02 (64770)
inode : 0x0000000020000056 (536870998)
extid : 0x0000000000000000 (0)
[2018/10/12 12:05:09.533639, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=locking]
../source3/locking/share_mode_lock.c:157(share_mode_memcache_delete)
deleting entry for file . seq 0x1141782026507589052 key fd02:20000056:0
[2018/10/12 12:05:09.533660, 5, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap.c:128(dbwrap_lock_order_state_destructor)
release lock order 1 for /var/lib/samba/lock/locking.tdb
[2018/10/12 12:05:09.533670, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap.c:115(debug_lock_order)
lock order: 1:<none> 2:<none> 3:<none>
[2018/10/12 12:05:09.533681, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../lib/dbwrap/dbwrap_tdb.c:59(db_tdb_log_key)
Unlocking key 02FD00000000000056000020000000000000000000000000
[2018/10/12 12:05:09.533690, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=locking]
../source3/locking/share_mode_lock.c:171(share_mode_memcache_store)
stored entry for file . seq 0x1141782026507589053 key fd02:20000056:0
[2018/10/12 12:05:09.533700, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:5405(create_file_unixpath)
create_file_unixpath: info=1
[2018/10/12 12:05:09.533708, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/open.c:5684(create_file_default)
create_file: info=1
[2018/10/12 12:05:09.533716, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/smbd/smb2_create.c:1194(smbd_smb2_create_send)
smbd_smb2_create_send: response construction phase
[2018/10/12 12:05:09.533724, 10, pid=3350, effective(1017, 1003), real(1017,
0), class=acls] ../source3/smbd/posix_acls.c:3564(posix_get_nt_acl)
posix_get_nt_acl: called for file .
[2018/10/12 12:05:09.533748, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/passdb/lookup_sid.c:1286(uid_to_sid)
uid 0 -> sid S-1-22-1-0
[2018/10/12 12:05:09.533759, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/passdb/lookup_sid.c:1335(gid_to_sid)
gid 0 -> sid S-1-5-21-717140398-4153742348-3969525143-1000
[2018/10/12 12:05:09.533770, 10, pid=3350, effective(1017, 1003), real(1017,
0)] ../source3/passdb/lookup_sid.c:1286
Rowland Penny
2018-Oct-16 16:11 UTC
[Samba] high cpu load with share_conflict on browsing and opening files
On Tue, 16 Oct 2018 16:26:37 +0200 Alberto Cavaliere via samba <samba at lists.samba.org> wrote:> Hello, > > I have a server running samba version 4.7.1 on centos 7.5 > > 1) A series of operations by a windows 10 (up to date) pc client > consisting of searching (or browsing)/opening/modifying/closing a > (each time different) file multiple times on a samba share containing > many files (more than 11000) goes fast for a while. > 2) Then the same operation (or just the searching or opening) of the > same user on the same pc on the same dir gets very very slow (up to a > minute) and the cpu of the pid samba process serving the user stays > over the 60% load. 3) Restarting the pc client doesn't resolve the > problem because it gets always served by the same (high cpu load) > samba pid.How are you starting Samba ? The 'smbd' daemon should fork for every new connection and hence should get a different pid. Rowland
Jeremy Allison
2018-Oct-16 16:24 UTC
[Samba] high cpu load with share_conflict on browsing and opening files
On Tue, Oct 16, 2018 at 04:26:37PM +0200, Alberto Cavaliere via samba wrote:> Hello, > > I have a server running samba version 4.7.1 on centos 7.5 > > 1) A series of operations by a windows 10 (up to date) pc client consisting > of searching (or browsing)/opening/modifying/closing a (each time > different) file multiple times on a samba share containing many files (more > than 11000) goes fast for a while. > 2) Then the same operation (or just the searching or opening) of the same > user on the same pc on the same dir gets very very slow (up to a minute) and > the cpu of the pid samba process serving the user stays over the 60% load. > 3) Restarting the pc client doesnt resolve the problem because it gets > always served by the same (high cpu load) samba pid. > 4) The same operations on a different pc (by the same user or not, doesnt > matter) are fast as long a they are served by a different samba process > (otherwise is just as slow). > 5) Restarting samba makes the problem go away for a short while, depending > on how many operations described in 1) are made. > > Please can sameone give some pointers on why this is happens? > > Thanks a lot (I'm in a very tight spot because of this) > -------------------------------------- > Smb.conf: > > client ipc signing = auto > oplocks=no > level2 oplocks=noWhy are you turning off oplocks. They are a big performance enhancement. Ensure you're using SMB2 also.