On Tue, Aug 9, 2022 at 4:14 PM Paul E. McKenney <paulmck@xxxxxxxxxx> wrote:
>
> On Tue, Aug 09, 2022 at 11:19:00AM +0200, Sedat Dilek wrote:
> > On Tue, Aug 9, 2022 at 11:06 AM Sedat Dilek <sedat.dilek@xxxxxxxxx> wrote:
> > >
> > > On Mon, Aug 8, 2022 at 3:43 PM Paul E. McKenney <paulmck@xxxxxxxxxx> wrote:
> > > >
> > > > On Sun, Aug 07, 2022 at 08:56:25AM +0200, Greg KH wrote:
> > > > > On Sat, Aug 06, 2022 at 09:32:47AM -0700, Paul E. McKenney wrote:
> > > > > > On Sat, Aug 06, 2022 at 08:31:26AM +0200, Sedat Dilek wrote:
> > > > > > > Hi Al and Paul,
> > > > > > >
> > > > > > > I pulled latest vfs-next on top of Linux v5.19 and see this in dmesg-logs:
> > > > > > >
> > > > > > > root# LC_ALL=C dmesg -T | egrep -B5 -A15 'Call Trace:'
> > > > > > > [Sat Aug 6 06:51:15 2022] Bluetooth: SCO socket layer initialized
> > > > > > > [Sat Aug 6 06:51:15 2022] rcu: INFO: rcu_preempt detected expedited
> > > > > > > stalls on CPUs/tasks: { 0-... } 6 jiffies s: 101 root: 0x1/.
> > > > > >
> > > > > > This is because of the CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20 in your
> > > > > > .config file. This is selected in kernels built with CONFIG_ANDROID=y,
> > > > > > and results in an ultra-short 20-millisecond RCU CPU stall timeout for
> > > > > > expedited grace periods. Yes, the Android guys want and are getting
> > > > > > milliseconds-scale response times from synchronize_rcu_expedited().
> > > > > >
> > > > > > The last time someone ran into this, the upshot was that CONFIG_ANDROID
> > > > > > was to be removed: https://lwn.net/Articles/899743/
> > > > > >
> > > > > > My guess is that the CONFIG_ANDROID-removal patches are still on their way
> > > > > > into mainline (they are in -next), but I added Greg KH and Christoph on CC
> > > > > > just in case some other issue arose.
> > > > >
> > > > > Not that I know of, those changes are all now in Linus's tree.
> > > >
> > > > And now that I do another pull, I do see them, thank you!
> > > >
> > > > So Sedat and Ben can just merge current mainline and be fine.
> > > >
> > >
> > > For the records:
> > >
> > > commit 1045a06724f322ed61f1ffb994427c7bdbe64647
> > > "remove CONFIG_ANDROID"
> > >
> > > diff --git a/kernel/rcu/Kconfig.debug b/kernel/rcu/Kconfig.debug
> > > index 9b64e55d4f615..e875f4f889656 100644
> > > --- a/kernel/rcu/Kconfig.debug
> > > +++ b/kernel/rcu/Kconfig.debug
> > > @@ -86,8 +86,7 @@ config RCU_EXP_CPU_STALL_TIMEOUT
> > > int "Expedited RCU CPU stall timeout in milliseconds"
> > > depends on RCU_STALL_COMMON
> > > range 0 21000
> > > - default 20 if ANDROID
> > > - default 0 if !ANDROID
> > > + default 0
> > > help
> > > If a given expedited RCU grace period extends more than the
> > > specified number of milliseconds, a CPU stall warning is printed.
> > >
> > > -Sedat-
> > >
> > > [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=1045a06724f322ed61f1ffb994427c7bdbe64647
> >
> > Hmm, with latest Debian-kernel I see the same call-trace as reported:
> >
> > root# grep -B5 -A15 'Call Trace:' dmesg-T_5.19.0-trunk-amd64.txt
> > 836-[Tue Aug 9 10:56:52 2022] iwlwifi 0000:01:00.0 wlp1s0: renamed from wlan0
> > 837-[Tue Aug 9 10:56:52 2022] rcu: INFO: rcu_preempt detected
> > expedited stalls on CPUs/tasks: { 2-... } 6 jiffies s: 213 root: 0x4/.
>
> Given only 6 jiffies (then 25, then 44, and so on), this kernel still
> has ANDROID, and thus CONFIG_RCU_EXP_CPU_STALL_TIMEOUT=20, correct?
>
> Or are we seeing some other bug here?
>
This Debian-kernel has CONFIG_ANDROID=y.
No new bugs - just a confirmation.
-Sedat-
> Thanx, Paul
>
> > 838-[Tue Aug 9 10:56:52 2022] rcu: blocking rcu_node structures
> > (internal RCU debug):
> > 839-[Tue Aug 9 10:56:52 2022] Task dump for CPU 2:
> > 840-[Tue Aug 9 10:56:52 2022] task:systemd-udevd state:R running
> > task stack: 0 pid: 347 ppid: 303 flags:0x00004008
> > 841:[Tue Aug 9 10:56:52 2022] Call Trace:
> > 842-[Tue Aug 9 10:56:52 2022] <TASK>
> > 843-[Tue Aug 9 10:56:52 2022] ? change_page_attr_set_clr+0x155/0x1c0
> > 844-[Tue Aug 9 10:56:52 2022] ? ftrace_module_enable+0xad/0x370
> > 845-[Tue Aug 9 10:56:52 2022] ? load_module+0x1bbc/0x2050
> > 846-[Tue Aug 9 10:56:52 2022] ? __do_sys_finit_module+0xb4/0x130
> > 847-[Tue Aug 9 10:56:52 2022] ? __do_sys_finit_module+0xb4/0x130
> > 848-[Tue Aug 9 10:56:52 2022] ? do_syscall_64+0x3b/0xc0
> > 849-[Tue Aug 9 10:56:52 2022] ? entry_SYSCALL_64_after_hwframe+0x63/0xcd
> > 850-[Tue Aug 9 10:56:52 2022] </TASK>
> > 851-[Tue Aug 9 10:56:52 2022] rcu: INFO: rcu_preempt detected
> > expedited stalls on CPUs/tasks: { 2-... } 25 jiffies s: 213 root:
> > 0x4/.
> > 852-[Tue Aug 9 10:56:52 2022] rcu: blocking rcu_node structures
> > (internal RCU debug):
> > 853-[Tue Aug 9 10:56:52 2022] Task dump for CPU 2:
> > 854-[Tue Aug 9 10:56:52 2022] task:systemd-udevd state:R running
> > task stack: 0 pid: 347 ppid: 303 flags:0x00004008
> > 855:[Tue Aug 9 10:56:52 2022] Call Trace:
> > 856-[Tue Aug 9 10:56:52 2022] <TASK>
> > 857-[Tue Aug 9 10:56:52 2022] ? change_page_attr_set_clr+0x155/0x1c0
> > 858-[Tue Aug 9 10:56:52 2022] ? ftrace_module_enable+0xad/0x370
> > 859-[Tue Aug 9 10:56:52 2022] ? load_module+0x1bbc/0x2050
> > 860-[Tue Aug 9 10:56:52 2022] ? __do_sys_finit_module+0xb4/0x130
> > 861-[Tue Aug 9 10:56:52 2022] ? __do_sys_finit_module+0xb4/0x130
> > 862-[Tue Aug 9 10:56:52 2022] ? do_syscall_64+0x3b/0xc0
> > 863-[Tue Aug 9 10:56:52 2022] ? entry_SYSCALL_64_after_hwframe+0x63/0xcd
> > 864-[Tue Aug 9 10:56:52 2022] </TASK>
> > 865-[Tue Aug 9 10:56:53 2022] rcu: INFO: rcu_preempt detected
> > expedited stalls on CPUs/tasks: { 2-... } 44 jiffies s: 213 root:
> > 0x4/.
> > 866-[Tue Aug 9 10:56:53 2022] rcu: blocking rcu_node structures
> > (internal RCU debug):
> > 867-[Tue Aug 9 10:56:53 2022] Task dump for CPU 2:
> > 868-[Tue Aug 9 10:56:53 2022] task:systemd-udevd state:R running
> > task stack: 0 pid: 347 ppid: 303 flags:0x00004008
> > 869:[Tue Aug 9 10:56:53 2022] Call Trace:
> > 870-[Tue Aug 9 10:56:53 2022] <TASK>
> > 871-[Tue Aug 9 10:56:53 2022] ? change_page_attr_set_clr+0x155/0x1c0
> > 872-[Tue Aug 9 10:56:53 2022] ? ftrace_module_enable+0xad/0x370
> > 873-[Tue Aug 9 10:56:53 2022] ? load_module+0x1bbc/0x2050
> > 874-[Tue Aug 9 10:56:53 2022] ? __do_sys_finit_module+0xb4/0x130
> > 875-[Tue Aug 9 10:56:53 2022] ? __do_sys_finit_module+0xb4/0x130
> > 876-[Tue Aug 9 10:56:53 2022] ? do_syscall_64+0x3b/0xc0
> > 877-[Tue Aug 9 10:56:53 2022] ? entry_SYSCALL_64_after_hwframe+0x63/0xcd
> > 878-[Tue Aug 9 10:56:53 2022] </TASK>
> > 879-[Tue Aug 9 10:56:53 2022] rcu: INFO: rcu_preempt detected
> > expedited stalls on CPUs/tasks: { 2-... } 63 jiffies s: 213 root:
> > 0x4/.
> > 880-[Tue Aug 9 10:56:53 2022] rcu: blocking rcu_node structures
> > (internal RCU debug):
> > 881-[Tue Aug 9 10:56:53 2022] Task dump for CPU 2:
> > 882-[Tue Aug 9 10:56:53 2022] task:systemd-udevd state:R running
> > task stack: 0 pid: 347 ppid: 303 flags:0x00004008
> > 883:[Tue Aug 9 10:56:53 2022] Call Trace:
> > 884-[Tue Aug 9 10:56:53 2022] <TASK>
> > 885-[Tue Aug 9 10:56:53 2022] ? change_page_attr_set_clr+0x155/0x1c0
> > 886-[Tue Aug 9 10:56:53 2022] ? ftrace_module_enable+0xad/0x370
> > 887-[Tue Aug 9 10:56:53 2022] ? load_module+0x1bbc/0x2050
> > 888-[Tue Aug 9 10:56:53 2022] ? __do_sys_finit_module+0xb4/0x130
> > 889-[Tue Aug 9 10:56:53 2022] ? __do_sys_finit_module+0xb4/0x130
> > 890-[Tue Aug 9 10:56:53 2022] ? do_syscall_64+0x3b/0xc0
> > 891-[Tue Aug 9 10:56:53 2022] ? entry_SYSCALL_64_after_hwframe+0x63/0xcd
> > 892-[Tue Aug 9 10:56:53 2022] </TASK>
> > 893-[Tue Aug 9 10:56:53 2022] zram0: detected capacity change from 0 to 1004656
> > 894-[Tue Aug 9 10:56:53 2022] i915 0000:00:02.0: vgaarb: deactivate vga console
> > 895-[Tue Aug 9 10:56:53 2022] Console: switching to colour dummy device 80x25
> > 896-[Tue Aug 9 10:56:53 2022] i915 0000:00:02.0: vgaarb: changed VGA
> > decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem
> > 897-[Tue Aug 9 10:56:53 2022] [drm] Initialized i915 1.6.0 20201103
> > for 0000:00:02.0 on minor 0
> > 898-[Tue Aug 9 10:56:53 2022] ACPI: video: Video Device [GFX0]
> > (multi-head: yes rom: no post: no)
> >
> > Just see Ben integrated [1]:
> >
> > android: Remove CONFIG_ANDROID
> > - Drop "wireguard: Clear keys after suspend despite CONFIG_ANDROID=y"
> > - pm/sleep: Add PM_USERSPACE_AUTOSLEEP Kconfig
> > - remove CONFIG_ANDROID
> > - Enable/disable ANDROID_BINDER_IPC to match previous configuration
> >
> > This fixes two more cases where kernel behaviour was changed by
> > CONFIG_ANDROID.
> >
> > -Sedat-
> >
> > [1] https://salsa.debian.org/kernel-team/linux/-/commit/78fcd943947d24bb162fcebf1a9ca86795e1b2b1
