Web lists-archives.com

[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 doesn’t 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, doesn’t
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



-- 
To unsubscribe from this list go to the following URL and read the
instructions:  https://lists.samba.org/mailman/options/samba