samba - Nov 2023 - understanding stat cache

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

On Fri, 10 Nov 2023 12:47:07 +0000
Ulrich Sibiller via samba <samba at lists.samba.org> wrote:
> 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.
Without knowing how you are running Samba, it is a bit hard to comment,
but what I can say is, version 4.10.16 is ancient from the Samba point
of view, it is no longer supported directly by Samba. Perhaps trying a
much later version might help.
 
>
> 
> smb.conf has
>        max stat cache size = 512
That is the default on later versions of Samba.
> 
> (BTW: Is there some way to gather statistics about the stat cache?)
>
Not that I am aware, but others might.

Rowland

Hello Ulrich,

On 11/10/23 13:47, Ulrich Sibiller via samba wrote:
> 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.
the classic workload where Samba performance sucks is when applications 
create many files in directories. In Samba this involves scanning the 
parent directory for every file as part of the case insensitive 
implementation on-top of a case sensitive filesystem.

There are a few things that can be done here, eg man smb.conf

        default case = upper/lower
            controls what the default case is for new
            filenames (ie. files that don't currently exist
            in the filesystem). Default lower. IMPORTANT
            NOTE: As part of the optimizations for
            directories containing large numbers of files,
            the following special case applies. If the
            options case sensitive = yes, preserve case = No,
            and short preserve case = No are set, then the
            case of all incoming client filenames, not just
            new filenames, will be modified. See additional
            notes below.

Ideally you'd have a filesystem that is case insensitive (ext4 added 
support recently) or a filesystem that is supported by Samba via a VFS 
hook to lookup files.
> 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?
the name stat cache is a bit misleading, only caches filenames, not stat 
info. It only helps if clients repeatedly access existing files with a 
wrong case.

-slow

-- 
SerNet Samba Team Lead          https://samba.plus/
Samba Team Member                https://samba.org/
SAMBA+ packages                 https://samba.plus/
Worldwide Samba Support, Consulting and Development
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature.asc
Type: application/pgp-signature
Size: 840 bytes
Desc: OpenPGP digital signature
URL:
<http://lists.samba.org/pipermail/samba/attachments/20231113/073e2a7d/OpenPGP_signature.sig>