From: Daniel Axtens <hidden> Date: 2020-11-27 02:04:07
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.
From: "Paul E. McKenney" <paulmck@kernel.org> Date: 2020-11-27 15:52:02
On Fri, Nov 27, 2020 at 01:02:29PM +1100, Daniel Axtens wrote:
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.)
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 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.
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 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
From: Michael Ellerman <mpe@ellerman.id.au> Date: 2020-12-02 14:06:24
Daniel Axtens [off-list ref] writes:
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>
One does not simply hang :)
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.
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:
On Thu, Dec 03, 2020 at 01:03:32AM +1100, Michael Ellerman wrote:
quoted hunk
Daniel Axtens [off-list ref] writes:
quoted
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>
One does not simply hang :)
quoted
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.
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:
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?
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
I think that it is because RCU is not fully initialized by that time.
Yeah that would explain it :)
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().
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
I think that it is because RCU is not fully initialized by that time.
Yeah that would explain it :)
quoted
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().
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
Agree with that.
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;
}
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.
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.
Sounds like it should be possible.
I guess I'll keep digging.
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>