Hit WARN_ON() in rcutorture.c:1055

Hit WARN_ON() in rcutorture.c:1055

[Qais Yousef]

Hi

I hit the following warning while running rcutorture tests. It only happens
when I try to hibernate the system (arm64 Juno-r2).

Let me know if you need additional info.


# echo suspend > /sys/power/disk
# [  299.688526] rcu_torture_fwd_prog_nr: Duration 2913 cver 183 gps 285
e[  300.176051] rcu_torture_fwd_prog_cr Duration 39 barrier: 29 pending 9295 n_launders: 21213 n_launders_sa: 8224 n_max_gps: 100 n_max_cbs: 12823 cver 4 gps 10
[  300.190434] rcu_torture_fwd_cb_hist: Callback-invocation histogram (duration 72 jiffies): 1s/10: 11381:6 2s/10: 21139:7 3s/10: 1516:1
# echo disk > /sys/power/state
[  304.592943] PM: hibernation: hibernation entry
[  304.612969] Filesystems sync: 0.003 seconds
[  304.617616] Freezing user space processes ... (elapsed 0.004 seconds) done.
[  304.629712] OOM killer disabled.
[  304.642462] PM: hibernation: Preallocating image memory
[  305.988263] PM: hibernation: Allocated 96990 pages for snapshot
[  305.994311] PM: hibernation: Allocated 387960 kbytes in 1.33 seconds (291.69 MB/s)
[  306.002022] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  306.013873] printk: Suspending console(s) (use no_console_suspend to debug)
[  306.079141] Disabling non-boot CPUs ...
[  306.082829] CPU1: shutdown
[  306.082947] psci: CPU1 killed (polled 0 ms)
[  306.090930] CPU2: shutdown
[  306.092095] psci: CPU2 killed (polled 0 ms)
[  306.101501] CPU3: shutdown
[  306.101551] psci: CPU3 killed (polled 0 ms)
[  306.112128] CPU4: shutdown
[  306.112177] psci: CPU4 killed (polled 0 ms)
[  306.130425] CPU5: shutdown
[  306.130477] psci: CPU5 killed (polled 0 ms)
[  306.135659] PM: hibernation: Creating image:
[  306.135659] PM: hibernation: Need to copy 95345 pages
[  306.135659] PM: hibernation: Image created (95345 pages copied)
[  306.138145] Enabling non-boot CPUs ...
[  306.152537] Detected PIPT I-cache on CPU1
[  306.152605] CPU1: Booted secondary processor 0x0000000000 [0x410fd080]
[  306.156520] CPU1 is up
[  306.170179] Detected PIPT I-cache on CPU2
[  306.170217] CPU2: Booted secondary processor 0x0000000001 [0x410fd080]
[  306.171592] CPU2 is up
[  306.185303] Detected VIPT I-cache on CPU3
[  306.185454] CPU3: Booted secondary processor 0x0000000101 [0x410fd033]
[  306.191492] CPU3 is up
[  306.205183] Detected VIPT I-cache on CPU4
[  306.205314] CPU4: Booted secondary processor 0x0000000102 [0x410fd033]
[  306.212156] CPU4 is up
[  306.226312] Detected VIPT I-cache on CPU5
[  306.226440] CPU5: Booted secondary processor 0x0000000103 [0x410fd033]
[  306.235222] CPU5 is up
[  306.392553] usb usb2: runtime PM trying to activate child device usb2 but parent (7ffb0000.ohci) is not active
[  306.552039] hibernate: Hibernating on CPU 0 [mpidr:0x100]
[  306.643894] PM: Using 3 thread(s) for compression
[  306.648700] PM: Compressing and saving image data (95532 pages)...
[  306.655007] PM: Image saving progress:   0%
[  308.347979] ata2: SATA link down (SStatus 0 SControl 0)
[  308.353489] ata1: SATA link down (SStatus 0 SControl 0)
[  311.608370] ------------[ cut here ]------------
[  311.613127] WARNING: CPU: 3 PID: 261 at kernel/rcu/rcutorture.c:1055 rcu_torture_writer+0x664/0xa90
[  311.622360] Modules linked in:
[  311.625495] CPU: 3 PID: 261 Comm: rcu_torture_wri Not tainted 5.6.0-rc6 #535
[  311.632690] Hardware name: ARM Juno development board (r2) (DT)
[  311.638737] pstate: 00000005 (nzcv daif -PAN -UAO)
[  311.643634] pc : rcu_torture_writer+0x664/0xa90
[  311.648266] lr : rcu_torture_writer+0x65c/0xa90
[  311.652896] sp : ffff800018a1bde0
[  311.656287] x29: ffff800018a1bde0 x28: ffff800014048140
[  311.661717] x27: 000000000000c134 x26: ffff800014046f08
[  311.667149] x25: ffff8000120ff000 x24: 0000000000000001
[  311.672581] x23: ffff800014046f08 x22: ffff800014045000
[  311.678012] x21: ffff800013279000 x20: ffff800014048938
[  311.683444] x19: ffff800014046000 x18: 00000000fffffffd
[  311.688875] x17: 000000001824429d x16: ffff800014554170
[  311.694306] x15: 00000000fffffffe x14: 003d090000000000
[  311.699737] x13: 00003d0900000000 x12: 0000000000000003
[  311.705169] x11: 0000000000000c02 x10: 0000000000000000
[  311.710599] x9 : ffff8000137ed0a0 x8 : ffff0009757c8850
[  311.716030] x7 : 0000000000000000 x6 : ffff800018a1bcc0
[  311.721461] x5 : 0000000000000001 x4 : 0000000000000000
[  311.726891] x3 : 0000000000000080 x2 : 0000000002611501
[  311.732322] x1 : 0000000000000000 x0 : 0000000000000001
[  311.737754] Call trace:
[  311.740263]  rcu_torture_writer+0x664/0xa90
[  311.744544]  kthread+0x13c/0x140
[  311.747852]  ret_from_fork+0x10/0x18
[  311.751510] irq event stamp: 228320
[  311.755086] hardirqs last  enabled at (228319): [<ffff800010113dc0>] __local_bh_enable_ip+0x98/0x148
[  311.764414] hardirqs last disabled at (228320): [<ffff8000100a9300>] do_debug_exception+0x1a8/0x258
[  311.773652] softirqs last  enabled at (228318): [<ffff8000101b95fc>] rcu_torture_free+0x84/0x98
[  311.782537] softirqs last disabled at (228316): [<ffff8000101b95d8>] rcu_torture_free+0x60/0x98
[  311.791417] ---[ end trace dab722c9424166a2 ]---
[  311.998802] PM: Image saving progress:  10%
[  312.211076] PM: Image saving progress:  20%
[  312.311430] PM: Image saving progress:  30%
[  312.949974] psmouse serio0: Failed to enable mouse on 1c060000.kmi
[  313.351906] rcu-torture: rtc: 00000000e3ff6cce ver: 6966 tfle: 0 rta: 6967 rtaf: 0 rtf: 6957 rtmbe: 0 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 123307 onoff: 0/0:0/0 -1,0:-1,0 0:0 (HZ=250) barrier: 0/
0:0
[  313.370772] rcu-torture: Reader Pipe:  75577741 19694 0 0 0 0 0 0 0 0 0
[  313.377628] rcu-torture: Reader Batch:  75556519 40915 0 0 0 0 0 0 0 0 0
[  313.384570] rcu-torture: Free-Block Circulation:  6966 6965 6964 6963 6962 6961 6960 6959 6958 6957 0
[  315.017220] PM: Image saving progress:  40%
[  319.595899] psmouse serio1: Failed to enable mouse on 1c070000.kmi
[  321.033476] PM: Image saving progress:  50%
[  325.241344] PM: Image saving progress:  60%
[  325.692738] PM: Image saving progress:  70%
[  329.862793] PM: Image saving progress:  80%
[  333.941109] PM: Image saving progress:  90%
[  334.429067] PM: Image saving progress: 100%
[  334.442732] PM: Image saving done
[  334.446290] PM: hibernation: Wrote 382128 kbytes in 27.78 seconds (13.75 MB/s)
[  334.458377] PM: S|
[  334.747355] printk: Suspending console(s) (use no_console_suspend to debug)


Thanks

--
Qais Yousef

Re: Hit WARN_ON() in rcutorture.c:1055

[Paul E. McKenney]

On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> Hi
> 
> I hit the following warning while running rcutorture tests. It only happens
> when I try to hibernate the system (arm64 Juno-r2).

Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)

> Let me know if you need additional info.

1.	Do you need this to work?  If so, please tell me your use case.

2.	What is line 1055 of your rcutorture.c?  Here is my guess:

		if (stutter_wait("rcu_torture_writer") &&
		    !READ_ONCE(rcu_fwd_cb_nodelay) &&
		    !cur_ops->slow_gps &&
		    !torture_must_stop() &&
		    rcu_inkernel_boot_has_ended())
			for (i = 0; i < ARRAY_SIZE(rcu_tortures); i++)
				if (list_empty(&rcu_tortures[i].rtort_free) &&
				    rcu_access_pointer(rcu_torture_current) !=
				    &rcu_tortures[i]) {
					rcu_ftrace_dump(DUMP_ALL);
					WARN(1, "%s: rtort_pipe_count: %d\n", __func__, rcu_tortures[i].rtort_pipe_count);

	If my guess is correct, it is complaining because of the lack of
	forward progress during the time the system was suspended.  ;-)

	Or tell me exactly what kernel commit you are using, and I can
	look it up.

							Thanx, Paul

> # echo suspend > /sys/power/disk
> # [  299.688526] rcu_torture_fwd_prog_nr: Duration 2913 cver 183 gps 285
> e[  300.176051] rcu_torture_fwd_prog_cr Duration 39 barrier: 29 pending 9295 n_launders: 21213 n_launders_sa: 8224 n_max_gps: 100 n_max_cbs: 12823 cver 4 gps 10
> [  300.190434] rcu_torture_fwd_cb_hist: Callback-invocation histogram (duration 72 jiffies): 1s/10: 11381:6 2s/10: 21139:7 3s/10: 1516:1
> # echo disk > /sys/power/state
> [  304.592943] PM: hibernation: hibernation entry
> [  304.612969] Filesystems sync: 0.003 seconds
> [  304.617616] Freezing user space processes ... (elapsed 0.004 seconds) done.
> [  304.629712] OOM killer disabled.
> [  304.642462] PM: hibernation: Preallocating image memory
> [  305.988263] PM: hibernation: Allocated 96990 pages for snapshot
> [  305.994311] PM: hibernation: Allocated 387960 kbytes in 1.33 seconds (291.69 MB/s)
> [  306.002022] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
> [  306.013873] printk: Suspending console(s) (use no_console_suspend to debug)
> [  306.079141] Disabling non-boot CPUs ...
> [  306.082829] CPU1: shutdown
> [  306.082947] psci: CPU1 killed (polled 0 ms)
> [  306.090930] CPU2: shutdown
> [  306.092095] psci: CPU2 killed (polled 0 ms)
> [  306.101501] CPU3: shutdown
> [  306.101551] psci: CPU3 killed (polled 0 ms)
> [  306.112128] CPU4: shutdown
> [  306.112177] psci: CPU4 killed (polled 0 ms)
> [  306.130425] CPU5: shutdown
> [  306.130477] psci: CPU5 killed (polled 0 ms)
> [  306.135659] PM: hibernation: Creating image:
> [  306.135659] PM: hibernation: Need to copy 95345 pages
> [  306.135659] PM: hibernation: Image created (95345 pages copied)
> [  306.138145] Enabling non-boot CPUs ...
> [  306.152537] Detected PIPT I-cache on CPU1
> [  306.152605] CPU1: Booted secondary processor 0x0000000000 [0x410fd080]
> [  306.156520] CPU1 is up
> [  306.170179] Detected PIPT I-cache on CPU2
> [  306.170217] CPU2: Booted secondary processor 0x0000000001 [0x410fd080]
> [  306.171592] CPU2 is up
> [  306.185303] Detected VIPT I-cache on CPU3
> [  306.185454] CPU3: Booted secondary processor 0x0000000101 [0x410fd033]
> [  306.191492] CPU3 is up
> [  306.205183] Detected VIPT I-cache on CPU4
> [  306.205314] CPU4: Booted secondary processor 0x0000000102 [0x410fd033]
> [  306.212156] CPU4 is up
> [  306.226312] Detected VIPT I-cache on CPU5
> [  306.226440] CPU5: Booted secondary processor 0x0000000103 [0x410fd033]
> [  306.235222] CPU5 is up
> [  306.392553] usb usb2: runtime PM trying to activate child device usb2 but parent (7ffb0000.ohci) is not active
> [  306.552039] hibernate: Hibernating on CPU 0 [mpidr:0x100]
> [  306.643894] PM: Using 3 thread(s) for compression
> [  306.648700] PM: Compressing and saving image data (95532 pages)...
> [  306.655007] PM: Image saving progress:   0%
> [  308.347979] ata2: SATA link down (SStatus 0 SControl 0)
> [  308.353489] ata1: SATA link down (SStatus 0 SControl 0)
> [  311.608370] ------------[ cut here ]------------
> [  311.613127] WARNING: CPU: 3 PID: 261 at kernel/rcu/rcutorture.c:1055 rcu_torture_writer+0x664/0xa90
> [  311.622360] Modules linked in:
> [  311.625495] CPU: 3 PID: 261 Comm: rcu_torture_wri Not tainted 5.6.0-rc6 #535
> [  311.632690] Hardware name: ARM Juno development board (r2) (DT)
> [  311.638737] pstate: 00000005 (nzcv daif -PAN -UAO)
> [  311.643634] pc : rcu_torture_writer+0x664/0xa90
> [  311.648266] lr : rcu_torture_writer+0x65c/0xa90
> [  311.652896] sp : ffff800018a1bde0
> [  311.656287] x29: ffff800018a1bde0 x28: ffff800014048140
> [  311.661717] x27: 000000000000c134 x26: ffff800014046f08
> [  311.667149] x25: ffff8000120ff000 x24: 0000000000000001
> [  311.672581] x23: ffff800014046f08 x22: ffff800014045000
> [  311.678012] x21: ffff800013279000 x20: ffff800014048938
> [  311.683444] x19: ffff800014046000 x18: 00000000fffffffd
> [  311.688875] x17: 000000001824429d x16: ffff800014554170
> [  311.694306] x15: 00000000fffffffe x14: 003d090000000000
> [  311.699737] x13: 00003d0900000000 x12: 0000000000000003
> [  311.705169] x11: 0000000000000c02 x10: 0000000000000000
> [  311.710599] x9 : ffff8000137ed0a0 x8 : ffff0009757c8850
> [  311.716030] x7 : 0000000000000000 x6 : ffff800018a1bcc0
> [  311.721461] x5 : 0000000000000001 x4 : 0000000000000000
> [  311.726891] x3 : 0000000000000080 x2 : 0000000002611501
> [  311.732322] x1 : 0000000000000000 x0 : 0000000000000001
> [  311.737754] Call trace:
> [  311.740263]  rcu_torture_writer+0x664/0xa90
> [  311.744544]  kthread+0x13c/0x140
> [  311.747852]  ret_from_fork+0x10/0x18
> [  311.751510] irq event stamp: 228320
> [  311.755086] hardirqs last  enabled at (228319): [<ffff800010113dc0>] __local_bh_enable_ip+0x98/0x148
> [  311.764414] hardirqs last disabled at (228320): [<ffff8000100a9300>] do_debug_exception+0x1a8/0x258
> [  311.773652] softirqs last  enabled at (228318): [<ffff8000101b95fc>] rcu_torture_free+0x84/0x98
> [  311.782537] softirqs last disabled at (228316): [<ffff8000101b95d8>] rcu_torture_free+0x60/0x98
> [  311.791417] ---[ end trace dab722c9424166a2 ]---
> [  311.998802] PM: Image saving progress:  10%
> [  312.211076] PM: Image saving progress:  20%
> [  312.311430] PM: Image saving progress:  30%
> [  312.949974] psmouse serio0: Failed to enable mouse on 1c060000.kmi
> [  313.351906] rcu-torture: rtc: 00000000e3ff6cce ver: 6966 tfle: 0 rta: 6967 rtaf: 0 rtf: 6957 rtmbe: 0 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 123307 onoff: 0/0:0/0 -1,0:-1,0 0:0 (HZ=250) barrier: 0/
> 0:0
> [  313.370772] rcu-torture: Reader Pipe:  75577741 19694 0 0 0 0 0 0 0 0 0
> [  313.377628] rcu-torture: Reader Batch:  75556519 40915 0 0 0 0 0 0 0 0 0
> [  313.384570] rcu-torture: Free-Block Circulation:  6966 6965 6964 6963 6962 6961 6960 6959 6958 6957 0
> [  315.017220] PM: Image saving progress:  40%
> [  319.595899] psmouse serio1: Failed to enable mouse on 1c070000.kmi
> [  321.033476] PM: Image saving progress:  50%
> [  325.241344] PM: Image saving progress:  60%
> [  325.692738] PM: Image saving progress:  70%
> [  329.862793] PM: Image saving progress:  80%
> [  333.941109] PM: Image saving progress:  90%
> [  334.429067] PM: Image saving progress: 100%
> [  334.442732] PM: Image saving done
> [  334.446290] PM: hibernation: Wrote 382128 kbytes in 27.78 seconds (13.75 MB/s)
> [  334.458377] PM: S|
> [  334.747355] printk: Suspending console(s) (use no_console_suspend to debug)
> 
> 
> Thanks
> 
> --
> Qais Yousef

Re: Hit WARN_ON() in rcutorture.c:1055

[Qais Yousef]

On 03/23/20 08:57, Paul E. McKenney wrote:
> On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> > Hi
> > 
> > I hit the following warning while running rcutorture tests. It only happens
> > when I try to hibernate the system (arm64 Juno-r2).
> 
> Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)

Hehe was just a side effect of testing the cpu hotplug stuff :-)

> 
> > Let me know if you need additional info.
> 
> 1.	Do you need this to work?  If so, please tell me your use case.

Nope. It just happened while trying to stress the cpu hotplug series I just
posted.

> 
> 2.	What is line 1055 of your rcutorture.c?  Here is my guess:

It's 5.6-rc6, sorry should have mentioned in the report.

		/* Cycle through nesting levels of rcu_expedite_gp() calls. */
		if (can_expedite &&
		    !(torture_random(&rand) & 0xff & (!!expediting - 1))) {
			WARN_ON_ONCE(expediting == 0 && rcu_gp_is_expedited());
			if (expediting >= 0)
				rcu_expedite_gp();
			else
				rcu_unexpedite_gp();
			if (++expediting > 3)
				expediting = -expediting;
		} else if (!can_expedite) { /* Disabled during boot, recheck. */

If it's something you don't care about, then I don't care about too. I just
thought I'd report it in case it uncovered something worthwhile.

Thanks!

--
Qais Yousef

Re: Hit WARN_ON() in rcutorture.c:1055

[Paul E. McKenney]

On Mon, Mar 23, 2020 at 05:06:10PM +0000, Qais Yousef wrote:
> On 03/23/20 08:57, Paul E. McKenney wrote:
> > On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> > > Hi
> > > 
> > > I hit the following warning while running rcutorture tests. It only happens
> > > when I try to hibernate the system (arm64 Juno-r2).
> > 
> > Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)
> 
> Hehe was just a side effect of testing the cpu hotplug stuff :-)
> 
> > 
> > > Let me know if you need additional info.
> > 
> > 1.	Do you need this to work?  If so, please tell me your use case.
> 
> Nope. It just happened while trying to stress the cpu hotplug series I just
> posted.
> 
> > 2.	What is line 1055 of your rcutorture.c?  Here is my guess:
> 
> It's 5.6-rc6, sorry should have mentioned in the report.
> 
> 		/* Cycle through nesting levels of rcu_expedite_gp() calls. */
> 		if (can_expedite &&
> 		    !(torture_random(&rand) & 0xff & (!!expediting - 1))) {
> 			WARN_ON_ONCE(expediting == 0 && rcu_gp_is_expedited());
> 			if (expediting >= 0)
> 				rcu_expedite_gp();
> 			else
> 				rcu_unexpedite_gp();
> 			if (++expediting > 3)
> 				expediting = -expediting;
> 		} else if (!can_expedite) { /* Disabled during boot, recheck. */
> 
> If it's something you don't care about, then I don't care about too. I just
> thought I'd report it in case it uncovered something worthwhile.

Well, my guess was wrong.  ;-)

This is instead rcutorture being surprised by the fact that RCU grace
periods are expedited during the hibernate process.  I could fix this
particular situation, but I bet that there are a number of others,
including my guess above.

One approach would be to halt rcutorture testing just before hibernating
and restart it just after resuming.

Thoughts?

							Thanx, Paul

Re: Hit WARN_ON() in rcutorture.c:1055

[Qais Yousef]

On 03/23/20 10:17, Paul E. McKenney wrote:
> On Mon, Mar 23, 2020 at 05:06:10PM +0000, Qais Yousef wrote:
> > On 03/23/20 08:57, Paul E. McKenney wrote:
> > > On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> > > > Hi
> > > > 
> > > > I hit the following warning while running rcutorture tests. It only happens
> > > > when I try to hibernate the system (arm64 Juno-r2).
> > > 
> > > Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)
> > 
> > Hehe was just a side effect of testing the cpu hotplug stuff :-)
> > 
> > > 
> > > > Let me know if you need additional info.
> > > 
> > > 1.	Do you need this to work?  If so, please tell me your use case.
> > 
> > Nope. It just happened while trying to stress the cpu hotplug series I just
> > posted.
> > 
> > > 2.	What is line 1055 of your rcutorture.c?  Here is my guess:
> > 
> > It's 5.6-rc6, sorry should have mentioned in the report.
> > 
> > 		/* Cycle through nesting levels of rcu_expedite_gp() calls. */
> > 		if (can_expedite &&
> > 		    !(torture_random(&rand) & 0xff & (!!expediting - 1))) {
> > 			WARN_ON_ONCE(expediting == 0 && rcu_gp_is_expedited());
> > 			if (expediting >= 0)
> > 				rcu_expedite_gp();
> > 			else
> > 				rcu_unexpedite_gp();
> > 			if (++expediting > 3)
> > 				expediting = -expediting;
> > 		} else if (!can_expedite) { /* Disabled during boot, recheck. */
> > 
> > If it's something you don't care about, then I don't care about too. I just
> > thought I'd report it in case it uncovered something worthwhile.
> 
> Well, my guess was wrong.  ;-)
> 
> This is instead rcutorture being surprised by the fact that RCU grace
> periods are expedited during the hibernate process.  I could fix this
> particular situation, but I bet that there are a number of others,
> including my guess above.
> 
> One approach would be to halt rcutorture testing just before hibernating
> and restart it just after resuming.
> 
> Thoughts?

{register, unregister}_pm_notifier() don't seem to be too hard to use.

But if it's not that simple, then it's not worthwhile I'd say. The report
lives in LKML as a documentation of this missing support :-P

Thanks

--
Qais Yousef

Re: Hit WARN_ON() in rcutorture.c:1055

[Paul E. McKenney]

On Mon, Mar 23, 2020 at 05:41:48PM +0000, Qais Yousef wrote:
> On 03/23/20 10:17, Paul E. McKenney wrote:
> > On Mon, Mar 23, 2020 at 05:06:10PM +0000, Qais Yousef wrote:
> > > On 03/23/20 08:57, Paul E. McKenney wrote:
> > > > On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> > > > > Hi
> > > > > 
> > > > > I hit the following warning while running rcutorture tests. It only happens
> > > > > when I try to hibernate the system (arm64 Juno-r2).
> > > > 
> > > > Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)
> > > 
> > > Hehe was just a side effect of testing the cpu hotplug stuff :-)
> > > 
> > > > 
> > > > > Let me know if you need additional info.
> > > > 
> > > > 1.	Do you need this to work?  If so, please tell me your use case.
> > > 
> > > Nope. It just happened while trying to stress the cpu hotplug series I just
> > > posted.
> > > 
> > > > 2.	What is line 1055 of your rcutorture.c?  Here is my guess:
> > > 
> > > It's 5.6-rc6, sorry should have mentioned in the report.
> > > 
> > > 		/* Cycle through nesting levels of rcu_expedite_gp() calls. */
> > > 		if (can_expedite &&
> > > 		    !(torture_random(&rand) & 0xff & (!!expediting - 1))) {
> > > 			WARN_ON_ONCE(expediting == 0 && rcu_gp_is_expedited());
> > > 			if (expediting >= 0)
> > > 				rcu_expedite_gp();
> > > 			else
> > > 				rcu_unexpedite_gp();
> > > 			if (++expediting > 3)
> > > 				expediting = -expediting;
> > > 		} else if (!can_expedite) { /* Disabled during boot, recheck. */
> > > 
> > > If it's something you don't care about, then I don't care about too. I just
> > > thought I'd report it in case it uncovered something worthwhile.
> > 
> > Well, my guess was wrong.  ;-)
> > 
> > This is instead rcutorture being surprised by the fact that RCU grace
> > periods are expedited during the hibernate process.  I could fix this
> > particular situation, but I bet that there are a number of others,
> > including my guess above.
> > 
> > One approach would be to halt rcutorture testing just before hibernating
> > and restart it just after resuming.
> > 
> > Thoughts?
> 
> {register, unregister}_pm_notifier() don't seem to be too hard to use.

That part is easy.  It would also be necessary to find all the affected
warnings in rcutorture and suppress them, not only during this time,
but also for some period of time afterwards.  Maybe this is the only one,
but that would be surprising.  ;-)

> But if it's not that simple, then it's not worthwhile I'd say. The report
> lives in LKML as a documentation of this missing support :-P

It might at some point be necessary for rcutorture to handle suspends
and hibernates in midstream, and yes, it could be done, but first I need
to see some reason why it provides significant help.

							Thanx, Paul

Re: Hit WARN_ON() in rcutorture.c:1055

[Qais Yousef]

On 03/23/20 11:10, Paul E. McKenney wrote:
> On Mon, Mar 23, 2020 at 05:41:48PM +0000, Qais Yousef wrote:
> > On 03/23/20 10:17, Paul E. McKenney wrote:
> > > On Mon, Mar 23, 2020 at 05:06:10PM +0000, Qais Yousef wrote:
> > > > On 03/23/20 08:57, Paul E. McKenney wrote:
> > > > > On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> > > > > > Hi
> > > > > > 
> > > > > > I hit the following warning while running rcutorture tests. It only happens
> > > > > > when I try to hibernate the system (arm64 Juno-r2).
> > > > > 
> > > > > Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)
> > > > 
> > > > Hehe was just a side effect of testing the cpu hotplug stuff :-)
> > > > 
> > > > > 
> > > > > > Let me know if you need additional info.
> > > > > 
> > > > > 1.	Do you need this to work?  If so, please tell me your use case.
> > > > 
> > > > Nope. It just happened while trying to stress the cpu hotplug series I just
> > > > posted.
> > > > 
> > > > > 2.	What is line 1055 of your rcutorture.c?  Here is my guess:
> > > > 
> > > > It's 5.6-rc6, sorry should have mentioned in the report.
> > > > 
> > > > 		/* Cycle through nesting levels of rcu_expedite_gp() calls. */
> > > > 		if (can_expedite &&
> > > > 		    !(torture_random(&rand) & 0xff & (!!expediting - 1))) {
> > > > 			WARN_ON_ONCE(expediting == 0 && rcu_gp_is_expedited());
> > > > 			if (expediting >= 0)
> > > > 				rcu_expedite_gp();
> > > > 			else
> > > > 				rcu_unexpedite_gp();
> > > > 			if (++expediting > 3)
> > > > 				expediting = -expediting;
> > > > 		} else if (!can_expedite) { /* Disabled during boot, recheck. */
> > > > 
> > > > If it's something you don't care about, then I don't care about too. I just
> > > > thought I'd report it in case it uncovered something worthwhile.
> > > 
> > > Well, my guess was wrong.  ;-)
> > > 
> > > This is instead rcutorture being surprised by the fact that RCU grace
> > > periods are expedited during the hibernate process.  I could fix this
> > > particular situation, but I bet that there are a number of others,
> > > including my guess above.
> > > 
> > > One approach would be to halt rcutorture testing just before hibernating
> > > and restart it just after resuming.
> > > 
> > > Thoughts?
> > 
> > {register, unregister}_pm_notifier() don't seem to be too hard to use.
> 
> That part is easy.  It would also be necessary to find all the affected
> warnings in rcutorture and suppress them, not only during this time,
> but also for some period of time afterwards.  Maybe this is the only one,
> but that would be surprising.  ;-)

Wouldn't be easier to just deinit/init()? ie: treat it like unload/load module.

But you'll lose some info then that maybe you'd like to keep across
suspend/resume cycles.

> 
> > But if it's not that simple, then it's not worthwhile I'd say. The report
> > lives in LKML as a documentation of this missing support :-P
> 
> It might at some point be necessary for rcutorture to handle suspends
> and hibernates in midstream, and yes, it could be done, but first I need
> to see some reason why it provides significant help.

Sounds reasonable to me. I agree my use case isn't sensible in general. It just
happened because I was testing an operation that affected both hibernation and
rcutorture test and I tend to compile my kernels with everything built-in.

Thanks

--
Qais Yousef

Re: Hit WARN_ON() in rcutorture.c:1055

[Paul E. McKenney]

On Mon, Mar 23, 2020 at 06:23:51PM +0000, Qais Yousef wrote:
> On 03/23/20 11:10, Paul E. McKenney wrote:
> > On Mon, Mar 23, 2020 at 05:41:48PM +0000, Qais Yousef wrote:
> > > On 03/23/20 10:17, Paul E. McKenney wrote:
> > > > On Mon, Mar 23, 2020 at 05:06:10PM +0000, Qais Yousef wrote:
> > > > > On 03/23/20 08:57, Paul E. McKenney wrote:
> > > > > > On Mon, Mar 23, 2020 at 03:43:09PM +0000, Qais Yousef wrote:
> > > > > > > Hi
> > > > > > > 
> > > > > > > I hit the following warning while running rcutorture tests. It only happens
> > > > > > > when I try to hibernate the system (arm64 Juno-r2).
> > > > > > 
> > > > > > Hibernating the system during rcutorture tests.  Now that is gutsy!  ;-)
> > > > > 
> > > > > Hehe was just a side effect of testing the cpu hotplug stuff :-)
> > > > > 
> > > > > > 
> > > > > > > Let me know if you need additional info.
> > > > > > 
> > > > > > 1.	Do you need this to work?  If so, please tell me your use case.
> > > > > 
> > > > > Nope. It just happened while trying to stress the cpu hotplug series I just
> > > > > posted.
> > > > > 
> > > > > > 2.	What is line 1055 of your rcutorture.c?  Here is my guess:
> > > > > 
> > > > > It's 5.6-rc6, sorry should have mentioned in the report.
> > > > > 
> > > > > 		/* Cycle through nesting levels of rcu_expedite_gp() calls. */
> > > > > 		if (can_expedite &&
> > > > > 		    !(torture_random(&rand) & 0xff & (!!expediting - 1))) {
> > > > > 			WARN_ON_ONCE(expediting == 0 && rcu_gp_is_expedited());
> > > > > 			if (expediting >= 0)
> > > > > 				rcu_expedite_gp();
> > > > > 			else
> > > > > 				rcu_unexpedite_gp();
> > > > > 			if (++expediting > 3)
> > > > > 				expediting = -expediting;
> > > > > 		} else if (!can_expedite) { /* Disabled during boot, recheck. */
> > > > > 
> > > > > If it's something you don't care about, then I don't care about too. I just
> > > > > thought I'd report it in case it uncovered something worthwhile.
> > > > 
> > > > Well, my guess was wrong.  ;-)
> > > > 
> > > > This is instead rcutorture being surprised by the fact that RCU grace
> > > > periods are expedited during the hibernate process.  I could fix this
> > > > particular situation, but I bet that there are a number of others,
> > > > including my guess above.
> > > > 
> > > > One approach would be to halt rcutorture testing just before hibernating
> > > > and restart it just after resuming.
> > > > 
> > > > Thoughts?
> > > 
> > > {register, unregister}_pm_notifier() don't seem to be too hard to use.
> > 
> > That part is easy.  It would also be necessary to find all the affected
> > warnings in rcutorture and suppress them, not only during this time,
> > but also for some period of time afterwards.  Maybe this is the only one,
> > but that would be surprising.  ;-)
> 
> Wouldn't be easier to just deinit/init()? ie: treat it like unload/load module.
> 
> But you'll lose some info then that maybe you'd like to keep across
> suspend/resume cycles.

Hmmm...  Are you running rcutorture as a loadable module or built into
your kernel?  In the latter case, it starts up automatically shortly
after boot.

> > > But if it's not that simple, then it's not worthwhile I'd say. The report
> > > lives in LKML as a documentation of this missing support :-P
> > 
> > It might at some point be necessary for rcutorture to handle suspends
> > and hibernates in midstream, and yes, it could be done, but first I need
> > to see some reason why it provides significant help.
> 
> Sounds reasonable to me. I agree my use case isn't sensible in general. It just
> happened because I was testing an operation that affected both hibernation and
> rcutorture test and I tend to compile my kernels with everything built-in.

Don't get me wrong, I am very happy to see people making use of
rcutorture!  ;-)

								Thanx, Paul

Re: Hit WARN_ON() in rcutorture.c:1055

[Qais Yousef]

[-- Attachment #1: Type: text/plain, Size: 3296 bytes --]

On 03/23/20 11:44, Paul E. McKenney wrote:
> > > > {register, unregister}_pm_notifier() don't seem to be too hard to use.
> > > 
> > > That part is easy.  It would also be necessary to find all the affected
> > > warnings in rcutorture and suppress them, not only during this time,
> > > but also for some period of time afterwards.  Maybe this is the only one,
> > > but that would be surprising.  ;-)
> > 
> > Wouldn't be easier to just deinit/init()? ie: treat it like unload/load module.
> > 
> > But you'll lose some info then that maybe you'd like to keep across
> > suspend/resume cycles.
> 
> Hmmm...  Are you running rcutorture as a loadable module or built into
> your kernel?  In the latter case, it starts up automatically shortly
> after boot.

Built-in. Sorry maybe I wasn't clear. I meant something like the attached.
Which still generates this warning, so yeah I get your point about suppressing
some warnings in the right places now.

[   48.898066] rcu-torture: Stopping rcu_torture_fwd_prog task
[   48.908998] rcu-torture: Stopping rcu_torture_reader
[   48.917052] rcu-torture: Stopping rcu_torture_fakewriter
[   48.926987] ------------[ cut here ]------------
[   48.927025] WARNING: CPU: 4 PID: 261 at kernel/rcu/rcutorture.c:1085 rcu_torture_writer+0x49c/0xa90
[   48.927038] rcu-torture: Stopping rcu_torture_fakewriter
[   48.927041] Modules linked in:
[   48.927070] CPU: 4 PID: 261 Comm: rcu_torture_wri Not tainted 5.6.0-rc6-00002-g533440e608d2-dirty #540
[   48.927085] Hardware name: ARM Juno development board (r2) (DT)
[   48.927103] pstate: 00000005 (nzcv daif -PAN -UAO)
[   48.927124] pc : rcu_torture_writer+0x49c/0xa90
[   48.927144] lr : rcu_torture_writer+0x494/0xa90
[   48.927157] sp : ffff800018bfbde0
[   48.927172] x29: ffff800018bfbde0 x28: ffff80001426da58
[   48.927198] x27: ffff80001426cf08 x26: ffff80001426cf08
[   48.927224] x25: ffff8000121b5000 x24: 0000000000000001
[   48.927250] x23: ffff80001426d650 x22: ffff80001426b000
[   48.927275] x21: ffff800013439000 x20: 0000000000000001
[   48.927301] x19: ffff80001426c000 x18: 0000000000000000
[   48.927326] x17: 0000000000000000 x16: 0000000000000000
[   48.927351] x15: 0000000000000000 x14: 0000000000000000
[   48.927376] x13: 0000000000000000 x12: 0000000000000000
[   48.927401] x11: 00000000000001fa x10: 0000000000000000
[   48.927426] x9 : ffff800013a130a0 x8 : ffff0009757f0850
[   48.927450] x7 : 0000000000000000 x6 : ffff800018bfbcc0
[   48.927475] x5 : 0000000000000001 x4 : 0000000000000000
[   48.927499] x3 : 0000000000000080 x2 : 0000000000000000
[   48.927524] x1 : 0000000000000000 x0 : 0000000000000001
[   48.927548] Call trace:
[   48.927569]  rcu_torture_writer+0x49c/0xa90
[   48.927590]  kthread+0x13c/0x140
[   48.927611]  ret_from_fork+0x10/0x18
[   48.927627] irq event stamp: 34170
[   48.927654] hardirqs last  enabled at (34169): [<ffff800010114300>] __local_bh_enable_ip+0x98/0x148
[   48.927680] hardirqs last disabled at (34170): [<ffff8000100a95d0>] do_debug_exception+0x1a8/0x258
[   48.927702] softirqs last  enabled at (34168): [<ffff8000101b949c>] rcu_torture_free+0x84/0x98
[   48.927725] softirqs last disabled at (34166): [<ffff8000101b9478>] rcu_torture_free+0x60/0x98
[   48.927740] ---[ end trace 57f88d092825f447 ]---

Thanks

--
Qais Yousef

[-- Attachment #2: rcu_pm.patch --]
[-- Type: text/x-diff, Size: 1996 bytes --]

diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 1aeecc165b21..defad882b236 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -45,6 +45,7 @@
 #include <linux/sched/sysctl.h>
 #include <linux/oom.h>
 #include <linux/tick.h>
+#include <linux/suspend.h>
 
 #include "rcu.h"
 
@@ -1628,7 +1629,7 @@ static int rcu_torture_stall(void *args)
 }
 
 /* Spawn CPU-stall kthread, if stall_cpu specified. */
-static int __init rcu_torture_stall_init(void)
+static int rcu_torture_stall_init(void)
 {
 	if (stall_cpu <= 0)
 		return 0;
@@ -2008,7 +2009,7 @@ static int rcu_torture_fwd_prog(void *args)
 }
 
 /* If forward-progress checking is requested and feasible, spawn the thread. */
-static int __init rcu_torture_fwd_prog_init(void)
+static int rcu_torture_fwd_prog_init(void)
 {
 	struct rcu_fwd *rfp;
 
@@ -2359,7 +2360,7 @@ static void rcutorture_sync(void)
 		cur_ops->sync();
 }
 
-static int __init
+static int
 rcu_torture_init(void)
 {
 	long i;
@@ -2549,5 +2550,47 @@ rcu_torture_init(void)
 	return firsterr;
 }
 
-module_init(rcu_torture_init);
-module_exit(rcu_torture_cleanup);
+static int rcu_torture_notify(struct notifier_block *nb,
+			      unsigned long mode, void *_unused)
+{
+	switch (mode) {
+	case PM_HIBERNATION_PREPARE:
+	case PM_SUSPEND_PREPARE:
+		pr_info("Shutdodwn rcu torture..");
+		rcu_torture_cleanup();
+		break;
+
+	case PM_POST_RESTORE:
+		pr_info("Restart rcu torture..");
+		rcu_torture_init();
+		break;
+	}
+
+	return 0;
+}
+
+static struct notifier_block rcu_nb = {
+	.notifier_call = rcu_torture_notify
+};
+
+static int nb_failed;
+
+int rcu_torture_module_init(void)
+{
+	nb_failed = register_pm_notifier(&rcu_nb);
+	if (nb_failed)
+		pr_warn("Failed to register PM notifier");
+
+	return rcu_torture_init();
+}
+
+void rcu_torture_module_exit(void)
+{
+	if (!nb_failed)
+		unregister_pm_notifier(&rcu_nb);
+
+	rcu_torture_cleanup();
+}
+
+module_init(rcu_torture_module_init);
+module_exit(rcu_torture_module_exit);

Re: Hit WARN_ON() in rcutorture.c:1055

[Paul E. McKenney]

On Tue, Mar 24, 2020 at 11:39:19AM +0000, Qais Yousef wrote:
> On 03/23/20 11:44, Paul E. McKenney wrote:
> > > > > {register, unregister}_pm_notifier() don't seem to be too hard to use.
> > > > 
> > > > That part is easy.  It would also be necessary to find all the affected
> > > > warnings in rcutorture and suppress them, not only during this time,
> > > > but also for some period of time afterwards.  Maybe this is the only one,
> > > > but that would be surprising.  ;-)
> > > 
> > > Wouldn't be easier to just deinit/init()? ie: treat it like unload/load module.
> > > 
> > > But you'll lose some info then that maybe you'd like to keep across
> > > suspend/resume cycles.
> > 
> > Hmmm...  Are you running rcutorture as a loadable module or built into
> > your kernel?  In the latter case, it starts up automatically shortly
> > after boot.
> 
> Built-in. Sorry maybe I wasn't clear. I meant something like the attached.
> Which still generates this warning, so yeah I get your point about suppressing
> some warnings in the right places now.

What my approach will be is to think through how to deal with this.
It might be that I can come up with a simple strategy, and if so, I will
make the changes.

But yes, I never had considered this in any of my rcutorture design or
implementation, so there is likely to be 15 years worth of bugs that
would need to be fixed.

Unless I can come up with something a bit more targeted.  Which might
happen.  It sometimes has in past encounters with this sort of thing.  ;-)

							Thanx, Paul

> [   48.898066] rcu-torture: Stopping rcu_torture_fwd_prog task
> [   48.908998] rcu-torture: Stopping rcu_torture_reader
> [   48.917052] rcu-torture: Stopping rcu_torture_fakewriter
> [   48.926987] ------------[ cut here ]------------
> [   48.927025] WARNING: CPU: 4 PID: 261 at kernel/rcu/rcutorture.c:1085 rcu_torture_writer+0x49c/0xa90
> [   48.927038] rcu-torture: Stopping rcu_torture_fakewriter
> [   48.927041] Modules linked in:
> [   48.927070] CPU: 4 PID: 261 Comm: rcu_torture_wri Not tainted 5.6.0-rc6-00002-g533440e608d2-dirty #540
> [   48.927085] Hardware name: ARM Juno development board (r2) (DT)
> [   48.927103] pstate: 00000005 (nzcv daif -PAN -UAO)
> [   48.927124] pc : rcu_torture_writer+0x49c/0xa90
> [   48.927144] lr : rcu_torture_writer+0x494/0xa90
> [   48.927157] sp : ffff800018bfbde0
> [   48.927172] x29: ffff800018bfbde0 x28: ffff80001426da58
> [   48.927198] x27: ffff80001426cf08 x26: ffff80001426cf08
> [   48.927224] x25: ffff8000121b5000 x24: 0000000000000001
> [   48.927250] x23: ffff80001426d650 x22: ffff80001426b000
> [   48.927275] x21: ffff800013439000 x20: 0000000000000001
> [   48.927301] x19: ffff80001426c000 x18: 0000000000000000
> [   48.927326] x17: 0000000000000000 x16: 0000000000000000
> [   48.927351] x15: 0000000000000000 x14: 0000000000000000
> [   48.927376] x13: 0000000000000000 x12: 0000000000000000
> [   48.927401] x11: 00000000000001fa x10: 0000000000000000
> [   48.927426] x9 : ffff800013a130a0 x8 : ffff0009757f0850
> [   48.927450] x7 : 0000000000000000 x6 : ffff800018bfbcc0
> [   48.927475] x5 : 0000000000000001 x4 : 0000000000000000
> [   48.927499] x3 : 0000000000000080 x2 : 0000000000000000
> [   48.927524] x1 : 0000000000000000 x0 : 0000000000000001
> [   48.927548] Call trace:
> [   48.927569]  rcu_torture_writer+0x49c/0xa90
> [   48.927590]  kthread+0x13c/0x140
> [   48.927611]  ret_from_fork+0x10/0x18
> [   48.927627] irq event stamp: 34170
> [   48.927654] hardirqs last  enabled at (34169): [<ffff800010114300>] __local_bh_enable_ip+0x98/0x148
> [   48.927680] hardirqs last disabled at (34170): [<ffff8000100a95d0>] do_debug_exception+0x1a8/0x258
> [   48.927702] softirqs last  enabled at (34168): [<ffff8000101b949c>] rcu_torture_free+0x84/0x98
> [   48.927725] softirqs last disabled at (34166): [<ffff8000101b9478>] rcu_torture_free+0x60/0x98
> [   48.927740] ---[ end trace 57f88d092825f447 ]---
> 
> Thanks
> 
> --
> Qais Yousef

> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index 1aeecc165b21..defad882b236 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -45,6 +45,7 @@
>  #include <linux/sched/sysctl.h>
>  #include <linux/oom.h>
>  #include <linux/tick.h>
> +#include <linux/suspend.h>
>  
>  #include "rcu.h"
>  
> @@ -1628,7 +1629,7 @@ static int rcu_torture_stall(void *args)
>  }
>  
>  /* Spawn CPU-stall kthread, if stall_cpu specified. */
> -static int __init rcu_torture_stall_init(void)
> +static int rcu_torture_stall_init(void)
>  {
>  	if (stall_cpu <= 0)
>  		return 0;
> @@ -2008,7 +2009,7 @@ static int rcu_torture_fwd_prog(void *args)
>  }
>  
>  /* If forward-progress checking is requested and feasible, spawn the thread. */
> -static int __init rcu_torture_fwd_prog_init(void)
> +static int rcu_torture_fwd_prog_init(void)
>  {
>  	struct rcu_fwd *rfp;
>  
> @@ -2359,7 +2360,7 @@ static void rcutorture_sync(void)
>  		cur_ops->sync();
>  }
>  
> -static int __init
> +static int
>  rcu_torture_init(void)
>  {
>  	long i;
> @@ -2549,5 +2550,47 @@ rcu_torture_init(void)
>  	return firsterr;
>  }
>  
> -module_init(rcu_torture_init);
> -module_exit(rcu_torture_cleanup);
> +static int rcu_torture_notify(struct notifier_block *nb,
> +			      unsigned long mode, void *_unused)
> +{
> +	switch (mode) {
> +	case PM_HIBERNATION_PREPARE:
> +	case PM_SUSPEND_PREPARE:
> +		pr_info("Shutdodwn rcu torture..");
> +		rcu_torture_cleanup();
> +		break;
> +
> +	case PM_POST_RESTORE:
> +		pr_info("Restart rcu torture..");
> +		rcu_torture_init();
> +		break;
> +	}
> +
> +	return 0;
> +}
> +
> +static struct notifier_block rcu_nb = {
> +	.notifier_call = rcu_torture_notify
> +};
> +
> +static int nb_failed;
> +
> +int rcu_torture_module_init(void)
> +{
> +	nb_failed = register_pm_notifier(&rcu_nb);
> +	if (nb_failed)
> +		pr_warn("Failed to register PM notifier");
> +
> +	return rcu_torture_init();
> +}
> +
> +void rcu_torture_module_exit(void)
> +{
> +	if (!nb_failed)
> +		unregister_pm_notifier(&rcu_nb);
> +
> +	rcu_torture_cleanup();
> +}
> +
> +module_init(rcu_torture_module_init);
> +module_exit(rcu_torture_module_exit);