powerpc 5.10-rcN boot failures with RCU_SCALE_TEST=m

Hi all,

I'm having some difficulty tracking down a bug.

Some configurations of the powerpc kernel since somewhere in the 5.10 merge window fail to boot on some ppc64 systems. They hang while trying to bring up SMP. It seems to depend on the RCU_SCALE/PERF_TEST option. (It was renamed in the 5.10 merge window.)

I can reproduce it as follows with qemu tcg:

make -j64 pseries_le_defconfig
scripts/config -m RCU_SCALE_TEST
scripts/config -m RCU_PERF_TEST
make -j 64 vmlinux CC="ccache gcc"

qemu-system-ppc64 -cpu power9 -M pseries -m 1G -nographic -vga none -smp 4 -kernel vmlinux

...

[    0.036284][    T0] Mount-cache hash table entries: 8192 (order: 0, 65536 bytes, linear)
[    0.036481][    T0] Mountpoint-cache hash table entries: 8192 (order: 0, 65536 bytes, linear)
[    0.148168][    T1] POWER9 performance monitor hardware support registered
[    0.151118][    T1] rcu: Hierarchical SRCU implementation.
[    0.186660][    T1] smp: Bringing up secondary CPUs ...

<hangs>

I have no idea why RCU_SCALE/PERF_TEST would be causing this, but that seems to be what does it: if I don't set that, the kernel boots fine.

I've tried to git bisect it, but I keep getting different results:
always a random merge of a seemingly-unrelated subsystem tree - things like armsoc or integrity or input.

It appears to also depend on the way the kernel is booted. Testing with a Canonical kernel, so a slightly different config but including RCU_SCALE_TEST=m, I see:

Power8 host + KVM + grub         -> boots
Power9 host bare metal (kexec)   -> fails
Power9 host + KVM + grub         -> fails

Power9 host + KVM + qemu -kernel -> boots
qemu TCG + power9 cpu -> fails
qemu TCG + power8 cpu -> fails

Any ideas?

Kind regards,
Daniel

$ qemu-system-ppc64 -version
QEMU emulator version 4.2.1 (Debian 1:4.2-3ubuntu6.9)

$ gcc --version
gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0

It also happens when compiling with GCC 7 and 10.

Adding Mark Rutland on CC in case his similarly mystifying experience obtaining a fix for ARM has relevance. From what I could see, that was a delayed consequence of the x86/entry rewrite. It was similarly difficult to bisect.

Thanx, Paul

I am not sure if that is helpful but i checked it on my x86_64 system using the cross compiled for powerpc Linux kernel:

<snip>

urezki@pc638:~/data/coding/linux-rcu.git$ powerpc64-linux-gnu-gcc
--version
powerpc64-linux-gnu-gcc (Debian 8.3.0-2) 8.3.0
Copyright (C) 2018 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is
NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR
PURPOSE.

urezki@pc638:~/data/coding/linux-rcu.git$
<snip>

with ARCH=powerpc make -j64 pseries_defconfig configuration. I used the 5.10.0-rc1 kernel.

<snip>

urezki@pc638:~/data/coding/linux-rcu.git$ qemu-system-ppc64 --version
QEMU emulator version 3.1.0 (Debian 1:3.1+dfsg-8+deb10u8)
Copyright (c) 2003-2018 Fabrice Bellard and the QEMU Project developers
urezki@pc638:~/data/coding/linux-rcu.git$
<snip>

On my setup i can run the kernel with and without the modules which are in question. So

qemu-system-ppc64 -cpu power9 -M pseries -m 1G -nographic -vga none -smp 4 -kernel ./vmlinux

works for both cases, with RCU_SCALE and without.

Just in case, maybe this information can be useful also.

--
Vlad Rezki

One does not simply hang :)

It seems to be TASKS_RCU that is the key.

I don't need RCU_SCALE_TEST enabled, I can trigger it just with the following applied:

index 0ebe15a84985..f3500c95d6a1 100644
@@ -78,7 +78,7 @@ config TASKS_RCU_GENERIC
 	  task-based RCU implementations.  Not for manual selection.
 
 config TASKS_RCU
-	def_bool PREEMPTION
+	def_bool y
 	help
 	  This option enables a task-based RCU implementation that uses
 	  only voluntary context switch (not preemption!), idle, and

And bisect points to:
36dadef23fcc ("kprobes: Init kprobes in early_initcall")

Which moved init_kprobes() prior to SMP bringup.

For some reason when it gets stuck sysrq doesn't work, but I was able to get it into gdb and manually call handle_sysrq('t') to get the output below.

The SMP bringup stalls because _cpu_up() is blocked trying to take cpu_hotplug_lock for writing:

[  401.403132][    T0] task:swapper/0       state:D stack:12512 pid:    1 ppid:     0 flags:0x00000800
[  401.403502][    T0] Call Trace:
[  401.403907][    T0] [c0000000062c37d0] [c0000000062c3830] 0xc0000000062c3830 (unreliable)
[  401.404068][    T0] [c0000000062c39b0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.404189][    T0] [c0000000062c3a10] [c000000000b87228] __schedule+0x288/0x9b0
[  401.404257][    T0] [c0000000062c3ad0] [c000000000b879b8] schedule+0x68/0x120
[  401.404324][    T0] [c0000000062c3b00] [c000000000184ad4] percpu_down_write+0x164/0x170
[  401.404390][    T0] [c0000000062c3b50] [c000000000116b68] _cpu_up+0x68/0x280
[  401.404475][    T0] [c0000000062c3bb0] [c000000000116e70] cpu_up+0xf0/0x140
[  401.404546][    T0] [c0000000062c3c30] [c00000000011776c] bringup_nonboot_cpus+0xac/0xf0
[  401.404643][    T0] [c0000000062c3c80] [c000000000eea1b8] smp_init+0x40/0xcc
[  401.404727][    T0] [c0000000062c3ce0] [c000000000ec43dc] kernel_init_freeable+0x1e0/0x3a0
[  401.404799][    T0] [c0000000062c3db0] [c000000000011ec4] kernel_init+0x24/0x150
[  401.404958][    T0] [c0000000062c3e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c

It can't get it because kprobe_optimizer() has taken it for read and is now blocked waiting for synchronize_rcu_tasks():

[  401.418808][    T0] task:kworker/0:1     state:D stack:13392 pid:   12 ppid:     2 flags:0x00000800
[  401.418951][    T0] Workqueue: events kprobe_optimizer
[  401.419078][    T0] Call Trace:
[  401.419121][    T0] [c0000000062ef650] [c0000000062ef710] 0xc0000000062ef710 (unreliable)
[  401.419213][    T0] [c0000000062ef830] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.419281][    T0] [c0000000062ef890] [c000000000b87228] __schedule+0x288/0x9b0
[  401.419347][    T0] [c0000000062ef950] [c000000000b879b8] schedule+0x68/0x120
[  401.419415][    T0] [c0000000062ef980] [c000000000b8e664] schedule_timeout+0x2a4/0x340
[  401.419484][    T0] [c0000000062efa80] [c000000000b894ec] wait_for_completion+0x9c/0x170
[  401.419552][    T0] [c0000000062efae0] [c0000000001ac85c] __wait_rcu_gp+0x19c/0x210
[  401.419619][    T0] [c0000000062efb40] [c0000000001ac90c] synchronize_rcu_tasks_generic+0x3c/0x70
[  401.419690][    T0] [c0000000062efbe0] [c00000000022a3dc] kprobe_optimizer+0x1dc/0x470
[  401.419757][    T0] [c0000000062efc60] [c000000000136684] process_one_work+0x2f4/0x530
[  401.419823][    T0] [c0000000062efd20] [c000000000138d28] worker_thread+0x78/0x570
[  401.419891][    T0] [c0000000062efdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.419976][    T0] [c0000000062efe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c

But why is the synchronize_rcu_tasks() not completing?

Hopefully Paul can help there, otherwise I'll try and work out how to dump some RCU state when it gets stuck.

Full sysrq-t output below.

cheers

[  401.402512][    T0] sysrq: Show State
[  401.403132][    T0] task:swapper/0       state:D stack:12512 pid:    1 ppid:     0 flags:0x00000800
[  401.403502][    T0] Call Trace:
[  401.403907][    T0] [c0000000062c37d0] [c0000000062c3830] 0xc0000000062c3830 (unreliable)
[  401.404068][    T0] [c0000000062c39b0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.404189][    T0] [c0000000062c3a10] [c000000000b87228] __schedule+0x288/0x9b0
[  401.404257][    T0] [c0000000062c3ad0] [c000000000b879b8] schedule+0x68/0x120
[  401.404324][    T0] [c0000000062c3b00] [c000000000184ad4] percpu_down_write+0x164/0x170
[  401.404390][    T0] [c0000000062c3b50] [c000000000116b68] _cpu_up+0x68/0x280
[  401.404475][    T0] [c0000000062c3bb0] [c000000000116e70] cpu_up+0xf0/0x140
[  401.404546][    T0] [c0000000062c3c30] [c00000000011776c] bringup_nonboot_cpus+0xac/0xf0
[  401.404643][    T0] [c0000000062c3c80] [c000000000eea1b8] smp_init+0x40/0xcc
[  401.404727][    T0] [c0000000062c3ce0] [c000000000ec43dc] kernel_init_freeable+0x1e0/0x3a0
[  401.404799][    T0] [c0000000062c3db0] [c000000000011ec4] kernel_init+0x24/0x150
[  401.404958][    T0] [c0000000062c3e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.405221][    T0] task:kthreadd        state:S stack:13712 pid:    2 ppid:     0 flags:0x00000800
[  401.405326][    T0] Call Trace:
[  401.405380][    T0] [c0000000062c7a60] [c0000000062c7ac0] 0xc0000000062c7ac0 (unreliable)
[  401.405473][    T0] [c0000000062c7c40] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.405565][    T0] [c0000000062c7ca0] [c000000000b87228] __schedule+0x288/0x9b0
[  401.405639][    T0] [c0000000062c7d60] [c000000000b879b8] schedule+0x68/0x120
[  401.405720][    T0] [c0000000062c7d90] [c000000000143508] kthreadd+0x278/0x2f0
[  401.405798][    T0] [c0000000062c7e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.405908][    T0] task:rcu_gp          state:I stack:14576 pid:    3 ppid:     2 flags:0x00000800
[  401.407471][    T0] Call Trace:
[  401.407690][    T0] [c0000000062cba00] [c0000000062cba60] 0xc0000000062cba60 (unreliable)
[  401.407851][    T0] [c0000000062cbbe0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.407952][    T0] [c0000000062cbc40] [c000000000b87228] __schedule+0x288/0x9b0
[  401.408037][    T0] [c0000000062cbd00] [c000000000b879b8] schedule+0x68/0x120
[  401.408123][    T0] [c0000000062cbd30] [c000000000136ed4] rescuer_thread+0x2c4/0x3f0
[  401.408268][    T0] [c0000000062cbdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.408351][    T0] [c0000000062cbe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.408463][    T0] task:rcu_par_gp      state:I stack:14624 pid:    4 ppid:     2 flags:0x00000800
[  401.408629][    T0] Call Trace:
[  401.408725][    T0] [c0000000062cfa00] [c0000000062cfa60] 0xc0000000062cfa60 (unreliable)
[  401.408830][    T0] [c0000000062cfbe0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.408927][    T0] [c0000000062cfc40] [c000000000b87228] __schedule+0x288/0x9b0
[  401.409030][    T0] [c0000000062cfd00] [c000000000b879b8] schedule+0x68/0x120
[  401.409143][    T0] [c0000000062cfd30] [c000000000136ed4] rescuer_thread+0x2c4/0x3f0
[  401.409256][    T0] [c0000000062cfdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.409349][    T0] [c0000000062cfe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.409458][    T0] task:kworker/0:0     state:I stack:13888 pid:    5 ppid:     2 flags:0x00000800
[  401.409749][    T0] Workqueue:  0x0 (events)
[  401.409923][    T0] Call Trace:
[  401.409986][    T0] [c0000000062d39f0] [c0000000062d3a50] 0xc0000000062d3a50 (unreliable)
[  401.410125][    T0] [c0000000062d3bd0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.410263][    T0] [c0000000062d3c30] [c000000000b87228] __schedule+0x288/0x9b0
[  401.410371][    T0] [c0000000062d3cf0] [c000000000b879b8] schedule+0x68/0x120
[  401.410450][    T0] [c0000000062d3d20] [c000000000138dac] worker_thread+0xfc/0x570
[  401.410567][    T0] [c0000000062d3db0] [c000000000142424] kthread+0x194/0x1a0
[  401.410671][    T0] [c0000000062d3e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.410795][    T0] task:kworker/0:0H    state:I stack:14624 pid:    6 ppid:     2 flags:0x00000800
[  401.411024][    T0] Call Trace:
[  401.411117][    T0] [c0000000062d79f0] [c0000000062d7a50] 0xc0000000062d7a50 (unreliable)
[  401.411267][    T0] [c0000000062d7bd0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.411401][    T0] [c0000000062d7c30] [c000000000b87228] __schedule+0x288/0x9b0
[  401.411484][    T0] [c0000000062d7cf0] [c000000000b879b8] schedule+0x68/0x120
[  401.411575][    T0] [c0000000062d7d20] [c000000000138dac] worker_thread+0xfc/0x570
[  401.411666][    T0] [c0000000062d7db0] [c000000000142424] kthread+0x194/0x1a0
[  401.411722][    T0] [c0000000062d7e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.411809][    T0] task:kworker/u8:0    state:I stack:14624 pid:    7 ppid:     2 flags:0x00000800
[  401.411923][    T0] Call Trace:
[  401.411969][    T0] [c0000000062db9f0] [c0000000062dba50] 0xc0000000062dba50 (unreliable)
[  401.412045][    T0] [c0000000062dbbd0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.412143][    T0] [c0000000062dbc30] [c000000000b87228] __schedule+0x288/0x9b0
[  401.413324][    T0] [c0000000062dbcf0] [c000000000b879b8] schedule+0x68/0x120
[  401.413402][    T0] [c0000000062dbd20] [c000000000138dac] worker_thread+0xfc/0x570
[  401.413468][    T0] [c0000000062dbdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.413522][    T0] [c0000000062dbe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.413595][    T0] task:mm_percpu_wq    state:I stack:14624 pid:    8 ppid:     2 flags:0x00000800
[  401.413699][    T0] Call Trace:
[  401.413745][    T0] [c0000000062dfa00] [c0000000062dfa60] 0xc0000000062dfa60 (unreliable)
[  401.413826][    T0] [c0000000062dfbe0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.413894][    T0] [c0000000062dfc40] [c000000000b87228] __schedule+0x288/0x9b0
[  401.413960][    T0] [c0000000062dfd00] [c000000000b879b8] schedule+0x68/0x120
[  401.414025][    T0] [c0000000062dfd30] [c000000000136ed4] rescuer_thread+0x2c4/0x3f0
[  401.414105][    T0] [c0000000062dfdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.414185][    T0] [c0000000062dfe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.414275][    T0] task:ksoftirqd/0     state:S stack:14544 pid:    9 ppid:     2 flags:0x00000800
[  401.414506][    T0] Call Trace:
[  401.414729][    T0] [c0000000062e3a20] [c0000000062e3a80] 0xc0000000062e3a80 (unreliable)
[  401.415109][    T0] [c0000000062e3c00] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.415651][    T0] [c0000000062e3c60] [c000000000b87228] __schedule+0x288/0x9b0
[  401.415944][    T0] [c0000000062e3d20] [c000000000b879b8] schedule+0x68/0x120
[  401.416044][    T0] [c0000000062e3d50] [c000000000148774] smpboot_thread_fn+0x254/0x260
[  401.416104][    T0] [c0000000062e3db0] [c000000000142424] kthread+0x194/0x1a0
[  401.416177][    T0] [c0000000062e3e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.416261][    T0] task:rcu_sched       state:I stack:12928 pid:   10 ppid:     2 flags:0x00000800
[  401.416378][    T0] Call Trace:
[  401.416423][    T0] [c0000000062e7990] [c0000000062e7a50] 0xc0000000062e7a50 (unreliable)
[  401.416501][    T0] [c0000000062e7b70] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.416569][    T0] [c0000000062e7bd0] [c000000000b87228] __schedule+0x288/0x9b0
[  401.416633][    T0] [c0000000062e7c90] [c000000000b879b8] schedule+0x68/0x120
[  401.416705][    T0] [c0000000062e7cc0] [c0000000001b7b54] rcu_gp_kthread+0xa94/0xc00
[  401.416798][    T0] [c0000000062e7db0] [c000000000142424] kthread+0x194/0x1a0
[  401.416871][    T0] [c0000000062e7e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.416965][    T0] task:migration/0     state:S stack:14496 pid:   11 ppid:     2 flags:0x00000800
[  401.417050][    T0] Call Trace:
[  401.417092][    T0] [c0000000062eba20] [c0000000062ebaa0] 0xc0000000062ebaa0 (unreliable)
[  401.417206][    T0] [c0000000062ebc00] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.417397][    T0] [c0000000062ebc60] [c000000000b87228] __schedule+0x288/0x9b0
[  401.417631][    T0] [c0000000062ebd20] [c000000000b879b8] schedule+0x68/0x120
[  401.417930][    T0] [c0000000062ebd50] [c000000000148774] smpboot_thread_fn+0x254/0x260
[  401.418251][    T0] [c0000000062ebdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.418520][    T0] [c0000000062ebe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.418808][    T0] task:kworker/0:1     state:D stack:13392 pid:   12 ppid:     2 flags:0x00000800
[  401.418951][    T0] Workqueue: events kprobe_optimizer
[  401.419078][    T0] Call Trace:
[  401.419121][    T0] [c0000000062ef650] [c0000000062ef710] 0xc0000000062ef710 (unreliable)
[  401.419213][    T0] [c0000000062ef830] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.419281][    T0] [c0000000062ef890] [c000000000b87228] __schedule+0x288/0x9b0
[  401.419347][    T0] [c0000000062ef950] [c000000000b879b8] schedule+0x68/0x120
[  401.419415][    T0] [c0000000062ef980] [c000000000b8e664] schedule_timeout+0x2a4/0x340
[  401.419484][    T0] [c0000000062efa80] [c000000000b894ec] wait_for_completion+0x9c/0x170
[  401.419552][    T0] [c0000000062efae0] [c0000000001ac85c] __wait_rcu_gp+0x19c/0x210
[  401.419619][    T0] [c0000000062efb40] [c0000000001ac90c] synchronize_rcu_tasks_generic+0x3c/0x70
[  401.419690][    T0] [c0000000062efbe0] [c00000000022a3dc] kprobe_optimizer+0x1dc/0x470
[  401.419757][    T0] [c0000000062efc60] [c000000000136684] process_one_work+0x2f4/0x530
[  401.419823][    T0] [c0000000062efd20] [c000000000138d28] worker_thread+0x78/0x570
[  401.419891][    T0] [c0000000062efdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.419976][    T0] [c0000000062efe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.420051][    T0] task:cpuhp/0         state:S stack:14544 pid:   13 ppid:     2 flags:0x00000800
[  401.420136][    T0] Call Trace:
[  401.420197][    T0] [c0000000062ffa20] [c0000000062ffa80] 0xc0000000062ffa80 (unreliable)
[  401.420342][    T0] [c0000000062ffc00] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.420519][    T0] [c0000000062ffc60] [c000000000b87228] __schedule+0x288/0x9b0
[  401.420704][    T0] [c0000000062ffd20] [c000000000b879b8] schedule+0x68/0x120
[  401.420904][    T0] [c0000000062ffd50] [c000000000148774] smpboot_thread_fn+0x254/0x260
[  401.421134][    T0] [c0000000062ffdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.421487][    T0] [c0000000062ffe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.421834][    T0] task:cpuhp/1         state:S stack:13584 pid:   14 ppid:     2 flags:0x00000800
[  401.422146][    T0] Call Trace:
[  401.422233][    T0] [c0000000063c3a20] [c0000000063c3a80] 0xc0000000063c3a80 (unreliable)
[  401.422314][    T0] [c0000000063c3c00] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.422378][    T0] [c0000000063c3c60] [c000000000b87228] __schedule+0x288/0x9b0
[  401.422444][    T0] [c0000000063c3d20] [c000000000b879b8] schedule+0x68/0x120
[  401.422511][    T0] [c0000000063c3d50] [c000000000148774] smpboot_thread_fn+0x254/0x260
[  401.422575][    T0] [c0000000063c3db0] [c000000000142424] kthread+0x194/0x1a0
[  401.422658][    T0] [c0000000063c3e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.422742][    T0] task:migration/1     state:S stack:13472 pid:   15 ppid:     2 flags:0x00000800
[  401.422826][    T0] Call Trace:
[  401.422873][    T0] [c0000000063c7a20] [c0000000063c7aa0] 0xc0000000063c7aa0 (unreliable)
[  401.423195][    T0] [c0000000063c7c00] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.423285][    T0] [c0000000063c7c60] [c000000000b87228] __schedule+0x288/0x9b0
[  401.423354][    T0] [c0000000063c7d20] [c000000000b879b8] schedule+0x68/0x120
[  401.423421][    T0] [c0000000063c7d50] [c000000000148774] smpboot_thread_fn+0x254/0x260
[  401.423486][    T0] [c0000000063c7db0] [c000000000142424] kthread+0x194/0x1a0
[  401.423576][    T0] [c0000000063c7e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.423783][    T0] task:ksoftirqd/1     state:S stack:14544 pid:   16 ppid:     2 flags:0x00000800
[  401.424112][    T0] Call Trace:
[  401.424410][    T0] [c0000000063cba20] [c0000000063cba80] 0xc0000000063cba80 (unreliable)
[  401.424775][    T0] [c0000000063cbc00] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.425005][    T0] [c0000000063cbc60] [c000000000b87228] __schedule+0x288/0x9b0
[  401.425124][    T0] [c0000000063cbd20] [c000000000b879b8] schedule+0x68/0x120
[  401.425197][    T0] [c0000000063cbd50] [c000000000148774] smpboot_thread_fn+0x254/0x260
[  401.425299][    T0] [c0000000063cbdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.425398][    T0] [c0000000063cbe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.425504][    T0] task:kworker/1:0     state:I stack:14624 pid:   17 ppid:     2 flags:0x00000800
[  401.425684][    T0] Call Trace:
[  401.425748][    T0] [c0000000063cf9f0] [c0000000063cfa50] 0xc0000000063cfa50 (unreliable)
[  401.425845][    T0] [c0000000063cfbd0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.425916][    T0] [c0000000063cfc30] [c000000000b87228] __schedule+0x288/0x9b0
[  401.425983][    T0] [c0000000063cfcf0] [c000000000b879b8] schedule+0x68/0x120
[  401.426050][    T0] [c0000000063cfd20] [c000000000138dac] worker_thread+0xfc/0x570
[  401.426123][    T0] [c0000000063cfdb0] [c000000000142424] kthread+0x194/0x1a0
[  401.426229][    T0] [c0000000063cfe20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.426327][    T0] task:kworker/1:0H    state:I stack:14320 pid:   18 ppid:     2 flags:0x00000800
[  401.426494][    T0] Call Trace:
[  401.426577][    T0] [c0000000063d39f0] [c0000000063d3ab0] 0xc0000000063d3ab0 (unreliable)
[  401.426685][    T0] [c0000000063d3bd0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.426772][    T0] [c0000000063d3c30] [c000000000b87228] __schedule+0x288/0x9b0
[  401.426868][    T0] [c0000000063d3cf0] [c000000000b879b8] schedule+0x68/0x120
[  401.426969][    T0] [c0000000063d3d20] [c000000000138dac] worker_thread+0xfc/0x570
[  401.427082][    T0] [c0000000063d3db0] [c000000000142424] kthread+0x194/0x1a0
[  401.427244][    T0] [c0000000063d3e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.427403][    T0] task:kworker/0:2     state:I stack:14320 pid:   19 ppid:     2 flags:0x00000800
[  401.427624][    T0] Workqueue:  0x0 (events)
[  401.427768][    T0] Call Trace:
[  401.427840][    T0] [c0000000063d79f0] [c0000000063d7ab0] 0xc0000000063d7ab0 (unreliable)
[  401.427981][    T0] [c0000000063d7bd0] [c000000000019d70] __switch_to+0x2e0/0x4a0
[  401.428096][    T0] [c0000000063d7c30] [c000000000b87228] __schedule+0x288/0x9b0
[  401.428303][    T0] [c0000000063d7cf0] [c000000000b879b8] schedule+0x68/0x120
[  401.428394][    T0] [c0000000063d7d20] [c000000000138dac] worker_thread+0xfc/0x570
[  401.428470][    T0] [c0000000063d7db0] [c000000000142424] kthread+0x194/0x1a0
[  401.428575][    T0] [c0000000063d7e20] [c00000000000daf0] ret_from_kernel_thread+0x5c/0x6c
[  401.429454][    T0] Sched Debug Version: v0.11, 5.10.0-rc6-gcc-8.2.0-01356-ga1aeabd25a36-dirty #563
[  401.429604][    T0] ktime                                   : 383770.000000
[  401.429683][    T0] sched_clk                               : 401429.227980
[  401.429744][    T0] cpu_clk                                 : 401429.232778
[  401.429799][    T0] jiffies                                 : 4294975673
[  401.429926][    T0]
[  401.430003][    T0] sysctl_sched
[  401.430066][    T0]   .sysctl_sched_latency                    : 12.000000
[  401.430152][    T0]   .sysctl_sched_min_granularity            : 1.500000
[  401.430339][    T0]   .sysctl_sched_wakeup_granularity         : 2.000000
[  401.430524][    T0]   .sysctl_sched_child_runs_first           : 0
[  401.430688][    T0]   .sysctl_sched_features                   : 4139835
[  401.430900][    T0]   .sysctl_sched_tunable_scaling            : 1 (logarithmic)
[  401.431124][    T0]
[  401.431697][    T0] cpu#0
[  401.431766][    T0]   .nr_running                    : 0
[  401.431813][    T0]   .nr_switches                   : 1055
[  401.431865][    T0]   .nr_uninterruptible            : 2
[  401.432042][    T0]   .next_balance                  : 4294.937296
[  401.432103][    T0]   .curr->pid                     : 0
[  401.432195][    T0]   .clock                         : 401423.022270
[  401.432313][    T0]   .clock_task                    : 401423.022270
[  401.432415][    T0]   .avg_idle                      : 1000000
[  401.432488][    T0]   .max_idle_balance_cost         : 500000
[  401.432817][    T0]
[  401.433054][    T0] cfs_rq[0]:/
[  401.433196][    T0]   .exec_clock                    : 0.000000
[  401.433386][    T0]   .MIN_vruntime                  : 0.000001
[  401.433503][    T0]   .min_vruntime                  : 278.095255
[  401.433596][    T0]   .max_vruntime                  : 0.000001
[  401.433691][    T0]   .spread                        : 0.000000
[  401.433784][    T0]   .spread0                       : 0.000000
[  401.433886][    T0]   .nr_spread_over                : 0
[  401.433954][    T0]   .nr_running                    : 0
[  401.434039][    T0]   .load                          : 0
[  401.434127][    T0]   .load_avg                      : 0
[  401.434235][    T0]   .runnable_avg                  : 0
[  401.434341][    T0]   .util_avg                      : 0
[  401.434451][    T0]   .util_est_enqueued             : 0
[  401.434540][    T0]   .removed.load_avg              : 0
[  401.434611][    T0]   .removed.util_avg              : 0
[  401.434697][    T0]   .removed.runnable_avg          : 0
[  401.434811][    T0]   .tg_load_avg_contrib           : 0
[  401.434902][    T0]   .tg_load_avg                   : 0
[  401.435203][    T0]
[  401.435308][    T0] rt_rq[0]:
[  401.435394][    T0]   .rt_nr_running                 : 0
[  401.435481][    T0]   .rt_nr_migratory               : 0
[  401.435569][    T0]   .rt_throttled                  : 0
[  401.435678][    T0]   .rt_time                       : 0.000000
[  401.435772][    T0]   .rt_runtime                    : 950.000000
[  401.435942][    T0]
[  401.436017][    T0] dl_rq[0]:
[  401.436116][    T0]   .dl_nr_running                 : 0
[  401.436212][    T0]   .dl_nr_migratory               : 0
[  401.436301][    T0]   .dl_bw->bw                     : 996147
[  401.436386][    T0]   .dl_bw->total_bw               : 0
[  401.436476][    T0]
[  401.436560][    T0] runnable tasks:
[  401.436614][    T0]  S            task   PID         tree-key  switches  prio     wait-time             sum-exec        sum-sleep
[  401.436687][    T0] -------------------------------------------------------------------------------------------------------------
[  401.436875][    T0]  D       swapper/0     1        84.404220        26   120         0.000000        69.398526         0.000000 0 0 /
[  401.437357][    T0]  S        kthreadd     2        80.816484        18   120         0.000000        24.915098         0.000000 0 0 /
[  401.437554][    T0]  I          rcu_gp     3        26.218815         2   100         0.000000         1.771584         0.000000 0 0 /
[  401.437698][    T0]  I      rcu_par_gp     4        28.434004         2   100         0.000000         0.138216         0.000000 0 0 /
[  401.437853][    T0]  I     kworker/0:0     5        86.357041         8   120         0.000000         7.010072         0.000000 0 0 /
[  401.438002][    T0]  I    kworker/0:0H     6        32.481348         2   100         0.000000         0.097112         0.000000 0 0 /
[  401.438144][    T0]  I    kworker/u8:0     7        32.635000         2   120         0.000000         0.086604         0.000000 0 0 /
[  401.438368][    T0]  I    mm_percpu_wq     8        34.185643         2   100         0.000000         0.118036         0.000000 0 0 /
[  401.438544][    T0]  S     ksoftirqd/0     9        36.753489         3   120         0.000000         0.617720         0.000000 0 0 /
[  401.438686][    T0]  I       rcu_sched    10        79.402224         7   120         0.000000         9.592868         0.000000 0 0 /
[  401.438890][    T0]  S     migration/0    11         0.100901        98     0         0.000000        40.445210         0.000000 0 0 /
[  401.439041][    T0]  D     kworker/0:1    12        83.770462         4   120         0.000000         4.564404         0.000000 0 0 /
[  401.439230][    T0]  S         cpuhp/0    13        54.369911         3   120         0.000000         1.278230         0.000000 0 0 /
[  401.439412][    T0]  I     kworker/0:2    19       278.095255       384   120         0.000000       187.691038         0.000000 0 0 /
[  401.439939][    T0]
[  401.440140][    T0] cpu#1
[  401.440250][    T0]   .nr_running                    : 0
[  401.440331][    T0]   .nr_switches                   : 196
[  401.440434][    T0]   .nr_uninterruptible            : 0
[  401.440500][    T0]   .next_balance                  : 4294.937296
[  401.440552][    T0]   .curr->pid                     : 0
[  401.440631][    T0]   .clock                         : 401422.799786
[  401.440689][    T0]   .clock_task                    : 401422.799786
[  401.440777][    T0]   .avg_idle                      : 1000000
[  401.440865][    T0]   .max_idle_balance_cost         : 500000
[  401.440945][    T0]
[  401.441027][    T0] rt_rq[1]:
[  401.441076][    T0]   .rt_nr_running                 : 0
[  401.441127][    T0]   .rt_nr_migratory               : 0
[  401.441197][    T0]   .rt_throttled                  : 0
[  401.441255][    T0]   .rt_time                       : 0.000000
[  401.441315][    T0]   .rt_runtime                    : 950.000000
[  401.441395][    T0]
[  401.441445][    T0] dl_rq[1]:
[  401.441497][    T0]   .dl_nr_running                 : 0
[  401.441555][    T0]   .dl_nr_migratory               : 0
[  401.441609][    T0]   .dl_bw->bw                     : 996147
[  401.441665][    T0]   .dl_bw->total_bw               : 0
[  401.441717][    T0]
[  401.441755][    T0] runnable tasks:
[  401.441817][    T0]  S            task   PID         tree-key  switches  prio     wait-time             sum-exec        sum-sleep
[  401.441888][    T0] -------------------------------------------------------------------------------------------------------------
[  401.441995][    T0]  S         cpuhp/1    14         7.177520         3   120         0.000000        11.790932         0.000000 0 0 /
[  401.442211][    T0]  S     migration/1    15         0.000000        98     0         0.000000        39.188082         0.000000 0 0 /
[  401.442383][    T0]  S     ksoftirqd/1    16         0.312838         3   120         0.000000         3.826106         0.000000 0 0 /
[  401.442615][    T0]  I     kworker/1:0    17        -3.720346         3   120         0.000000         0.592222         0.000000 0 0 /
[  401.442879][    T0]  I    kworker/1:0H    18        -4.047847         3   100         0.000000         0.211754         0.000000 0 0 /
[  401.443037][    T0]
[  401.443407][    T0]
[  401.443407][    T0] Showing all locks held in the system:
[  401.443722][    T0] 2 locks held by swapper/0/1:
[  401.443859][    T0]  #0: c000000000f6be60 (cpu_add_remove_lock){....}-{3:3}, at: cpu_up+0xcc/0x140
[  401.444836][    T0]  #1: c000000000f6bdd0 (cpu_hotplug_lock){....}-{0:0}, at: _cpu_up+0x68/0x280
[  401.445096][    T0] 5 locks held by kworker/0:1/12:
[  401.445223][    T0]  #0: c000000006070138 ((wq_completion)events){....}-{0:0}, at: process_one_work+0x278/0x530
[  401.445408][    T0]  #1: c0000000062efcc0 ((optimizing_work).work){....}-{0:0}, at: process_one_work+0x278/0x530
[  401.445528][    T0]  #2: c00000000107de60 (kprobe_mutex){....}-{3:3}, at: kprobe_optimizer+0x50/0x470
[  401.445610][    T0]  #3: c000000000f6bdd0 (cpu_hotplug_lock){....}-{0:0}, at: kprobe_optimizer+0x58/0x470
[  401.445746][    T0]  #4: c000000000f6d018 (text_mutex){....}-{3:3}, at: kprobe_optimizer+0x70/0x470
[  401.445895][    T0]
[  401.445934][    T0] =============================================
[  401.445934][    T0]
[  401.446043][    T0] Showing busy workqueues and worker pools:
[  401.446139][    T0] workqueue events: flags=0x0
[  401.446275][    T0]   pwq 0: cpus=0 node=0 flags=0x0 nice=0 active=1/256 refcnt=2
[  401.446602][    T0]     in-flight: 12:kprobe_optimizer
[  401.447083][    T0] pool 0: cpus=0 node=0 flags=0x0 nice=0 hung=0s workers=3 idle: 19 5

I think that it is because RCU is not fully initialized by that time.

The 36dadef23fcc ("kprobes: Init kprobes in early_initcall") patch switches to early_initcall() that has a higher priority sequence than core_initcall() that is used to complete an RCU setup in the rcu_set_runtime_mode().

--
Vlad Rezki

...

Yeah that would explain it :)

I was looking at debug_lockdep_rcu_enabled(), which is:

noinstr int notrace debug_lockdep_rcu_enabled(void)

{
	return rcu_scheduler_active != RCU_SCHEDULER_INACTIVE && debug_locks &&
	       current->lockdep_recursion == 0;
}

That is not firing any warnings for me because rcu_scheduler_active is:

(gdb) p/x rcu_scheduler_active
$1 = 0x1

Which is:

#define RCU_SCHEDULER_INIT 1

But that's different to RCU_SCHEDULER_RUNNING, which is set in rcu_set_runtime_mode() as you mentioned:

static int __init rcu_set_runtime_mode(void)

{
	rcu_test_sync_prims();
	rcu_scheduler_active = RCU_SCHEDULER_RUNNING;
	kfree_rcu_scheduler_running();
	rcu_test_sync_prims();
	return 0;
}

The comment on rcu_scheduler_active implies that once we're at RCU_SCHEDULER_INIT things should work:

/*
* The rcu_scheduler_active variable is initialized to the value
* RCU_SCHEDULER_INACTIVE and transitions RCU_SCHEDULER_INIT just before the
* first task is spawned. So when this variable is RCU_SCHEDULER_INACTIVE,
* RCU can assume that there is but one task, allowing RCU to (for example)
* optimize synchronize_rcu() to a simple barrier(). When this variable
* is RCU_SCHEDULER_INIT, RCU must actually do all the hard work required
* to detect real grace periods. This variable is also used to suppress
* boot-time false positives from lockdep-RCU error checking. Finally, it
* transitions from RCU_SCHEDULER_INIT to RCU_SCHEDULER_RUNNING after RCU
* is fully initialized, including all of its kthreads having been spawned. */

So I'm not sure, the comments and the debug checks imply that it is OK for kprobes to be using RCU this early.

I guess I'll keep digging.

cheers

Agree with that.

BTW, since you can reproduce it and have a test setup, could you please check that:

<snip>
-core_initcall(rcu_set_runtime_mode);
+early_initcall(rcu_set_runtime_mode);
<snip>

Just in case. The the synchronize_rcu_tasks() gets blocked:

<snip>
void __wait_rcu_gp(bool checktiny, int n, call_rcu_func_t *crcu_array,

    if (crcu_array[j] == crcu_array[i])
                                break;
        if (j == i) {
            wait_for_completion(&rs_array[i].completion); <--- here
            destroy_rcu_head_on_stack(&rs_array[i].head);
        }

...
<snip>

but that is obvious when looking at your full traces.

Sounds like it should be possible.

Thank you! I also will dig further with that even though i do not have a setup for reproducing it.

--
Vlad Rezki

OK. Seems i have understood why the synchronize_rcu_tasks() is not doing progress waiting on complition. Actually the GP kthreads are not spawned by the time when early_initcall callbacks gets invoked.

It means that callbacks will not be processed because GP kthreads do not exist, so wakeme_after_rcu() is not invoked, thus does not signal about that a grace period has elapsed.

<snip>

index 35bdcfd84d42..c5422bba7fe7 100644  
@@ -241,7 +241,7 @@ static int __noreturn rcu_tasks_kthread(void *arg)
        }
 }
 
-/* Spawn RCU-tasks grace-period kthread, e.g., at core_initcall() time. */
+/* Spawn RCU-tasks grace-period kthread at early_initcall() time. */
 static void __init rcu_spawn_tasks_kthread_generic(struct rcu_tasks *rtp)
 {
        struct task_struct *t;

@@ -564,7 +564,7 @@ static int __init rcu_spawn_tasks_kthread(void)
        rcu_spawn_tasks_kthread_generic(&rcu_tasks);
        return 0;
 }
-core_initcall(rcu_spawn_tasks_kthread);
+early_initcall(rcu_spawn_tasks_kthread);
 
 #if !defined(CONFIG_TINY_RCU)
 void show_rcu_tasks_classic_gp_kthread(void)

@@ -692,7 +692,7 @@ static int __init rcu_spawn_tasks_rude_kthread(void)
        rcu_spawn_tasks_kthread_generic(&rcu_tasks_rude);
        return 0;
 }
-core_initcall(rcu_spawn_tasks_rude_kthread);
+early_initcall(rcu_spawn_tasks_rude_kthread);
 
 #if !defined(CONFIG_TINY_RCU)
 void show_rcu_tasks_rude_gp_kthread(void)

@@ -1193,7 +1193,7 @@ static int __init rcu_spawn_tasks_trace_kthread(void)
        rcu_spawn_tasks_kthread_generic(&rcu_tasks_trace);
        return 0;
 }
-core_initcall(rcu_spawn_tasks_trace_kthread);
+early_initcall(rcu_spawn_tasks_trace_kthread);
 
 #if !defined(CONFIG_TINY_RCU)
 void show_rcu_tasks_trace_gp_kthread(void)

index 39334d2d2b37..a251fc705abd 100644  
@@ -133,7 +133,7 @@ EXPORT_SYMBOL(rcu_read_lock_sched_held);
  * that if the user specifies both rcu_expedited and rcu_normal, then
  * rcu_normal wins.  (Except during the time period during boot from
  * when the first task is spawned until the rcu_set_runtime_mode()
- * core_initcall() is invoked, at which point everything is expedited.)
+ * early_initcall() is invoked, at which point everything is expedited.)
  */
 

ol rcu_gp_is_normal(void)
{
@@ -235,7 +235,7 @@ static int __init rcu_set_runtime_mode(void)

        rcu_test_sync_prims();
        return 0;

}
-core_initcall(rcu_set_runtime_mode);
+early_initcall(rcu_set_runtime_mode);

#endif /* #if !defined(CONFIG_TINY_RCU) || defined(CONFIG_SRCU) */
<snip>

Appreciate if you can test on your setup above patch!

--
Vlad Rezki