> -----Original Message-----
> From: Paul E. McKenney <paulmck@kernel.org>
> Sent: Wednesday, November 23, 2022 8:44 AM
> Subject: Re: BUG: BISECTED: in squashfs_xz_uncompress() (Was: RCU stalls
> in squashfs_readahead())
> 
> On Wed, Nov 23, 2022 at 10:14:07AM +0100, Mirsad Goran Todorovac wrote:
...

> > commit 1045a06724f322ed61f1ffb994427c7bdbe64647
> > Author: Christoph Hellwig <hch@lst.de>
> > Date:   Wed Jun 29 17:01:02 2022 +0200
> >
> >     remove CONFIG_ANDROID
> 
> But your CONFIG_RCU_EXP_CPU_STALL_TIMEOUT seems to be about 20.
> As in 20 milliseconds.
> 
> Is that intentional?
...
> > > And one approach is to take a less aggressive RCU CPU stall timeout,
> > > say reducing from 21 seconds to (say) 15 seconds instead of all the
> > > way down to 20 milliseconds.  This could allow you to ease into the
> > > latency-reduction work.
> > >
> > > Alternatively, consider that response time is a property of the
> > > entire system plus the environment that it runs in.  So I suspect that
> > > the Android folks are accompanying that 20-millisecond timeout with
> > > some restrictions on what the on-phone workloads are permitted to do.
> > > Maybe ask the Android guys what those restrictions are and loosen them
> > > slightly, again allowing you to ease into the latency-reduction work.

Since there is no longer a kernel default of 20 ms for Android since
commit 1045a06724f3 ("remove CONFIG_ANDROID"), it might be appropriate
to drop that from stallwarn.rst. Something like:

diff --git a/Documentation/RCU/stallwarn.rst b/Documentation/RCU/stallwarn.rst
index e38c587067fc..d86a8b47504f 100644
--- a/Documentation/RCU/stallwarn.rst
+++ b/Documentation/RCU/stallwarn.rst
@@ -168,10 +168,11 @@ CONFIG_RCU_EXP_CPU_STALL_TIMEOUT
        Same as the CONFIG_RCU_CPU_STALL_TIMEOUT parameter but only for
        the expedited grace period. This parameter defines the period
        of time that RCU will wait from the beginning of an expedited
-       grace period until it issues an RCU CPU stall warning. This time
-       period is normally 20 milliseconds on Android devices.  A zero
-       value causes the CONFIG_RCU_CPU_STALL_TIMEOUT value to be used,
-       after conversion to milliseconds.
+       grace period until it issues an RCU CPU stall warning.
+
+       A zero value causes the CONFIG_RCU_CPU_STALL_TIMEOUT value to be
+        used, after conversion to milliseconds, limited to a maximum of
+        21 seconds.

        This configuration parameter may be changed at runtime via the
        /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout, however
diff --git a/kernel/rcu/Kconfig.debug b/kernel/rcu/Kconfig.debug
index 1b0c41d490f0..4477eeb8a54f 100644
--- a/kernel/rcu/Kconfig.debug
+++ b/kernel/rcu/Kconfig.debug
@@ -93,7 +93,7 @@ config RCU_EXP_CPU_STALL_TIMEOUT
          If the RCU grace period persists, additional CPU stall warnings
          are printed at more widely spaced intervals.  A value of zero
          says to use the RCU_CPU_STALL_TIMEOUT value converted from
-         seconds to milliseconds.
+         seconds to milliseconds, limited to a maximum of 21 seconds.

> > > But please keep in mind that cond_resched() helps only in kernels
> > > built with CONFIG_PREEMPTION=n.

I think they also help with
	CONFIG_PREEMPT_VOLUNTARY=y
which is used by Fedora and RHEL. For example, adding more of those in
the crypto tcrypt test module eliminated some RCU stalls when running
speed tests (that send lots of data through the algorithms).

> > I have bad news that 6.1-r6 is still affected with
> > squashfs_xz_uncompress bug, despite having both of your fixes
> > (as visible in above command's output -- double checked):
> >
> > [   91.065659] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 3-.... } 6 jiffies s: 621 root: 0x8/.
> 
> If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
> this still happen?

BTW, you don't need to rebuild the kernel to change those parameters; they're
module parameters, so can be modified on the kernel command line (if needed
during boot) and sysfs (if only needed after boot).

For sysfs the syntax is:
#!/bin/bash
# set rcu timeouts to specified values
echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout

On Wed, Nov 23, 2022 at 04:08:03PM +0000, Elliott, Robert (Servers) wrote:
> > -----Original Message-----
> > From: Paul E. McKenney <paulmck@kernel.org>
> > Sent: Wednesday, November 23, 2022 8:44 AM
> > Subject: Re: BUG: BISECTED: in squashfs_xz_uncompress() (Was: RCU stalls
> > in squashfs_readahead())
> > 
> > On Wed, Nov 23, 2022 at 10:14:07AM +0100, Mirsad Goran Todorovac wrote:
> ...
> 
> > > commit 1045a06724f322ed61f1ffb994427c7bdbe64647
> > > Author: Christoph Hellwig <hch@lst.de>
> > > Date:   Wed Jun 29 17:01:02 2022 +0200
> > >
> > >     remove CONFIG_ANDROID
> > 
> > But your CONFIG_RCU_EXP_CPU_STALL_TIMEOUT seems to be about 20.
> > As in 20 milliseconds.
> > 
> > Is that intentional?
> ...
> > > > And one approach is to take a less aggressive RCU CPU stall timeout,
> > > > say reducing from 21 seconds to (say) 15 seconds instead of all the
> > > > way down to 20 milliseconds.  This could allow you to ease into the
> > > > latency-reduction work.
> > > >
> > > > Alternatively, consider that response time is a property of the
> > > > entire system plus the environment that it runs in.  So I suspect that
> > > > the Android folks are accompanying that 20-millisecond timeout with
> > > > some restrictions on what the on-phone workloads are permitted to do.
> > > > Maybe ask the Android guys what those restrictions are and loosen them
> > > > slightly, again allowing you to ease into the latency-reduction work.
> 
> Since there is no longer a kernel default of 20 ms for Android since
> commit 1045a06724f3 ("remove CONFIG_ANDROID"), it might be appropriate
> to drop that from stallwarn.rst. Something like:

Fair point, except that the Android guys asked for this.  In fact, the
Android guys supplied the patches.  I like the traceability.

> diff --git a/Documentation/RCU/stallwarn.rst b/Documentation/RCU/stallwarn.rst
> index e38c587067fc..d86a8b47504f 100644
> --- a/Documentation/RCU/stallwarn.rst
> +++ b/Documentation/RCU/stallwarn.rst
> @@ -168,10 +168,11 @@ CONFIG_RCU_EXP_CPU_STALL_TIMEOUT
>         Same as the CONFIG_RCU_CPU_STALL_TIMEOUT parameter but only for
>         the expedited grace period. This parameter defines the period
>         of time that RCU will wait from the beginning of an expedited
> -       grace period until it issues an RCU CPU stall warning. This time
> -       period is normally 20 milliseconds on Android devices.  A zero
> -       value causes the CONFIG_RCU_CPU_STALL_TIMEOUT value to be used,
> -       after conversion to milliseconds.
> +       grace period until it issues an RCU CPU stall warning.
> +
> +       A zero value causes the CONFIG_RCU_CPU_STALL_TIMEOUT value to be
> +        used, after conversion to milliseconds, limited to a maximum of
> +        21 seconds.
> 
>         This configuration parameter may be changed at runtime via the
>         /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout, however
> diff --git a/kernel/rcu/Kconfig.debug b/kernel/rcu/Kconfig.debug
> index 1b0c41d490f0..4477eeb8a54f 100644
> --- a/kernel/rcu/Kconfig.debug
> +++ b/kernel/rcu/Kconfig.debug
> @@ -93,7 +93,7 @@ config RCU_EXP_CPU_STALL_TIMEOUT
>           If the RCU grace period persists, additional CPU stall warnings
>           are printed at more widely spaced intervals.  A value of zero
>           says to use the RCU_CPU_STALL_TIMEOUT value converted from
> -         seconds to milliseconds.
> +         seconds to milliseconds, limited to a maximum of 21 seconds.
> 
> > > > But please keep in mind that cond_resched() helps only in kernels
> > > > built with CONFIG_PREEMPTION=n.
> 
> I think they also help with
> 	CONFIG_PREEMPT_VOLUNTARY=y
> which is used by Fedora and RHEL. For example, adding more of those in
> the crypto tcrypt test module eliminated some RCU stalls when running
> speed tests (that send lots of data through the algorithms).
> 
> > > I have bad news that 6.1-r6 is still affected with
> > > squashfs_xz_uncompress bug, despite having both of your fixes
> > > (as visible in above command's output -- double checked):
> > >
> > > [   91.065659] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 3-.... } 6 jiffies s: 621 root: 0x8/.
> > 
> > If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
> > this still happen?
> 
> BTW, you don't need to rebuild the kernel to change those parameters; they're
> module parameters, so can be modified on the kernel command line (if needed
> during boot) and sysfs (if only needed after boot).
> 
> For sysfs the syntax is:
> #!/bin/bash
> # set rcu timeouts to specified values
> echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
> echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
> echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
> grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout

Excellent point, thank you!

I hope that this makes Mirsad's life easier, perhaps featuring less time
waiting for kernel builds and reboots.  ;-)

							Thanx, Paul

On 23. 11. 2022. 20:09, Paul E. McKenney wrote:

>>> If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
>>> this still happen?
>>
>> BTW, you don't need to rebuild the kernel to change those parameters; they're
>> module parameters, so can be modified on the kernel command line (if needed
>> during boot) and sysfs (if only needed after boot).
>>
>> For sysfs the syntax is:
>> #!/bin/bash
>> # set rcu timeouts to specified values
>> echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
>> echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
>> echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
>> grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout
> 
> Excellent point, thank you!
> 
> I hope that this makes Mirsad's life easier, perhaps featuring less time
> waiting for kernel builds and reboots.  ;-)

Unfortunately, the first stall and NMI occurs before any system script or setting a /sys/module/rcupdate/parameters/*
could be executed, as second 14 of the boot process:

[   14.320045] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-.... } 6 jiffies s: 105 root: 0x80/.
[   14.320064] rcu: blocking rcu_node structures (internal RCU debug):
[   14.320070] Sending NMI from CPU 1 to CPUs 7:
[   14.320081] NMI backtrace for cpu 7
[   14.320085] CPU: 7 PID: 532 Comm: modprobe Not tainted 6.1.0-rc6 #1
[   14.320090] Hardware name: LENOVO 82H8/LNVNB161216, BIOS GGCN49WW 07/21/2022
[   14.320093] RIP: 0010:find_kallsyms_symbol+0x1ba/0x2e0
[   14.320103] Code: 24 02 84 c0 74 24 3c 2e 48 8b 55 a0 74 1c 48 39 55 b8 0f 82 f8 00 00 00 48 3b 55 c0 0f 86 ee 00 00 00 48 89 55 
c0 44 89 6d ac <41> 83 c5 01 48 83
c3 18 45 39 fd 0f 85 2d ff ff ff 8b 45 ac 4c 8b
[   14.320107] RSP: 0018:ffff88811ab5f4f0 EFLAGS: 00000202
[   14.320113] RAX: 0000000000000000 RBX: ffffffffc1d1429e RCX: ffffffffb1c378e5
[   14.320116] RDX: ffffc900066e11e0 RSI: dffffc0000000000 RDI: ffffffffc1d142a0
[   14.320120] RBP: ffff88811ab5f560 R08: 0000000000000000 R09: ffff88811ab5f670
[   14.320123] R10: ffff88811ab5f90f R11: ffffed102356bf21 R12: ffffffffc1d33bd9
[   14.320126] R13: 0000000000000171 R14: 000000000000005f R15: 00000000000014ed
[   14.320128] FS:  00007f878ce39000(0000) GS:ffff888257380000(0000) knlGS:0000000000000000
[   14.320132] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   14.320135] CR2: 00007f13ac19cae0 CR3: 000000010c73e001 CR4: 0000000000770ee0
[   14.320138] PKRU: 55555554
[   14.320140] Call Trace:
[   14.320142]  <TASK>
[   14.320145]  ? __SCT__tp_func_raid56_scrub_read_recover+0x8/0x8 [btrfs]
[   14.320318]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
[   14.320485]  ? btrfs_show_options+0x860/0x860 [btrfs]
[   14.320647]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
[   14.320816]  module_address_lookup+0x7a/0xc0
[   14.320822]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
[   14.320987]  kallsyms_lookup_buildid+0x172/0x200
[   14.320993]  ? do_kernel_range_flush+0x60/0x60
[   14.321002]  kallsyms_lookup+0x14/0x20
[   14.321007]  test_for_valid_rec.isra.38+0x95/0x110
[   14.321015]  ? remove_direct_functions_hash.isra.37+0x1c0/0x1c0
[   14.321021]  ? _find_next_bit+0x42/0xe0
[   14.321037]  ? __kasan_check_write+0x14/0x20
[   14.321043]  ? mutex_lock+0x8f/0xe0
[   14.321049]  ? __mutex_lock_slowpath+0x20/0x20
[   14.321056]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
[   14.321220]  ftrace_module_enable+0x15f/0x460
[   14.321228]  load_module+0x323e/0x3800
[   14.321233]  ? __kernel_read+0x304/0x450
[   14.321246]  ? module_frob_arch_sections+0x40/0x40
[   14.321252]  ? security_kernel_post_read_file+0x6d/0x80
[   14.321259]  ? __kasan_check_write+0x14/0x20
[   14.321264]  ? kernel_read_file+0x20a/0x490
[   14.321270]  ? __kasan_check_read+0x11/0x20
[   14.321275]  ? __fget_light+0xb6/0x220
[   14.321283]  __do_sys_finit_module+0x131/0x1d0
[   14.321288]  ? __do_sys_finit_module+0x131/0x1d0
[   14.321293]  ? __ia32_sys_init_module+0x50/0x50
[   14.321297]  ? vm_mmap_pgoff+0x1a8/0x240
[   14.321307]  ? __kasan_check_write+0x14/0x20
[   14.321311]  ? fput+0x1d/0xd0
[   14.321317]  __x64_sys_finit_module+0x43/0x50
[   14.321322]  do_syscall_64+0x58/0x80
[   14.321330]  ? exit_to_user_mode_prepare+0x32/0x190
[   14.321337]  ? syscall_exit_to_user_mode+0x1b/0x30
[   14.321343]  ? do_syscall_64+0x67/0x80
[   14.321348]  ? fpregs_assert_state_consistent+0x5e/0x70
[   14.321356]  ? exit_to_user_mode_prepare+0x32/0x190
[   14.321362]  ? syscall_exit_to_user_mode+0x1b/0x30
[   14.321367]  ? do_syscall_64+0x67/0x80
[   14.321372]  ? syscall_exit_to_user_mode+0x1b/0x30
[   14.321377]  ? do_syscall_64+0x67/0x80
[   14.321382]  ? do_syscall_64+0x67/0x80
[   14.321388]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
[   14.321397] RIP: 0033:0x7f878c51ea3d
[   14.321401] Code: 5b 41 5c c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa 48 89 f8 48 89
f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff
73 01 c3 48 8b 0d c3 a3 0f 00 f7 d8 64 89 01 48
[   14.321405] RSP: 002b:00007ffd078d4c88 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[   14.321410] RAX: ffffffffffffffda RBX: 0000558c0d8830a0 RCX: 00007f878c51ea3d
[   14.321414] RDX: 0000000000000000 RSI: 0000558c0d6fdcd2 RDI: 0000000000000005
[   14.321417] RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000002
[   14.321419] R10: 0000000000000005 R11: 0000000000000246 R12: 0000558c0d6fdcd2
[   14.321422] R13: 0000558c0d883060 R14: 0000558c0d8824f0 R15: 0000558c0d88f5d0
[   14.321428]  </TASK>

Probably something sensible should be set in the case of KASAN build. This example of stall
apparently has nothing to do with squashfs_readahead().

Thanks,
Mirsad

--
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
-- 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

On Thu, Nov 24, 2022 at 06:06:13PM +0100, Mirsad Goran Todorovac wrote:
> On 23. 11. 2022. 20:09, Paul E. McKenney wrote:
> 
> > > > If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
> > > > this still happen?
> > > 
> > > BTW, you don't need to rebuild the kernel to change those parameters; they're
> > > module parameters, so can be modified on the kernel command line (if needed
> > > during boot) and sysfs (if only needed after boot).
> > > 
> > > For sysfs the syntax is:
> > > #!/bin/bash
> > > # set rcu timeouts to specified values
> > > echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
> > > echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
> > > echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
> > > grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout
> > 
> > Excellent point, thank you!
> > 
> > I hope that this makes Mirsad's life easier, perhaps featuring less time
> > waiting for kernel builds and reboots.  ;-)
> 
> Unfortunately, the first stall and NMI occurs before any system script or setting a /sys/module/rcupdate/parameters/*
> could be executed, as second 14 of the boot process:
> 
> [   14.320045] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-.... } 6 jiffies s: 105 root: 0x80/.
> [   14.320064] rcu: blocking rcu_node structures (internal RCU debug):
> [   14.320070] Sending NMI from CPU 1 to CPUs 7:
> [   14.320081] NMI backtrace for cpu 7
> [   14.320085] CPU: 7 PID: 532 Comm: modprobe Not tainted 6.1.0-rc6 #1
> [   14.320090] Hardware name: LENOVO 82H8/LNVNB161216, BIOS GGCN49WW 07/21/2022
> [   14.320093] RIP: 0010:find_kallsyms_symbol+0x1ba/0x2e0
> [   14.320103] Code: 24 02 84 c0 74 24 3c 2e 48 8b 55 a0 74 1c 48 39 55 b8
> 0f 82 f8 00 00 00 48 3b 55 c0 0f 86 ee 00 00 00 48 89 55 c0 44 89 6d ac <41>
> 83 c5 01 48 83
> c3 18 45 39 fd 0f 85 2d ff ff ff 8b 45 ac 4c 8b
> [   14.320107] RSP: 0018:ffff88811ab5f4f0 EFLAGS: 00000202
> [   14.320113] RAX: 0000000000000000 RBX: ffffffffc1d1429e RCX: ffffffffb1c378e5
> [   14.320116] RDX: ffffc900066e11e0 RSI: dffffc0000000000 RDI: ffffffffc1d142a0
> [   14.320120] RBP: ffff88811ab5f560 R08: 0000000000000000 R09: ffff88811ab5f670
> [   14.320123] R10: ffff88811ab5f90f R11: ffffed102356bf21 R12: ffffffffc1d33bd9
> [   14.320126] R13: 0000000000000171 R14: 000000000000005f R15: 00000000000014ed
> [   14.320128] FS:  00007f878ce39000(0000) GS:ffff888257380000(0000) knlGS:0000000000000000
> [   14.320132] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   14.320135] CR2: 00007f13ac19cae0 CR3: 000000010c73e001 CR4: 0000000000770ee0
> [   14.320138] PKRU: 55555554
> [   14.320140] Call Trace:
> [   14.320142]  <TASK>
> [   14.320145]  ? __SCT__tp_func_raid56_scrub_read_recover+0x8/0x8 [btrfs]
> [   14.320318]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
> [   14.320485]  ? btrfs_show_options+0x860/0x860 [btrfs]
> [   14.320647]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
> [   14.320816]  module_address_lookup+0x7a/0xc0
> [   14.320822]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
> [   14.320987]  kallsyms_lookup_buildid+0x172/0x200
> [   14.320993]  ? do_kernel_range_flush+0x60/0x60
> [   14.321002]  kallsyms_lookup+0x14/0x20
> [   14.321007]  test_for_valid_rec.isra.38+0x95/0x110
> [   14.321015]  ? remove_direct_functions_hash.isra.37+0x1c0/0x1c0
> [   14.321021]  ? _find_next_bit+0x42/0xe0
> [   14.321037]  ? __kasan_check_write+0x14/0x20
> [   14.321043]  ? mutex_lock+0x8f/0xe0
> [   14.321049]  ? __mutex_lock_slowpath+0x20/0x20
> [   14.321056]  ? btrfs_free_reserved_bytes+0xe0/0xe0 [btrfs]
> [   14.321220]  ftrace_module_enable+0x15f/0x460
> [   14.321228]  load_module+0x323e/0x3800
> [   14.321233]  ? __kernel_read+0x304/0x450
> [   14.321246]  ? module_frob_arch_sections+0x40/0x40
> [   14.321252]  ? security_kernel_post_read_file+0x6d/0x80
> [   14.321259]  ? __kasan_check_write+0x14/0x20
> [   14.321264]  ? kernel_read_file+0x20a/0x490
> [   14.321270]  ? __kasan_check_read+0x11/0x20
> [   14.321275]  ? __fget_light+0xb6/0x220
> [   14.321283]  __do_sys_finit_module+0x131/0x1d0
> [   14.321288]  ? __do_sys_finit_module+0x131/0x1d0
> [   14.321293]  ? __ia32_sys_init_module+0x50/0x50
> [   14.321297]  ? vm_mmap_pgoff+0x1a8/0x240
> [   14.321307]  ? __kasan_check_write+0x14/0x20
> [   14.321311]  ? fput+0x1d/0xd0
> [   14.321317]  __x64_sys_finit_module+0x43/0x50
> [   14.321322]  do_syscall_64+0x58/0x80
> [   14.321330]  ? exit_to_user_mode_prepare+0x32/0x190
> [   14.321337]  ? syscall_exit_to_user_mode+0x1b/0x30
> [   14.321343]  ? do_syscall_64+0x67/0x80
> [   14.321348]  ? fpregs_assert_state_consistent+0x5e/0x70
> [   14.321356]  ? exit_to_user_mode_prepare+0x32/0x190
> [   14.321362]  ? syscall_exit_to_user_mode+0x1b/0x30
> [   14.321367]  ? do_syscall_64+0x67/0x80
> [   14.321372]  ? syscall_exit_to_user_mode+0x1b/0x30
> [   14.321377]  ? do_syscall_64+0x67/0x80
> [   14.321382]  ? do_syscall_64+0x67/0x80
> [   14.321388]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
> [   14.321397] RIP: 0033:0x7f878c51ea3d
> [   14.321401] Code: 5b 41 5c c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa 48 89 f8 48 89
> f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff
> 73 01 c3 48 8b 0d c3 a3 0f 00 f7 d8 64 89 01 48
> [   14.321405] RSP: 002b:00007ffd078d4c88 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
> [   14.321410] RAX: ffffffffffffffda RBX: 0000558c0d8830a0 RCX: 00007f878c51ea3d
> [   14.321414] RDX: 0000000000000000 RSI: 0000558c0d6fdcd2 RDI: 0000000000000005
> [   14.321417] RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000002
> [   14.321419] R10: 0000000000000005 R11: 0000000000000246 R12: 0000558c0d6fdcd2
> [   14.321422] R13: 0000558c0d883060 R14: 0000558c0d8824f0 R15: 0000558c0d88f5d0
> [   14.321428]  </TASK>
> 
> Probably something sensible should be set in the case of KASAN build. This example of stall
> apparently has nothing to do with squashfs_readahead().

Can't have everything, I guess!

How about building your kernel with CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200?
Again, mainline defaults to 21000.

							Thanx, Paul

On 24. 11. 2022. 18:19, Paul E. McKenney wrote:
> On Thu, Nov 24, 2022 at 06:06:13PM +0100, Mirsad Goran Todorovac wrote:
>> On 23. 11. 2022. 20:09, Paul E. McKenney wrote:
>>
>>>>> If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
>>>>> this still happen?
>>>>
>>>> BTW, you don't need to rebuild the kernel to change those parameters; they're
>>>> module parameters, so can be modified on the kernel command line (if needed
>>>> during boot) and sysfs (if only needed after boot).
>>>>
>>>> For sysfs the syntax is:
>>>> #!/bin/bash
>>>> # set rcu timeouts to specified values
>>>> echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
>>>> echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
>>>> echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
>>>> grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout
>>>
>>> Excellent point, thank you!
>>>
>>> I hope that this makes Mirsad's life easier, perhaps featuring less time
>>> waiting for kernel builds and reboots.  ;-)
>>
>> Unfortunately, the first stall and NMI occurs before any system script or setting a /sys/module/rcupdate/parameters/*
>> could be executed, as second 14 of the boot process:
>>
>> [   14.320045] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-.... } 6 jiffies s: 105 root: 0x80/.
>> [   14.320064] rcu: blocking rcu_node structures (internal RCU debug):

...

>> Probably something sensible should be set in the case of KASAN build. This example of stall
>> apparently has nothing to do with squashfs_readahead().
> 
> Can't have everything, I guess!
> 
> How about building your kernel with CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200?
> Again, mainline defaults to 21000.

Did just that, and so far there is no modprobe stall in second 14 of boot at least. Looks good.
Probably it is too early to say anything in general before more uptime and stress load.

BTW, the 20 for CONFIG_RCU_EXP_STALL_TIMEOUT wasn't my invention, but it comes from generic
Ubuntu stock kernel (but without KASAN or KMEMLEAK config options):

# grep STALL /boot/config-5.19.5-051905-generic
CONFIG_RCU_STALL_COMMON=y
# CONFIG_HEADERS_INSTALL is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20
#

Thanks,
Mirsad

--
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
-- 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union

On Thu, Nov 24, 2022 at 07:04:13PM +0100, Mirsad Goran Todorovac wrote:
> On 24. 11. 2022. 18:19, Paul E. McKenney wrote:
> > On Thu, Nov 24, 2022 at 06:06:13PM +0100, Mirsad Goran Todorovac wrote:
> > > On 23. 11. 2022. 20:09, Paul E. McKenney wrote:
> > > 
> > > > > > If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
> > > > > > this still happen?
> > > > > 
> > > > > BTW, you don't need to rebuild the kernel to change those parameters; they're
> > > > > module parameters, so can be modified on the kernel command line (if needed
> > > > > during boot) and sysfs (if only needed after boot).
> > > > > 
> > > > > For sysfs the syntax is:
> > > > > #!/bin/bash
> > > > > # set rcu timeouts to specified values
> > > > > echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
> > > > > echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
> > > > > echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
> > > > > grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout
> > > > 
> > > > Excellent point, thank you!
> > > > 
> > > > I hope that this makes Mirsad's life easier, perhaps featuring less time
> > > > waiting for kernel builds and reboots.  ;-)
> > > 
> > > Unfortunately, the first stall and NMI occurs before any system script or setting a /sys/module/rcupdate/parameters/*
> > > could be executed, as second 14 of the boot process:
> > > 
> > > [   14.320045] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-.... } 6 jiffies s: 105 root: 0x80/.
> > > [   14.320064] rcu: blocking rcu_node structures (internal RCU debug):
> 
> ...
> 
> > > Probably something sensible should be set in the case of KASAN build. This example of stall
> > > apparently has nothing to do with squashfs_readahead().
> > 
> > Can't have everything, I guess!
> > 
> > How about building your kernel with CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200?
> > Again, mainline defaults to 21000.
> 
> Did just that, and so far there is no modprobe stall in second 14 of boot at least. Looks good.
> Probably it is too early to say anything in general before more uptime and stress load.
> 
> BTW, the 20 for CONFIG_RCU_EXP_STALL_TIMEOUT wasn't my invention, but it comes from generic
> Ubuntu stock kernel (but without KASAN or KMEMLEAK config options):
> 
> # grep STALL /boot/config-5.19.5-051905-generic
> CONFIG_RCU_STALL_COMMON=y
> # CONFIG_HEADERS_INSTALL is not set
> CONFIG_RCU_CPU_STALL_TIMEOUT=60
> CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20
> #

Gotta admit, those Ubuntu folks do not lack for bravery!!!  Even if they
don't also enable KASAN or KMEMLEAK by default.  ;-)

							Thanx, Paul

On 24/11/2022 18:04, Mirsad Goran Todorovac wrote:
> On 24. 11. 2022. 18:19, Paul E. McKenney wrote:
>> On Thu, Nov 24, 2022 at 06:06:13PM +0100, Mirsad Goran Todorovac wrote:
>>> On 23. 11. 2022. 20:09, Paul E. McKenney wrote:
>>>
>>>>>> If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
>>>>>> this still happen?
>>>>>
>>>>> BTW, you don't need to rebuild the kernel to change those 
>>>>> parameters; they're
>>>>> module parameters, so can be modified on the kernel command line 
>>>>> (if needed
>>>>> during boot) and sysfs (if only needed after boot).
>>>>>
>>>>> For sysfs the syntax is:
>>>>> #!/bin/bash
>>>>> # set rcu timeouts to specified values
>>>>> echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
>>>>> echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
>>>>> echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
>>>>> grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout
>>>>
>>>> Excellent point, thank you!
>>>>
>>>> I hope that this makes Mirsad's life easier, perhaps featuring less 
>>>> time
>>>> waiting for kernel builds and reboots.  ;-)
>>>
>>> Unfortunately, the first stall and NMI occurs before any system 
>>> script or setting a /sys/module/rcupdate/parameters/*
>>> could be executed, as second 14 of the boot process:
>>>
>>> [   14.320045] rcu: INFO: rcu_preempt detected expedited stalls on 
>>> CPUs/tasks: { 7-.... } 6 jiffies s: 105 root: 0x80/.
>>> [   14.320064] rcu: blocking rcu_node structures (internal RCU debug):
> 
> ...
> 
>>> Probably something sensible should be set in the case of KASAN build. 
>>> This example of stall
>>> apparently has nothing to do with squashfs_readahead().
>>
>> Can't have everything, I guess!
>>
>> How about building your kernel with CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200?
>> Again, mainline defaults to 21000.
> 
> Did just that, and so far there is no modprobe stall in second 14 of 
> boot at least. Looks good.
> Probably it is too early to say anything in general before more uptime 
> and stress load.
> 
> BTW, the 20 for CONFIG_RCU_EXP_STALL_TIMEOUT wasn't my invention, but it 
> comes from generic
> Ubuntu stock kernel (but without KASAN or KMEMLEAK config options):
> 
> # grep STALL /boot/config-5.19.5-051905-generic
> CONFIG_RCU_STALL_COMMON=y
> # CONFIG_HEADERS_INSTALL is not set
> CONFIG_RCU_CPU_STALL_TIMEOUT=60
> CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20 > #

That has been raised as a bug, and a fix has been committed.

https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1991951


> 
> Thanks,
> Mirsad
> 
> -- 
> Mirsad Goran Todorovac
> Sistem inženjer
> Grafički fakultet | Akademija likovnih umjetnosti
> Sveučilište u Zagrebu

On 24. 11. 2022. 20:32, Phillip Lougher wrote:
> On 24/11/2022 18:04, Mirsad Goran Todorovac wrote:
>> On 24. 11. 2022. 18:19, Paul E. McKenney wrote:
>>> On Thu, Nov 24, 2022 at 06:06:13PM +0100, Mirsad Goran Todorovac wrote:
>>>> On 23. 11. 2022. 20:09, Paul E. McKenney wrote:
>>>>
>>>>>>> If you build with (say) CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200, does
>>>>>>> this still happen?
>>>>>>
>>>>>> BTW, you don't need to rebuild the kernel to change those parameters; they're
>>>>>> module parameters, so can be modified on the kernel command line (if needed
>>>>>> during boot) and sysfs (if only needed after boot).
>>>>>>
>>>>>> For sysfs the syntax is:
>>>>>> #!/bin/bash
>>>>>> # set rcu timeouts to specified values
>>>>>> echo 60 > /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
>>>>>> echo 21000 > /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout
>>>>>> echo 600000 > /sys/module/rcupdate/parameters/rcu_task_stall_timeout
>>>>>> grep -Hs . /sys/module/rcupdate/parameters/rcu_*_timeout
>>>>>
>>>>> Excellent point, thank you!
>>>>>
>>>>> I hope that this makes Mirsad's life easier, perhaps featuring less time
>>>>> waiting for kernel builds and reboots.  ;-)
>>>>
>>>> Unfortunately, the first stall and NMI occurs before any system script or setting a /sys/module/rcupdate/parameters/*
>>>> could be executed, as second 14 of the boot process:
>>>>
>>>> [   14.320045] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 7-.... } 6 jiffies s: 105 root: 0x80/.
>>>> [   14.320064] rcu: blocking rcu_node structures (internal RCU debug):
>>
>> ...
>>
>>>> Probably something sensible should be set in the case of KASAN build. This example of stall
>>>> apparently has nothing to do with squashfs_readahead().
>>>
>>> Can't have everything, I guess!
>>>
>>> How about building your kernel with CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=200?
>>> Again, mainline defaults to 21000.
>>
>> Did just that, and so far there is no modprobe stall in second 14 of boot at least. Looks good.
>> Probably it is too early to say anything in general before more uptime and stress load.
>>
>> BTW, the 20 for CONFIG_RCU_EXP_STALL_TIMEOUT wasn't my invention, but it comes from generic
>> Ubuntu stock kernel (but without KASAN or KMEMLEAK config options):
>>
>> # grep STALL /boot/config-5.19.5-051905-generic
>> CONFIG_RCU_STALL_COMMON=y
>> # CONFIG_HEADERS_INSTALL is not set
>> CONFIG_RCU_CPU_STALL_TIMEOUT=60
>> CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20 > #
> 
> That has been raised as a bug, and a fix has been committed.
> 
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1991951

P.S.

As for the comment that I am thrashing my systems, I now test activated MG-LRU kernel option
with 6.1-rc8 build and it functions much better, with no multimedia lags or chirps, even
with only 130/8192 MiB free and 5/10 GiB in swap area.

I am running basically the same load of simultaneously opened Firefox, Chrome and Thunderbird
windows.

However, I have set CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=0

The conclusion is that the squashfs isn't blocking, but 6 to 8 jiffies were not enough to
complete the operation, so other CPUs issued NMIs. With longer timeout, it is evident that
it was a longer operation due to KASAN build and not a lockup.

So I think I have to apologise to have wasted so much of your time with a false alarm.

To summarise, the culprit was obviously the CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20 setting
from the Ubuntu mainline kernel stock, which I unsuspectedly copied into my build and
made a recommended "make olddefconfig".

Thanks,
Mirsad

--
Mirsad Goran Todorovac
Sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
-- 
System engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
The European Union