On Fri, Nov 25, 2022 at 07:33:46PM +0100, Uladzislau Rezki wrote:
> > Hello, Uladzislau,
> >
> > Here is where I placed that probe code and the corresponding output.
> > Where should I be placing it instead?
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > index 219b4b516f387..308cbc5e68a64 100644
> > --- a/kernel/rcu/tree.c
> > +++ b/kernel/rcu/tree.c
> > @@ -4546,8 +4546,17 @@ void rcu_scheduler_starting(void)
> > local_irq_restore(flags);
> >
> > // Switch out of early boot mode.
> > + pr_err("-> [%d] Invoke synchronize_rcu(): seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > + synchronize_rcu();
> > + pr_err("-> [%d] Done. A seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > rcu_scheduler_active = RCU_SCHEDULER_INIT;
> > + pr_err("-> [%d] Invoke synchronize_rcu(): seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > + synchronize_rcu();
> > + pr_err("-> [%d] Done. A seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > rcu_test_sync_prims();
> > + pr_err("-> [%d] Invoke synchronize_rcu(): seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > + synchronize_rcu();
> > + pr_err("-> [%d] Done. A seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > }
> >
> > /*
> > @@ -4817,6 +4826,9 @@ void __init rcu_init(void)
> >
> > kfree_rcu_batch_init();
> > rcu_bootup_announce();
> > + pr_err("-> [%d] Invoke synchronize_rcu(): seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > + synchronize_rcu();
> > + pr_err("-> [%d] Done. A seq number: %lu\n", current->pid, get_state_synchronize_rcu());
> > sanitize_kthread_prio();
> > rcu_init_geometry();
> > rcu_init_one();
> > diff --git a/kernel/rcu/update.c b/kernel/rcu/update.c
> > index 7b1e183b0eb23..2993be46f81d5 100644
> > --- a/kernel/rcu/update.c
> > +++ b/kernel/rcu/update.c
> > @@ -557,9 +557,12 @@ struct early_boot_kfree_rcu {
> > static void early_boot_test_call_rcu(void)
> > {
> > static struct rcu_head head;
> > + int idx;
> > static struct rcu_head shead;
> > struct early_boot_kfree_rcu *rhp;
> >
> > + idx = srcu_down_read(&early_srcu);
> > + srcu_up_read(&early_srcu, idx);
> > call_rcu(&head, test_callback);
> > early_srcu_cookie = start_poll_synchronize_srcu(&early_srcu);
> > call_srcu(&early_srcu, &shead, test_callback);
> >
> > ------------------------------------------------------------------------
> >
> > [ 0.016333] rcu: -> [0] Invoke synchronize_rcu(): seq number: 12
> > [ 0.016334] rcu: -> [0] Done. A seq number: 16
> > [ 0.114209] rcu: -> [0] Invoke synchronize_rcu(): seq number: 32
> > [ 0.114662] rcu: -> [0] Done. A seq number: 36
> > [ 0.115191] rcu: -> [0] Invoke synchronize_rcu(): seq number: 36
> > [ 0.115684] rcu: -> [0] Done. A seq number: 40
> > [ 0.116046] rcu: -> [0] Invoke synchronize_rcu(): seq number: 48
> > [ 0.116202] rcu: -> [0] Done. A seq number: 52
>
> Just for a backup:
>
> urezki@pc638:~/data/raid0/coding/linux-rcu.git$ git diff
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index 76973d716921..dea7dcc6973b 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -3107,6 +3107,18 @@ static void kfree_rcu_work(struct work_struct *work)
> }
> rcu_lock_release(&rcu_callback_map);
>
> + {
> + unsigned long seq_a;
> + unsigned long seq_b;
> +
> + seq_a = get_state_synchronize_rcu();
> + synchronize_rcu();
> + seq_b = get_state_synchronize_rcu();
> +
> + if (seq_a == seq_b)
> + BUG();
> + }
> +
> raw_spin_lock_irqsave(&krcp->lock, flags);
> if (put_cached_bnode(krcp, bkvhead[i]))
> bkvhead[i] = NULL;
> urezki@pc638:~/data/raid0/coding/linux-rcu.git$ head -10 Makefile
> # SPDX-License-Identifier: GPL-2.0
> VERSION = 6
> PATCHLEVEL = 1
> SUBLEVEL = 0
> EXTRAVERSION = -rc1
> NAME = Hurr durr I'ma ninja sloth
>
> # *DOCUMENTATION*
> # To see a list of typical targets execute "make help"
> # More info can be located in ./README
> urezki@pc638:~/data/raid0/coding/linux-rcu.git
>
> urezki@pc638:~/data/raid0/coding/linux-rcu.git$ ../scripts/rcuscale.sh
> tools/testing/selftests/rcutorture/initrd/init already exists, no need to create it
> Results directory: /home/urezki/data/raid0/coding/linux-rcu.git/tools/testing/selftests/rcutorture/res/2022.11.25-17.50.32
> tools/testing/selftests/rcutorture/bin/kvm.sh --memory 10G --torture rcuscale --allcpus --duration 1 --kconfig CONFIG_NR_CPUS=64 --kconfig CONFIG_RCU_NOCB_CPU=y --kconfig CONFIG_RCU_NOCB_CPU_DEFAULT_ALL=y --kconfig CONFIG_RCU_LAZY=n --bootargs rcuscale.kfree_rcu_test=1 rcuscale.kfree_nthreads=16 rcuscale.holdoff=20 rcuscale.kfree_loops=10000 torture.disable_onoff_at_boot --trust-make
> ----Start batch 1: Fri 25 Nov 2022 05:50:32 PM CET
> TREE 64: Starting build. Fri 25 Nov 2022 05:50:32 PM CET
> TREE 64: Waiting for build to complete. Fri 25 Nov 2022 05:50:32 PM CET
> TREE 64: Build complete. Fri 25 Nov 2022 05:50:37 PM CET
> ---- TREE 64: Kernel present. Fri 25 Nov 2022 05:50:37 PM CET
> ---- Starting kernels. Fri 25 Nov 2022 05:50:37 PM CET
>
>
>
> ---- All kernel runs complete. Fri 25 Nov 2022 05:54:37 PM CET
> ---- TREE 64: Build/run results:
> --- Fri 25 Nov 2022 05:50:32 PM CET: Starting build, PID 1284995
> --- Fri 25 Nov 2022 05:50:37 PM CET: Starting kernel
> --- Fri 25 Nov 2022 05:50:37 PM CET: Starting kernel, PID 1291757
> QEMU 5.2.0 monitor - type 'help' for more information
> (qemu) Monitoring qemu job at pid 1291776 Fri 25 Nov 2022 05:50:47 PM CET
> Grace period for qemu job at pid 1291776 Fri 25 Nov 2022 05:51:37 PM CET
> WARNING: Assertion failure in /home/urezki/data/raid0/coding/linux-rcu.git/tools/testing/selftests/rcutorture/res/2022.11.25-17.50.32/TREE/console.log TREE
> WARNING: Summary: Bugs: 4 Call Traces: 6
>
> urezki@pc638:~/data/raid0/coding/linux-rcu.git$ cat ../scripts/rcuscale.sh
> #! /usr/bin/env bash
>
> LOOPS=10
>
> for (( i=0; i<$LOOPS; i++ )); do
> tools/testing/selftests/rcutorture/bin/kvm.sh --memory 10G --torture rcuscale --allcpus --duration 1 \
> --kconfig CONFIG_NR_CPUS=64 \
> --kconfig CONFIG_RCU_NOCB_CPU=y \
> --kconfig CONFIG_RCU_NOCB_CPU_DEFAULT_ALL=y \
> --kconfig CONFIG_RCU_LAZY=n \
> --bootargs "rcuscale.kfree_rcu_test=1 rcuscale.kfree_nthreads=16 rcuscale.holdoff=20 rcuscale.kfree_loops=10000 torture.disable_onoff_at_boot" --trust-make
> echo "Done $i"
> done
> urezki@pc638:~/data/raid0/coding/linux-rcu.git$
>
> [ 0.911180] ------------[ cut here ]------------
> [ 0.911747] kernel BUG at kernel/rcu/tree.c:3119!
> [ 0.912332] invalid opcode: 0000 [#1] PREEMPT SMP NOPTI
> [ 0.912984] CPU: 0 PID: 408 Comm: kworker/0:2 Not tainted 6.1.0-rc1-00098-gcda6ad040ade-dirty #1509
> [ 0.913325] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014
> [ 0.913325] Workqueue: events kfree_rcu_work
> [ 0.913325] RIP: 0010:kfree_rcu_work+0x348/0x350
> [ 0.913325] Code: 85 48 ff ff ff 48 89 df e8 65 61 ff ff e9 3b ff ff ff c7 44 24 08 01 00 00 00 49 8b 6d 00 e9 49 fd ff ff 0f 0b e9 e5 fe ff ff <0f> 0b e8 91 5d af 00 90 48 83 ec 40 65 48 8b 04 25 28 00 00 00 48
> [ 0.913325] RSP: 0018:ffff9fc680fc3e08 EFLAGS: 00010246
> [ 0.913325] RAX: 0000000000000068 RBX: 0000000000000068 RCX: 0000000000000000
> [ 0.913325] RDX: 0000000000000000 RSI: 0000000000000287 RDI: ffffffffab32f9f8
> [ 0.913325] RBP: ffff8b2a45525000 R08: ffffffffab32ee30 R09: ffffffffab32ee30
> [ 0.913325] R10: 0000000000000000 R11: 0000000000000001 R12: ffff8b2a410d5580
> [ 0.913325] R13: ffff9fc680fc3e28 R14: ffff8b2a45524000 R15: ffff8b2c34e1bb28
> [ 0.913325] FS: 0000000000000000(0000) GS:ffff8b2c34e00000(0000) knlGS:0000000000000000
> [ 0.913325] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 0.913325] CR2: ffff8b2c3ffff000 CR3: 000000029aa0c000 CR4: 00000000000006f0
> [ 0.913325] Call Trace:
> [ 0.913325] <TASK>
> [ 0.913325] ? finish_task_switch.isra.0+0x89/0x260
> [ 0.913325] process_one_work+0x1b4/0x310
> [ 0.913325] worker_thread+0x48/0x3c0
> [ 0.913325] ? process_one_work+0x310/0x310
> [ 0.913325] kthread+0xe2/0x110
> [ 0.913325] ? kthread_complete_and_exit+0x20/0x20
> [ 0.913325] ret_from_fork+0x22/0x30
> [ 0.913325] </TASK>
> [ 0.913325] Modules linked in:
> [ 0.930724] calling init_posix_timers+0x0/0x29 @ 1
> [ 0.931651] initcall init_posix_timers+0x0/0x29 returned 0 after 2 usecs
> [ 0.933036] calling clockevents_init_sysfs+0x0/0xc7 @ 1
> [ 0.933179] ------------[ cut here ]------------
> [ 0.934353] initcall clockevents_init_sysfs+0x0/0xc7 returned 0 after 406 usecs
> [ 0.934812] kernel BUG at kernel/rcu/tree.c:3119!
And 110 runs had 46 cases where get_state_synchronize_rcu()
failed to notice a grace period's passage, and none for
get_state_synchronize_rcu_full().
So my advice is to either tolerate the occasional obliviousness of
get_state_synchronize_rcu() or switch to get_state_synchronize_rcu_full().
Thanx, Paul
