Slowdown with latest kernels

[NetSysFire]

Description

With the newest kernels, at least on Arch Linux, which ships 5.18.15-arch1-1, the time to initialize the sandbox (Child process initialized in ...) skyrockets. Arch Linux's kernel patches are minimal enough that I think they are not the issue here.

Steps to Reproduce

1. Use the given kernel version. I updated multiple times and the problems persisted, so it is likely present in all the newer stable kernels.
2. Run e.g firejail ls.
3. Time to initialize the sandbox fluctuates wildly.

To be clear here: Right now it takes around 900 ms to init, on a prior boot without updating or touching anything, 35 ms. On slightly earlier kernel versions I sometimes even had an unusable 10 seconds.

I need to do proper tests, but it looks like systemd sandboxing, which also makes use of the same kernel features, may also be affected. I noticed a slowdown there, too but I did not measure it. I only took note of this during the start and shutdown sequence, and it was worse in the latter.
However, when I had the unusable 10 seconds delay, only firejailed stuff was affected by it. All systemd service units, which do not use firejail but their own sandboxing, initialized without delay, resulting in a normal system startup.

I did run firejail with --debug and the slowdown was very visible when it was setting up filesystems.

Expected behavior

No slowdown.

Actual behavior

Slowdown.

Behavior without a profile

n/a

Additional context

Ping @glitsj16, I discussed this on IRC with them and they said they also noticed slowdowns. It may very well be a kernel regression, aka a "notourbug".
The bug is so inconsistent it is driving me insane, so I'd love some more pairs of eyes looking over this.

Environment

• Linux distribution and version: Arch Linux
• Firejail version: 0.9.70

Checklist

• The issues is caused by firejail (i.e. running the program by path (e.g. /usr/bin/vlc) "fixes" it).
• I can reproduce the issue without custom modifications (e.g. globals.local).
• The program has a profile. (If not, request one in https://github.com/netblue30/firejail/issues/1139)
• The profile (and redirect profile if exists) hasn't already been fixed upstream.
• I have performed a short search for similar issues (to avoid opening a duplicate).
  • I'm aware of browser-allow-drm yes/browser-disable-u2f no in firejail.config to allow DRM/U2F in browsers.
• I used --profile=PROFILENAME to set the right profile. (Only relevant for AppImages)

Log

n/a

[glitsj16]

After hearing about this by accidental presence on #archlinux IRC I installed several kernels available on Arch Linux to dig deeper into this slowdown issue:

• linux 5.18
• linux-clear 5.18 (if you've got Intel hardware this 'flies' and sandbox init times are usually cut in half)
• linux-lts 5.15
• linux-zen 5.18 (the slowest of the bunch)

There's indeed a rather significant difference in sandbox initialization time depending on kernel in use, as observed by the OP. I cannot (yet) determine what could be causing any of this but I'm keeping these extra kernels installed to check how things evolve on future releases. Even when its not our bug it's always nice to know how firejail users in the field may notice these fluctuations, and how we could respond to potential reports.

[reinerh]

I don't notice any slowdown on Debian (5.18.5), firejail ls initialization always takes about 50ms.

[NetSysFire]

Hmm. I wonder if this could be hardware specific then. My CPU is a ryzen 1600af. I wonder if the mitigations could affect the sandbox init time.

[reinerh]

I just updated my kernel to 5.18.14 and noticed a very small slowdown; it consistently takes about 60ms now.

Edit: CPU: Intel Core i7-7820HQ

[NetSysFire]

Alright, I recorded firejail --debug with script. These files are not human-readable. To replay them, use scriptreplay, it is bundled in util-linux and therefore usually included in every installation.
The exact command you need is: scriptreplay -T timing.log -B io.log

io.log
timing.log

[reinerh]

Can you maybe try recording it with perf (needs debug symbols)? For example:

perf record -F 99 -g -- firejail ls
perf report --stdio

(might need to be run as root)

If that works there are also tools to generate flamegraphs etc., see https://www.brendangregg.com/perf.html

For me it seems to spend a lot of time in fs_blacklist, and there in globbing and expand_macros.

[NetSysFire]

It fluctuates quite a bit for me. I have built firejail from master with debug symbols. Right now it is at 86 ms which is fine. I will re-test after a reboot which also applies the kernel update. It appears that a reboot randomizes the time it takes for the sandbox to initialize, its super weird.
After that I will see if this either another kernel upgrade or the upgrade to the unstable version has helped, if not I will provide the perf stuff.

[glitsj16]

There's a nice tool in arch linux repo https://archlinux.org/packages/community/x86_64/cargo-flamegraph/. Pretty handy to create flamegraphs directly from perf output.

[NetSysFire]

Alright. I got 16k ms after a reboot and kernel upgrade.
perf.data.gz

Had to gzip because of github.

# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 905  of event 'cycles'
# Event count (approx.): 35745591774
#
# Children      Self  Command   Shared Object      Symbol
# ........  ........  ........  .................  ...................................
#
    98.93%     0.00%  firejail  [kernel.kallsyms]  [k] entry_SYSCALL_64_after_hwframe
            |
            ---entry_SYSCALL_64_after_hwframe
               do_syscall_64
               |
               |--96.56%--ksys_read
               |          vfs_read
               |          |
               |           --96.46%--new_sync_read
               |                     |
               |                      --96.46%--seq_read_iter
               |                                |
               |                                 --96.25%--show_mountinfo
               |                                           |
               |                                           |--93.88%--get_dominating_id
               |                                           |
               |                                           |--0.73%--seq_path_root
               |                                           |          |
               |                                           |           --0.52%--__d_path
               |                                           |                     prepend_path
               |                                           |
               |                                            --0.52%--shmem_show_options
               |                                                      seq_printf
               |
                --1.92%--__x64_sys_getdents64
                          iterate_dir
                          ext4_readdir
                          ext4_htree_fill_tree
                          htree_dirblock_to_tree
                          __ext4_check_dir_entry

    98.93%     0.00%  firejail  [kernel.kallsyms]  [k] do_syscall_64
            |
            ---do_syscall_64
               |
               |--96.56%--ksys_read
               |          vfs_read
               |          |
               |           --96.46%--new_sync_read
               |                     |
               |                      --96.46%--seq_read_iter
               |                                |
               |                                 --96.25%--show_mountinfo
               |                                           |
               |                                           |--93.88%--get_dominating_id
               |                                           |
               |                                           |--0.73%--seq_path_root
               |                                           |          |
               |                                           |           --0.52%--__d_path
               |                                           |                     prepend_path
               |                                           |
               |                                            --0.52%--shmem_show_options
               |                                                      seq_printf
               |
                --1.92%--__x64_sys_getdents64
                          iterate_dir
                          ext4_readdir
                          ext4_htree_fill_tree
                          htree_dirblock_to_tree
                          __ext4_check_dir_entry

    98.52%     0.00%  firejail  [unknown]          [k] 0000000000000000
            |
            ---0
               |
               |--96.56%--read
               |          entry_SYSCALL_64_after_hwframe
               |          do_syscall_64
               |          ksys_read
               |          vfs_read
               |          |
               |           --96.46%--new_sync_read
               |                     |
               |                      --96.46%--seq_read_iter
               |                                |
               |                                 --96.25%--show_mountinfo
               |                                           |
               |                                           |--93.88%--get_dominating_id
               |                                           |
               |                                           |--0.73%--seq_path_root
               |                                           |          |
               |                                           |           --0.52%--__d_path
               |                                           |                     prepend_path
               |                                           |
               |                                            --0.52%--shmem_show_options
               |                                                      seq_printf
               |
                --1.92%--getdents64
                          entry_SYSCALL_64_after_hwframe
                          do_syscall_64
                          __x64_sys_getdents64
                          iterate_dir
                          ext4_readdir
                          ext4_htree_fill_tree
                          htree_dirblock_to_tree
                          __ext4_check_dir_entry

    96.56%     0.00%  firejail  libc.so.6          [.] read
            |
            ---read
               entry_SYSCALL_64_after_hwframe
               do_syscall_64
               ksys_read
               vfs_read
               |
                --96.46%--new_sync_read
                          |
                           --96.46%--seq_read_iter
                                     |
                                      --96.25%--show_mountinfo
                                                |
                                                |--93.88%--get_dominating_id
                                                |
                                                |--0.73%--seq_path_root
                                                |          |
                                                |           --0.52%--__d_path
                                                |                     prepend_path
                                                |
                                                 --0.52%--shmem_show_options
                                                           seq_printf

    96.56%     0.00%  firejail  [kernel.kallsyms]  [k] ksys_read
            |
            ---ksys_read
               vfs_read
               |
                --96.46%--new_sync_read
                          |
                           --96.46%--seq_read_iter
                                     |
                                      --96.25%--show_mountinfo
                                                |
                                                |--93.88%--get_dominating_id
                                                |
                                                |--0.73%--seq_path_root
                                                |          |
                                                |           --0.52%--__d_path
                                                |                     prepend_path
                                                |
                                                 --0.52%--shmem_show_options
                                                           seq_printf

    96.56%     0.00%  firejail  [kernel.kallsyms]  [k] vfs_read
            |
            ---vfs_read
               |
                --96.46%--new_sync_read
                          |
                           --96.46%--seq_read_iter
                                     |
                                      --96.25%--show_mountinfo
                                                |
                                                |--93.88%--get_dominating_id
                                                |
                                                |--0.73%--seq_path_root
                                                |          |
                                                |           --0.52%--__d_path
                                                |                     prepend_path
                                                |
                                                 --0.52%--shmem_show_options
                                                           seq_printf

    96.46%     0.00%  firejail  [kernel.kallsyms]  [k] new_sync_read
            |
            ---new_sync_read
               |
                --96.46%--seq_read_iter
                          |
                           --96.25%--show_mountinfo
                                     |
                                     |--93.88%--get_dominating_id
                                     |
                                     |--0.73%--seq_path_root
                                     |          |
                                     |           --0.52%--__d_path
                                     |                     prepend_path
                                     |
                                      --0.52%--shmem_show_options
                                                seq_printf

    96.46%     0.00%  firejail  [kernel.kallsyms]  [k] seq_read_iter
            |
            ---seq_read_iter
               |
                --96.25%--show_mountinfo
                          |
                          |--93.88%--get_dominating_id
                          |
                          |--0.73%--seq_path_root
                          |          |
                          |           --0.52%--__d_path
                          |                     prepend_path
                          |
                           --0.52%--shmem_show_options
                                     seq_printf

    96.25%     0.32%  firejail  [kernel.kallsyms]  [k] show_mountinfo
            |
             --95.93%--show_mountinfo
                       |
                       |--93.88%--get_dominating_id
                       |
                       |--0.73%--seq_path_root
                       |          |
                       |           --0.52%--__d_path
                       |                     prepend_path
                       |
                        --0.52%--shmem_show_options
                                  seq_printf

    93.88%    93.77%  firejail  [kernel.kallsyms]  [k] get_dominating_id
            |
             --93.77%--0
                       read
                       entry_SYSCALL_64_after_hwframe
                       do_syscall_64
                       ksys_read
                       vfs_read
                       new_sync_read
                       seq_read_iter
                       show_mountinfo
                       get_dominating_id

[glitsj16]

Hmm. I wonder if this could be hardware specific then. My CPU is a ryzen 1600af. I wonder if the mitigations could affect the sandbox init time.

This sounds increasingly more plausible, especially when taken in context with the observation shared on IRC that the 16k ms sowdown is also noticeable on starting systemd sandboxed units.

I just finished another round of tests on the kernels noted in #5293 (comment). On an Intel® Core™2 Duo CPU T6600 @ 2.20GHz × 2 there's hardly any difference between running with/without mitigations=off and I'm seeing 'normal' sandbox initialization of ~70ms. Alas I never measured this before this issue was reported, but FWIW I can't say I notice any recent regressions.

Realizing this is a big ask, but would any of you be willing to run the same tests with mitigations=off to rule those out?

[reinerh]

According to the perf trace it seems to take >95% of the time doing syscalls (read).

[NetSysFire]

I am a noob at interpreting perf traces, but 93.88%--get_dominating_id looks really suspicious, especially since it appears to be used several times and it is the only thing which takes this amount of time.

Realizing this is a big ask, but would any of you be willing to run the same tests with mitigations=off to rule those out?

Sure, I can do that. Applying the kernel parameter will take a reboot and since the time used for initializing is very inconsistent, I will report back if it still happens after I reboot. So expect another comment from me tomorrow or so.

[NetSysFire]

Took a bit longer than I planned because I did not get a slowdown immediately, but it is currently at 5k ms even with mitigations=off

[NetSysFire]

Still happening by the way. glitsj16 said on IRC I should bump this.

[glitsj16]

Wondering if this might be related to #6307. Couldn't determine that (yet) as OP needed to attend other things on IRC.

[NetSysFire]

Looks to be unrelated. I freshly built firejail from -git while I had that persistent delay again just now, according to time firejail ls it takes 6s of cpu time.

[glitsj16]

Recap of the latest revisit (with recent 6.8.x kernels) on IRC #firejail:

• issue is still noticeable in firejail (incl. firejail-git) and more/most pronounced in disable-common.inc
• also affected
  • pacman (when checking for free space)
  • systemd (when using BindPaths)

TL;DR looks like a kernel issue. Not very likely we can do much about it.

[NetSysFire]

I updated my BIOS, yes the firmware, the BIOS, however you want to call it, and the issue got immediately better. This is very cursed indeed that the firmware affects a random syscall. However, since this issue is very random I am unsure if this is really fixed. Give me some more time and I'll see if this still happens.

Hardware, for anyone interested:

• MSI B450M-a pro max (probably the primary culprit here?!)
• rx 570 OC version
• ryzen 1600af
• 32 gb ddr4 ram (though unrelated since I replaced the RAM for unrelated reason and the issue did not change)

[NetSysFire]

So far no more slowdowns. I still cant believe this issue got fixed by a BIOS update of all things. I should have applied more holy water.