On Wed, Aug 10, 2022 at 08:07:15AM +0200, Sedat Dilek wrote:
> 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.
Very good, and thank you for the confirmation!
Thanx, Paul
> -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
