[Samba] understanding stat cache

[Ulrich Sibiller]

Hello,

We have a user that switched from Linux to Windows with his engineering software. Previously he was using NFS to access data and there were no performance complaints.

Now, with Windows, the same procedures take minutes instead of seconds.

I created some log files in Samba 4.10.16-25.el7_9 (recompiled with gpfs support and using the gpfs vfs module) with debuglevel 10 to see if there's an obvious reason for the performance problems.

For one of the log files (that only cover 73secs) I have made a poor man's profiling by simply counting the called functions, here's the result:
      2 max_data
     4 
      4 fd_open
      4 smbd_idle_event_handler
      4 smbXsrv_open_update
      6 filename_convert_internal
      8 check_parent_exists
      8 grant_fsp_oplock_type
      8 smb2
     20 smbd_do_qfsinfo
     36 stat_cache_add
    451 change_to_root_user
   3040 get_ea_dos_attribute
  11172 fill_ea_chained_buffer
  11172 get_ea_names_from_file
  11172 get_ea_value
  11216 open_directory
  11224 se_access_check
  11232 unix_mode
  11236 create_file
  11236 create_file_default
  22344 get_ea_list_from_file
  22348 smbd_do_qfilepathinfo
  22448 file_name_hash
  22448 smbXsrv_open_create
  22448 smbXsrv_open_global_verify_record
  22452 smbXsrv_open_global_store
  22464 create_file_unixpath
  22464 open_file_ntcreate
  22550 ctdbd_migrate
  23938 smbd_check_access_rights
  30254 change_to_user_impersonate
  32897 stat_cache_lookup
  32909 ctdbd_control
  33618 dos_mode
  33668 print_impersonation_info
  67348 dbwrap_lock_order_lock
  67348 dbwrap_lock_order_unlock
  75420 dos_mode_debug_print
  83604 parse_dos_attribute_blob
 294337 xid_to_sid

(I guess, some of them have to be reduced because the same call print multiple lines and some of them are only called because of the high debug level).

The first thing that I came upon was that there are lots of stat_cache_lookups but only very few stat cache add calls. So I took a closer look at the stat cache related output and found e.g. this (path names obfuscated):
 
[2023/11/07 14:24:01.004138,  5, pid=21305, effective(27606, 50753), real(27606, 0)]   unix_convert called on file "proj/someproj/sub/03_database/AA/bb_bb_bb"
[2023/11/07 14:24:01.004148, 10, pid=21305, effective(27606, 50753), real(27606, 0)]   stat_cache_lookup: lookup failed for name [PROJ/SOMEPROJ/SUB/03_DATABASE/AA/BB_BB_BB]
[2023/11/07 14:24:01.004155, 10, pid=21305, effective(27606, 50753), real(27606, 0)]   stat_cache_lookup: lookup failed for name [PROJ/SOMEPROJ/SUB/03_DATABASE/AA]
[2023/11/07 14:24:01.004161, 10, pid=21305, effective(27606, 50753), real(27606, 0)]   stat_cache_lookup: lookup succeeded for name [PROJ/SOMEPROJ/SUB/03_DATABASE] -> [proj/someproj/sub/03_database]
[2023/11/07 14:24:01.004175,  5, pid=21305, effective(27606, 50753), real(27606, 0)]   unix_convert begin: name = proj/someproj/sub/03_database/AA/bb_bb_bb, dirpath = proj/someproj/sub/03_database, start = AA/bb_bb_bb
[2023/11/07 14:24:01.004185,  5, pid=21305, effective(27606, 50753), real(27606, 0)]   conversion of base_name finished proj/someproj/sub/03_database/AA/bb_bb_bb -> proj/someproj/sub/03_database/AA/bb_bb_bb
[2023/11/07 14:24:01.004193, 10, pid=21305, effective(27606, 50753), real(27606, 0)]   create_file_default: create_file: access_mask = 0x100080 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 root_dir_fid = 0x0, ea_list = (nil), sd = (nil), fname = proj/someproj/sub/03_database/AA/bb_bb_bb
[2023/11/07 14:24:01.004205, 10, pid=21305, effective(27606, 50753), real(27606, 0)]   create_file_unixpath: create_file_unixpath: access_mask = 0x100080 file_attributes = 0x0, share_access = 0x7, create_disposition = 0x1 create_options = 0x0 oplock_request = 0x0 private_flags = 0x0 ea_list = (nil), sd = (nil), fname = proj/someproj/sub/03_database/AA/bb_bb_bb

I have 754 of these stanzas in the 73s logfile - for this one directory! And the same again for some more other directories.

So I am wondering why the first two lookups always fail and/or obviously are never stored to the stat cache?  Is there a depth limit in the stat cache?

smb.conf has
       max stat cache size = 512

(BTW: Is there some way to gather statistics about the stat cache?)


Kind regards,
Ulrich Sibiller

-- 
Dipl.-Inf. Ulrich Sibiller
Senior IT Consultant
T: +49 (0) 7071 9457 681 (Hotline)
Hagellocher Weg 73 – 72070 Tübingen – Germany
eviden.com

an atos business


science+computing ag
Management Board: Dr. Martin Matzke (Chairman), Sabine Hohenstein, Matthias Schempp; Chairman of the Supervisory Board: Emmanuel Le Roux; Registered office: Tübingen; Commercial register of the local court of Stuttgart, HRB 382196