* [PATCH rcu v2] 1/5] rcu: Split rcu_report_exp_cpu_mult() mask parameter and use for tracing
2025-01-30 18:53 ` [PATCH rcu 0/5] Miscellaneous fixes Paul E. McKenney
@ 2025-01-30 18:53 ` Paul E. McKenney
2025-01-30 18:53 ` [PATCH rcu v2] 2/5] rcu: Remove READ_ONCE() for rdp->gpwrap access in __note_gp_changes() Paul E. McKenney
` (4 subsequent siblings)
5 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-01-30 18:53 UTC (permalink / raw)
To: rcu
Cc: linux-kernel, kernel-team, rostedt, Paul E. McKenney,
Frederic Weisbecker
This commit renames the rcu_report_exp_cpu_mult() function from "mask"
to "mask_in" and introduced a "mask" local variable to better support
upcoming event-tracing additions.
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Frederic Weisbecker <frederic@kernel.org>
---
kernel/rcu/tree_exp.h | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/kernel/rcu/tree_exp.h b/kernel/rcu/tree_exp.h
index 77efed89c79e..8d4895c854c5 100644
--- a/kernel/rcu/tree_exp.h
+++ b/kernel/rcu/tree_exp.h
@@ -230,17 +230,19 @@ static void __maybe_unused rcu_report_exp_rnp(struct rcu_node *rnp, bool wake)
* specified leaf rcu_node structure, which is acquired by the caller.
*/
static void rcu_report_exp_cpu_mult(struct rcu_node *rnp, unsigned long flags,
- unsigned long mask, bool wake)
+ unsigned long mask_in, bool wake)
__releases(rnp->lock)
{
int cpu;
+ unsigned long mask;
struct rcu_data *rdp;
raw_lockdep_assert_held_rcu_node(rnp);
- if (!(rnp->expmask & mask)) {
+ if (!(rnp->expmask & mask_in)) {
raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
return;
}
+ mask = mask_in & rnp->expmask;
WRITE_ONCE(rnp->expmask, rnp->expmask & ~mask);
for_each_leaf_node_cpu_mask(rnp, cpu, mask) {
rdp = per_cpu_ptr(&rcu_data, cpu);
--
2.40.1
^ permalink raw reply related [flat|nested] 34+ messages in thread* [PATCH rcu v2] 2/5] rcu: Remove READ_ONCE() for rdp->gpwrap access in __note_gp_changes()
2025-01-30 18:53 ` [PATCH rcu 0/5] Miscellaneous fixes Paul E. McKenney
2025-01-30 18:53 ` [PATCH rcu v2] 1/5] rcu: Split rcu_report_exp_cpu_mult() mask parameter and use for tracing Paul E. McKenney
@ 2025-01-30 18:53 ` Paul E. McKenney
2025-01-30 18:53 ` [PATCH rcu v2] 3/5] rcu: Fix get_state_synchronize_rcu_full() GP-start detection Paul E. McKenney
` (3 subsequent siblings)
5 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-01-30 18:53 UTC (permalink / raw)
To: rcu; +Cc: linux-kernel, kernel-team, rostedt, Zilin Guan, Paul E . McKenney
From: Zilin Guan <zilinguan811@gmail.com>
There is one access to the per-CPU rdp->gpwrap field in the
__note_gp_changes() function that does not use READ_ONCE(), but all other
accesses do use READ_ONCE(). When using the 8*TREE03 and CONFIG_NR_CPUS=8
configuration, KCSAN found no data races at that point. This is because
all calls to __note_gp_changes() hold rnp->lock, which excludes writes
to the rdp->gpwrap fields for all CPUs associated with that same leaf
rcu_node structure.
This commit therefore removes READ_ONCE() from rdp->gpwrap accesses
within the __note_gp_changes() function.
Signed-off-by: Zilin Guan <zilinguan811@gmail.com>
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
---
kernel/rcu/tree.c | 6 +++---
1 file changed, 3 insertions(+), 3 deletions(-)
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index 229f427b8c82..e49bcb86b6d3 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -1275,7 +1275,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, struct rcu_data *rdp)
/* Handle the ends of any preceding grace periods first. */
if (rcu_seq_completed_gp(rdp->gp_seq, rnp->gp_seq) ||
- unlikely(READ_ONCE(rdp->gpwrap))) {
+ unlikely(rdp->gpwrap)) {
if (!offloaded)
ret = rcu_advance_cbs(rnp, rdp); /* Advance CBs. */
rdp->core_needs_qs = false;
@@ -1289,7 +1289,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, struct rcu_data *rdp)
/* Now handle the beginnings of any new-to-this-CPU grace periods. */
if (rcu_seq_new_gp(rdp->gp_seq, rnp->gp_seq) ||
- unlikely(READ_ONCE(rdp->gpwrap))) {
+ unlikely(rdp->gpwrap)) {
/*
* If the current grace period is waiting for this CPU,
* set up to detect a quiescent state, otherwise don't
@@ -1304,7 +1304,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, struct rcu_data *rdp)
rdp->gp_seq = rnp->gp_seq; /* Remember new grace-period state. */
if (ULONG_CMP_LT(rdp->gp_seq_needed, rnp->gp_seq_needed) || rdp->gpwrap)
WRITE_ONCE(rdp->gp_seq_needed, rnp->gp_seq_needed);
- if (IS_ENABLED(CONFIG_PROVE_RCU) && READ_ONCE(rdp->gpwrap))
+ if (IS_ENABLED(CONFIG_PROVE_RCU) && rdp->gpwrap)
WRITE_ONCE(rdp->last_sched_clock, jiffies);
WRITE_ONCE(rdp->gpwrap, false);
rcu_gpnum_ovf(rnp, rdp);
--
2.40.1
^ permalink raw reply related [flat|nested] 34+ messages in thread* [PATCH rcu v2] 3/5] rcu: Fix get_state_synchronize_rcu_full() GP-start detection
2025-01-30 18:53 ` [PATCH rcu 0/5] Miscellaneous fixes Paul E. McKenney
2025-01-30 18:53 ` [PATCH rcu v2] 1/5] rcu: Split rcu_report_exp_cpu_mult() mask parameter and use for tracing Paul E. McKenney
2025-01-30 18:53 ` [PATCH rcu v2] 2/5] rcu: Remove READ_ONCE() for rdp->gpwrap access in __note_gp_changes() Paul E. McKenney
@ 2025-01-30 18:53 ` Paul E. McKenney
2025-01-30 18:53 ` [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall() Paul E. McKenney
` (2 subsequent siblings)
5 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-01-30 18:53 UTC (permalink / raw)
To: rcu
Cc: linux-kernel, kernel-team, rostedt, Paul E. McKenney,
Frederic Weisbecker, Joel Fernandes, Uladzislau Rezki
The get_state_synchronize_rcu_full() and poll_state_synchronize_rcu_full()
functions use the root rcu_node structure's ->gp_seq field to detect
the beginnings and ends of grace periods, respectively. This choice is
necessary for the poll_state_synchronize_rcu_full() function because
(give or take counter wrap), the following sequence is guaranteed not
to trigger:
get_state_synchronize_rcu_full(&rgos);
synchronize_rcu();
WARN_ON_ONCE(!poll_state_synchronize_rcu_full(&rgos));
The RCU callbacks that awaken synchronize_rcu() instances are
guaranteed not to be invoked before the root rcu_node structure's
->gp_seq field is updated to indicate the end of the grace period.
However, these callbacks might start being invoked immediately
thereafter, in particular, before rcu_state.gp_seq has been updated.
Therefore, poll_state_synchronize_rcu_full() must refer to the
root rcu_node structure's ->gp_seq field. Because this field is
updated under this structure's ->lock, any code following a call to
poll_state_synchronize_rcu_full() will be fully ordered after the
full grace-period computation, as is required by RCU's memory-ordering
semantics.
By symmetry, the get_state_synchronize_rcu_full() function should also
use this same root rcu_node structure's ->gp_seq field. But it turns out
that symmetry is profoundly (though extremely infrequently) destructive
in this case. To see this, consider the following sequence of events:
1. CPU 0 starts a new grace period, and updates rcu_state.gp_seq
accordingly.
2. As its first step of grace-period initialization, CPU 0 examines
the current CPU hotplug state and decides that it need not wait
for CPU 1, which is currently offline.
3. CPU 1 comes online, and updates its state. But this does not
affect the current grace period, but rather the one after that.
After all, CPU 1 was offline when the current grace period
started, so all pre-existing RCU readers on CPU 1 must have
completed or been preempted before it last went offline.
The current grace period therefore has nothing it needs to wait
for on CPU 1.
4. CPU 1 switches to an rcutorture kthread which is running
rcutorture's rcu_torture_reader() function, which starts a new
RCU reader.
5. CPU 2 is running rcutorture's rcu_torture_writer() function
and collects a new polled grace-period "cookie" using
get_state_synchronize_rcu_full(). Because the newly started
grace period has not completed initialization, the root rcu_node
structure's ->gp_seq field has not yet been updated to indicate
that this new grace period has already started.
This cookie is therefore set up for the end of the current grace
period (rather than the end of the following grace period).
6. CPU 0 finishes grace-period initialization.
7. If CPU 1’s rcutorture reader is preempted, it will be added to
the ->blkd_tasks list, but because CPU 1’s ->qsmask bit is not
set in CPU 1's leaf rcu_node structure, the ->gp_tasks pointer
will not be updated. Thus, this grace period will not wait on
it. Which is only fair, given that the CPU did not come online
until after the grace period officially started.
8. CPUs 0 and 2 then detect the new grace period and then report
a quiescent state to the RCU core.
9. Because CPU 1 was offline at the start of the current grace
period, CPUs 0 and 2 are the only CPUs that this grace period
needs to wait on. So the grace period ends and post-grace-period
cleanup starts. In particular, the root rcu_node structure's
->gp_seq field is updated to indicate that this grace period
has now ended.
10. CPU 2 continues running rcu_torture_writer() and sees that,
from the viewpoint of the root rcu_node structure consulted by
the poll_state_synchronize_rcu_full() function, the grace period
has ended. It therefore updates state accordingly.
11. CPU 1 is still running the same RCU reader, which notices this
update and thus complains about the too-short grace period.
The fix is for the get_state_synchronize_rcu_full() function to use
rcu_state.gp_seq instead of the root rcu_node structure's ->gp_seq field.
With this change in place, if step 5's cookie indicates that the grace
period has not yet started, then any prior code executed by CPU 2 must
have happened before CPU 1 came online. This will in turn prevent CPU
1's code in steps 3 and 11 from spanning CPU 2's grace-period wait,
thus preventing CPU 1 from being subjected to a too-short grace period.
This commit therefore makes this change. Note that there is no change to
the poll_state_synchronize_rcu_full() function, which as noted above,
must continue to use the root rcu_node structure's ->gp_seq field.
This is of course an asymmetry between these two functions, but is an
asymmetry that is absolutely required for correct operation. It is a
common human tendency to greatly value symmetry, and sometimes symmetry
is a wonderful thing. Other times, symmetry results in poor performance.
But in this case, symmetry is just plain wrong.
Nevertheless, the asymmetry does require an additional adjustment.
It is possible for get_state_synchronize_rcu_full() to see a given
grace period as having started, but for an immediately following
poll_state_synchronize_rcu_full() to see it as having not yet started.
Given the current rcu_seq_done_exact() implementation, this will
result in a false-positive indication that the grace period is done
from poll_state_synchronize_rcu_full(). This is dealt with by making
rcu_seq_done_exact() reach back three grace periods rather than just
two of them.
Although this fixes 91a967fd6934 ("rcu: Add full-sized polling for
get_completed*() and poll_state*()"), it is not clear that it is
worth backporting this commit. First, it took me many weeks to
convince rcutorture to reproduce this more frequently than once
per year. Second, this cannot be reproduced at all without frequent
CPU-hotplug operations, as in waiting all of 50 milliseconds from the
end of the previous operation until starting the next one. Third,
the TREE03.boot settings cause multi-millisecond delays during RCU
grace-period initialization, which greatly increase the probability of
the above sequence of events. (Don't do this in production workloads!)
Fourth, the TREE03 rcutorture scenario was modified to use four-CPU
guest OSes, to have a single-rcu_node combining tree, no testing of RCU
priority boosting, and no random preemption, and these modifications
were necessary to reproduce this issue in a reasonable timeframe.
Fifth, extremely heavy use of get_state_synchronize_rcu_full() and/or
poll_state_synchronize_rcu_full() is required to reproduce this, and as of
v6.12, only kfree_rcu() uses it, and even then not particularly heavily.
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Reviewed-by: Frederic Weisbecker <frederic@kernel.org>
Reviewed-by: Joel Fernandes (Google) <joel@joelfernandes.org>
Tested-by: Uladzislau Rezki (Sony) <urezki@gmail.com>
---
kernel/rcu/rcu.h | 2 +-
kernel/rcu/tree.c | 9 ++++++---
2 files changed, 7 insertions(+), 4 deletions(-)
diff --git a/kernel/rcu/rcu.h b/kernel/rcu/rcu.h
index feb3ac1dc5d5..f87c9d6d36fc 100644
--- a/kernel/rcu/rcu.h
+++ b/kernel/rcu/rcu.h
@@ -162,7 +162,7 @@ static inline bool rcu_seq_done_exact(unsigned long *sp, unsigned long s)
{
unsigned long cur_s = READ_ONCE(*sp);
- return ULONG_CMP_GE(cur_s, s) || ULONG_CMP_LT(cur_s, s - (2 * RCU_SEQ_STATE_MASK + 1));
+ return ULONG_CMP_GE(cur_s, s) || ULONG_CMP_LT(cur_s, s - (3 * RCU_SEQ_STATE_MASK + 1));
}
/*
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index e49bcb86b6d3..9ba34206e20d 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -4197,14 +4197,17 @@ EXPORT_SYMBOL_GPL(get_state_synchronize_rcu);
*/
void get_state_synchronize_rcu_full(struct rcu_gp_oldstate *rgosp)
{
- struct rcu_node *rnp = rcu_get_root();
-
/*
* Any prior manipulation of RCU-protected data must happen
* before the loads from ->gp_seq and ->expedited_sequence.
*/
smp_mb(); /* ^^^ */
- rgosp->rgos_norm = rcu_seq_snap(&rnp->gp_seq);
+
+ // Yes, rcu_state.gp_seq, not rnp_root->gp_seq, the latter's use
+ // in poll_state_synchronize_rcu_full() notwithstanding. Use of
+ // the latter here would result in too-short grace periods due to
+ // interactions with newly onlined CPUs.
+ rgosp->rgos_norm = rcu_seq_snap(&rcu_state.gp_seq);
rgosp->rgos_exp = rcu_seq_snap(&rcu_state.expedited_sequence);
}
EXPORT_SYMBOL_GPL(get_state_synchronize_rcu_full);
--
2.40.1
^ permalink raw reply related [flat|nested] 34+ messages in thread* [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-01-30 18:53 ` [PATCH rcu 0/5] Miscellaneous fixes Paul E. McKenney
` (2 preceding siblings ...)
2025-01-30 18:53 ` [PATCH rcu v2] 3/5] rcu: Fix get_state_synchronize_rcu_full() GP-start detection Paul E. McKenney
@ 2025-01-30 18:53 ` Paul E. McKenney
2025-02-04 10:26 ` Sebastian Andrzej Siewior
2025-01-30 18:53 ` [PATCH rcu v2] 5/5] rcu/nocb: Print segment lengths in show_rcu_nocb_gp_state() Paul E. McKenney
2025-02-06 10:15 ` [PATCH rcu 6/5] Make RCU watch ct_kernel_exit_state() warning Paul E. McKenney
5 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-01-30 18:53 UTC (permalink / raw)
To: rcu
Cc: linux-kernel, kernel-team, rostedt, Paul E. McKenney,
Sebastian Andrzej Siewior, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
The timer and hrtimer softirq processing has moved to dedicated threads
for kernels built with CONFIG_IRQ_FORCED_THREADING=y. This results in
timers not expiring until later in early boot, which in turn causes the
RCU Tasks self-tests to hang in kernels built with CONFIG_PROVE_RCU=y,
which further causes the entire kernel to hang. One fix would be to
make timers work during this time, but there are no known users of RCU
Tasks grace periods during that time, so no justification for the added
complexity. Not yet, anyway.
This commit therefore moves the call to rcu_init_tasks_generic() from
kernel_init_freeable() to a core_initcall(). This works because the
timer and hrtimer kthreads are created at early_initcall() time.
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Cc: Frederic Weisbecker <frederic@kernel.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Alexei Starovoitov <ast@kernel.org>
Cc: Andrii Nakryiko <andrii@kernel.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Masami Hiramatsu <mhiramat@kernel.org>
Cc: <linux-trace-kernel@vger.kernel.org>
---
include/linux/rcupdate.h | 6 ------
init/main.c | 1 -
kernel/rcu/tasks.h | 5 ++++-
3 files changed, 4 insertions(+), 8 deletions(-)
diff --git a/include/linux/rcupdate.h b/include/linux/rcupdate.h
index 3bb554723074..c6c4aee47df2 100644
--- a/include/linux/rcupdate.h
+++ b/include/linux/rcupdate.h
@@ -121,12 +121,6 @@ void rcu_init(void);
extern int rcu_scheduler_active;
void rcu_sched_clock_irq(int user);
-#ifdef CONFIG_TASKS_RCU_GENERIC
-void rcu_init_tasks_generic(void);
-#else
-static inline void rcu_init_tasks_generic(void) { }
-#endif
-
#ifdef CONFIG_RCU_STALL_COMMON
void rcu_sysrq_start(void);
void rcu_sysrq_end(void);
diff --git a/init/main.c b/init/main.c
index 00fac1170294..fb880b6fb524 100644
--- a/init/main.c
+++ b/init/main.c
@@ -1562,7 +1562,6 @@ static noinline void __init kernel_init_freeable(void)
init_mm_internals();
- rcu_init_tasks_generic();
do_pre_smp_initcalls();
lockup_detector_init();
diff --git a/kernel/rcu/tasks.h b/kernel/rcu/tasks.h
index 59314da5eb60..466668eb4fad 100644
--- a/kernel/rcu/tasks.h
+++ b/kernel/rcu/tasks.h
@@ -2256,7 +2256,7 @@ void __init tasks_cblist_init_generic(void)
#endif
}
-void __init rcu_init_tasks_generic(void)
+static int __init rcu_init_tasks_generic(void)
{
#ifdef CONFIG_TASKS_RCU
rcu_spawn_tasks_kthread();
@@ -2272,7 +2272,10 @@ void __init rcu_init_tasks_generic(void)
// Run the self-tests.
rcu_tasks_initiate_self_tests();
+
+ return 0;
}
+core_initcall(rcu_init_tasks_generic);
#else /* #ifdef CONFIG_TASKS_RCU_GENERIC */
static inline void rcu_tasks_bootup_oddness(void) {}
--
2.40.1
^ permalink raw reply related [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-01-30 18:53 ` [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall() Paul E. McKenney
@ 2025-02-04 10:26 ` Sebastian Andrzej Siewior
2025-02-04 11:51 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: Sebastian Andrzej Siewior @ 2025-02-04 10:26 UTC (permalink / raw)
To: Paul E. McKenney
Cc: rcu, linux-kernel, kernel-team, rostedt, Frederic Weisbecker,
Thomas Gleixner, Alexei Starovoitov, Andrii Nakryiko,
Mathieu Desnoyers, Masami Hiramatsu, linux-trace-kernel
On 2025-01-30 10:53:19 [-0800], Paul E. McKenney wrote:
> The timer and hrtimer softirq processing has moved to dedicated threads
> for kernels built with CONFIG_IRQ_FORCED_THREADING=y. This results in
> timers not expiring until later in early boot, which in turn causes the
> RCU Tasks self-tests to hang in kernels built with CONFIG_PROVE_RCU=y,
> which further causes the entire kernel to hang. One fix would be to
> make timers work during this time, but there are no known users of RCU
> Tasks grace periods during that time, so no justification for the added
> complexity. Not yet, anyway.
>
> This commit therefore moves the call to rcu_init_tasks_generic() from
> kernel_init_freeable() to a core_initcall(). This works because the
> timer and hrtimer kthreads are created at early_initcall() time.
Fixes: 49a17639508c3 ("softirq: Use a dedicated thread for timer wakeups on PREEMPT_RT.")
?
I played with it and I can reproduce the issue with !RT + threadirqs but
not with RT (which implies threadirqs).
Is there anything in RT that avoids the problem?
Thank you for debugging and the patch.
Sebastian
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-04 10:26 ` Sebastian Andrzej Siewior
@ 2025-02-04 11:51 ` Paul E. McKenney
2025-02-04 16:34 ` Sebastian Andrzej Siewior
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-04 11:51 UTC (permalink / raw)
To: Sebastian Andrzej Siewior
Cc: rcu, linux-kernel, kernel-team, rostedt, Frederic Weisbecker,
Thomas Gleixner, Alexei Starovoitov, Andrii Nakryiko,
Mathieu Desnoyers, Masami Hiramatsu, linux-trace-kernel
On Tue, Feb 04, 2025 at 11:26:11AM +0100, Sebastian Andrzej Siewior wrote:
> On 2025-01-30 10:53:19 [-0800], Paul E. McKenney wrote:
> > The timer and hrtimer softirq processing has moved to dedicated threads
> > for kernels built with CONFIG_IRQ_FORCED_THREADING=y. This results in
> > timers not expiring until later in early boot, which in turn causes the
> > RCU Tasks self-tests to hang in kernels built with CONFIG_PROVE_RCU=y,
> > which further causes the entire kernel to hang. One fix would be to
> > make timers work during this time, but there are no known users of RCU
> > Tasks grace periods during that time, so no justification for the added
> > complexity. Not yet, anyway.
> >
> > This commit therefore moves the call to rcu_init_tasks_generic() from
> > kernel_init_freeable() to a core_initcall(). This works because the
> > timer and hrtimer kthreads are created at early_initcall() time.
>
> Fixes: 49a17639508c3 ("softirq: Use a dedicated thread for timer wakeups on PREEMPT_RT.")
> ?
Quite possibly... I freely confess that I was more focused on the fix
than on the bug's origin. Would you be willing to try this commit and
its predecessor?
> I played with it and I can reproduce the issue with !RT + threadirqs but
> not with RT (which implies threadirqs).
> Is there anything in RT that avoids the problem?
Not that I know of, but then again I did not try it. To your point,
I do need to make a -rt rcutorture scenario. TREE03 has been intended to
approximate this, and it uses the following Kconfig options:
------------------------------------------------------------------------
CONFIG_SMP=y
CONFIG_NR_CPUS=16
CONFIG_PREEMPT_NONE=n
CONFIG_PREEMPT_VOLUNTARY=n
CONFIG_PREEMPT=y
#CHECK#CONFIG_PREEMPT_RCU=y
CONFIG_HZ_PERIODIC=y
CONFIG_NO_HZ_IDLE=n
CONFIG_NO_HZ_FULL=n
CONFIG_RCU_TRACE=y
CONFIG_HOTPLUG_CPU=y
CONFIG_RCU_FANOUT=2
CONFIG_RCU_FANOUT_LEAF=2
CONFIG_RCU_NOCB_CPU=n
CONFIG_DEBUG_LOCK_ALLOC=n
CONFIG_RCU_BOOST=y
CONFIG_DEBUG_OBJECTS_RCU_HEAD=n
CONFIG_RCU_EXPERT=y
------------------------------------------------------------------------
And the following kernel-boot parameters:
------------------------------------------------------------------------
rcutorture.onoff_interval=200 rcutorture.onoff_holdoff=30
rcutree.gp_preinit_delay=12
rcutree.gp_init_delay=3
rcutree.gp_cleanup_delay=3
rcutree.kthread_prio=2
threadirqs
rcutree.use_softirq=0
rcutorture.preempt_duration=10
------------------------------------------------------------------------
Some of these are for RCU's benefit, but what should I change to more
closely approximate a typical real-time deployment?
> Thank you for debugging and the patch.
And to you for digging into it!
Thanx, Paul
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-04 11:51 ` Paul E. McKenney
@ 2025-02-04 16:34 ` Sebastian Andrzej Siewior
2025-02-04 20:20 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: Sebastian Andrzej Siewior @ 2025-02-04 16:34 UTC (permalink / raw)
To: Paul E. McKenney
Cc: rcu, linux-kernel, kernel-team, rostedt, Frederic Weisbecker,
Thomas Gleixner, Alexei Starovoitov, Andrii Nakryiko,
Mathieu Desnoyers, Masami Hiramatsu, linux-trace-kernel
On 2025-02-04 03:51:48 [-0800], Paul E. McKenney wrote:
> On Tue, Feb 04, 2025 at 11:26:11AM +0100, Sebastian Andrzej Siewior wrote:
> > On 2025-01-30 10:53:19 [-0800], Paul E. McKenney wrote:
> > > The timer and hrtimer softirq processing has moved to dedicated threads
> > > for kernels built with CONFIG_IRQ_FORCED_THREADING=y. This results in
> > > timers not expiring until later in early boot, which in turn causes the
> > > RCU Tasks self-tests to hang in kernels built with CONFIG_PROVE_RCU=y,
> > > which further causes the entire kernel to hang. One fix would be to
> > > make timers work during this time, but there are no known users of RCU
> > > Tasks grace periods during that time, so no justification for the added
> > > complexity. Not yet, anyway.
> > >
> > > This commit therefore moves the call to rcu_init_tasks_generic() from
> > > kernel_init_freeable() to a core_initcall(). This works because the
> > > timer and hrtimer kthreads are created at early_initcall() time.
> >
> > Fixes: 49a17639508c3 ("softirq: Use a dedicated thread for timer wakeups on PREEMPT_RT.")
> > ?
>
> Quite possibly... I freely confess that I was more focused on the fix
> than on the bug's origin. Would you be willing to try this commit and
> its predecessor?
Yes. Just verified.
Tested-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Reviewed-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> > I played with it and I can reproduce the issue with !RT + threadirqs but
> > not with RT (which implies threadirqs).
> > Is there anything in RT that avoids the problem?
>
> Not that I know of, but then again I did not try it. To your point,
The change looks fine.
> I do need to make a -rt rcutorture scenario. TREE03 has been intended to
> approximate this, and it uses the following Kconfig options:
>
> ------------------------------------------------------------------------
>
> CONFIG_SMP=y
> CONFIG_NR_CPUS=16
> CONFIG_PREEMPT_NONE=n
> CONFIG_PREEMPT_VOLUNTARY=n
> CONFIG_PREEMPT=y
> #CHECK#CONFIG_PREEMPT_RCU=y
> CONFIG_HZ_PERIODIC=y
> CONFIG_NO_HZ_IDLE=n
> CONFIG_NO_HZ_FULL=n
> CONFIG_RCU_TRACE=y
> CONFIG_HOTPLUG_CPU=y
> CONFIG_RCU_FANOUT=2
> CONFIG_RCU_FANOUT_LEAF=2
> CONFIG_RCU_NOCB_CPU=n
> CONFIG_DEBUG_LOCK_ALLOC=n
> CONFIG_RCU_BOOST=y
> CONFIG_DEBUG_OBJECTS_RCU_HEAD=n
> CONFIG_RCU_EXPERT=y
You could enable CONFIG_PREEMPT_RT ;)
CONFIG_PREEMPT_LAZY is probably also set a lot.
That should be it.
> ------------------------------------------------------------------------
>
> And the following kernel-boot parameters:
>
> ------------------------------------------------------------------------
>
> rcutorture.onoff_interval=200 rcutorture.onoff_holdoff=30
> rcutree.gp_preinit_delay=12
> rcutree.gp_init_delay=3
> rcutree.gp_cleanup_delay=3
> rcutree.kthread_prio=2
> threadirqs
> rcutree.use_softirq=0
> rcutorture.preempt_duration=10
>
> ------------------------------------------------------------------------
>
> Some of these are for RCU's benefit, but what should I change to more
> closely approximate a typical real-time deployment?
See above.
> > Thank you for debugging and the patch.
>
> And to you for digging into it!
Thanks.
> Thanx, Paul
Sebastian
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-04 16:34 ` Sebastian Andrzej Siewior
@ 2025-02-04 20:20 ` Paul E. McKenney
2025-02-05 14:50 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-04 20:20 UTC (permalink / raw)
To: Sebastian Andrzej Siewior
Cc: rcu, linux-kernel, kernel-team, rostedt, Frederic Weisbecker,
Thomas Gleixner, Alexei Starovoitov, Andrii Nakryiko,
Mathieu Desnoyers, Masami Hiramatsu, linux-trace-kernel
On Tue, Feb 04, 2025 at 05:34:09PM +0100, Sebastian Andrzej Siewior wrote:
> On 2025-02-04 03:51:48 [-0800], Paul E. McKenney wrote:
> > On Tue, Feb 04, 2025 at 11:26:11AM +0100, Sebastian Andrzej Siewior wrote:
> > > On 2025-01-30 10:53:19 [-0800], Paul E. McKenney wrote:
> > > > The timer and hrtimer softirq processing has moved to dedicated threads
> > > > for kernels built with CONFIG_IRQ_FORCED_THREADING=y. This results in
> > > > timers not expiring until later in early boot, which in turn causes the
> > > > RCU Tasks self-tests to hang in kernels built with CONFIG_PROVE_RCU=y,
> > > > which further causes the entire kernel to hang. One fix would be to
> > > > make timers work during this time, but there are no known users of RCU
> > > > Tasks grace periods during that time, so no justification for the added
> > > > complexity. Not yet, anyway.
> > > >
> > > > This commit therefore moves the call to rcu_init_tasks_generic() from
> > > > kernel_init_freeable() to a core_initcall(). This works because the
> > > > timer and hrtimer kthreads are created at early_initcall() time.
> > >
> > > Fixes: 49a17639508c3 ("softirq: Use a dedicated thread for timer wakeups on PREEMPT_RT.")
> > > ?
> >
> > Quite possibly... I freely confess that I was more focused on the fix
> > than on the bug's origin. Would you be willing to try this commit and
> > its predecessor?
>
> Yes. Just verified.
> Tested-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> Reviewed-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Boqun, could you please apply Sebastian's tags, including the Fixes
tag above?
> > > I played with it and I can reproduce the issue with !RT + threadirqs but
> > > not with RT (which implies threadirqs).
> > > Is there anything in RT that avoids the problem?
> >
> > Not that I know of, but then again I did not try it. To your point,
>
> The change looks fine.
>
> > I do need to make a -rt rcutorture scenario. TREE03 has been intended to
> > approximate this, and it uses the following Kconfig options:
> >
> > ------------------------------------------------------------------------
> >
> > CONFIG_SMP=y
> > CONFIG_NR_CPUS=16
> > CONFIG_PREEMPT_NONE=n
> > CONFIG_PREEMPT_VOLUNTARY=n
> > CONFIG_PREEMPT=y
> > #CHECK#CONFIG_PREEMPT_RCU=y
> > CONFIG_HZ_PERIODIC=y
> > CONFIG_NO_HZ_IDLE=n
> > CONFIG_NO_HZ_FULL=n
> > CONFIG_RCU_TRACE=y
> > CONFIG_HOTPLUG_CPU=y
> > CONFIG_RCU_FANOUT=2
> > CONFIG_RCU_FANOUT_LEAF=2
> > CONFIG_RCU_NOCB_CPU=n
> > CONFIG_DEBUG_LOCK_ALLOC=n
> > CONFIG_RCU_BOOST=y
> > CONFIG_DEBUG_OBJECTS_RCU_HEAD=n
> > CONFIG_RCU_EXPERT=y
>
> You could enable CONFIG_PREEMPT_RT ;)
> CONFIG_PREEMPT_LAZY is probably also set a lot.
>
> That should be it.
>
> > ------------------------------------------------------------------------
> >
> > And the following kernel-boot parameters:
> >
> > ------------------------------------------------------------------------
> >
> > rcutorture.onoff_interval=200 rcutorture.onoff_holdoff=30
> > rcutree.gp_preinit_delay=12
> > rcutree.gp_init_delay=3
> > rcutree.gp_cleanup_delay=3
> > rcutree.kthread_prio=2
> > threadirqs
> > rcutree.use_softirq=0
> > rcutorture.preempt_duration=10
> >
> > ------------------------------------------------------------------------
> >
> > Some of these are for RCU's benefit, but what should I change to more
> > closely approximate a typical real-time deployment?
>
> See above.
Which got me this diff:
------------------------------------------------------------------------
diff --git a/tools/testing/selftests/rcutorture/configs/rcu/TREE03 b/tools/testing/selftests/rcutorture/configs/rcu/TREE03
index 2dc31b16e506..6158f5002497 100644
--- a/tools/testing/selftests/rcutorture/configs/rcu/TREE03
+++ b/tools/testing/selftests/rcutorture/configs/rcu/TREE03
@@ -2,7 +2,9 @@ CONFIG_SMP=y
CONFIG_NR_CPUS=16
CONFIG_PREEMPT_NONE=n
CONFIG_PREEMPT_VOLUNTARY=n
-CONFIG_PREEMPT=y
+CONFIG_PREEMPT=n
+CONFIG_PREEMPT_LAZY=y
+CONFIG_PREEMPT_RT=y
#CHECK#CONFIG_PREEMPT_RCU=y
CONFIG_HZ_PERIODIC=y
CONFIG_NO_HZ_IDLE=n
@@ -15,4 +17,5 @@ CONFIG_RCU_NOCB_CPU=n
CONFIG_DEBUG_LOCK_ALLOC=n
CONFIG_RCU_BOOST=y
CONFIG_DEBUG_OBJECTS_RCU_HEAD=n
+CONFIG_EXPERT=y
CONFIG_RCU_EXPERT=y
------------------------------------------------------------------------
But a 10-minute run got me the splat shown below, and in addition a
shutdown-time hang.
This is caused by RCU falling behind a callback-flooding kthread that
invokes call_rcu() in a semi-tight loop. Setting rcutree.kthread_prio=40
avoids the splat, but still gets the shutdown-time hang. Retrying with
the default rcutree.kthread_prio=2 failed to reproduce the splat, but
it did reproduce the shutdown-time hang.
OK, maybe printk buffers are not being flushed? A 100-millisecond sleep
at the end of of rcu_torture_cleanup() got all of rcutorture's output
flushed, but lost the subsequent shutdown-time console traffic. The
pr_flush(HZ/10,1) seems more sensible, but this is private to printk().
I would like to log the shutdown-time console traffic because RCU can
sometimes break things on that path.
Thoughts?
Thanx, Paul
PS: I will do longer runs in case that splat was not a one-off.
My concern is that I might need to adjust something more in order
to get a reliable callback-flooding test.
------------------------------------------------------------------------
[ 133.107605] ------------[ cut here ]------------
[ 133.107611] rcutorture_oom_notify invoked upon OOM during forward-progress testing.
[ 133.107636] WARNING: CPU: 0 PID: 236 at kernel/rcu/rcutorture.c:3117 rcutorture_oom_notify+0x48/0x2e0
[ 133.107651] Modules linked in:
[ 133.107662] CPU: 0 UID: 0 PID: 236 Comm: rcu_torture_fwd Not tainted 6.13.0-rc2-00108-g56d12f072c66-dirty #1747
[ 133.107667] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.15.0-1 04/01/2014
[ 133.107669] RIP: 0010:rcutorture_oom_notify+0x48/0x2e0
[ 133.107673] Code: e8 3d ca c3 00 48 8b 2d 5e 8e 17 02 48 85 ed 0f 84 82 02 00 00 90 48 c7 c6 a0 fc 20 a7 48 c7 c7 40 82 68 a7 e8 f9 38 f6 ff 90 <0f> 0b 90 90 8b 35 36 10 82 01 45 31 e4 85 f6 7e 3c 49 63 dc 41 83
[ 133.107675] RSP: 0018:ffffa3b10081fab0 EFLAGS: 00010286
[ 133.107679] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000027
[ 133.107681] RDX: ffff8bf11f21c948 RSI: 0000000000000001 RDI: ffff8bf11f21c940
[ 133.107682] RBP: ffff8bf101ff8000 R08: ffffffffa7b42608 R09: 00000000ffffdfff
[ 133.107683] R10: ffffffffa7a62620 R11: ffffffffa7b12620 R12: 0000000000000000
[ 133.107685] R13: ffffa3b10081fb60 R14: 00000000ffffffff R15: 0000000000000000
[ 133.107688] FS: 0000000000000000(0000) GS:ffff8bf11f200000(0000) knlGS:0000000000000000
[ 133.107690] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 133.107691] CR2: ffff8bf10fe01000 CR3: 0000000001f88000 CR4: 00000000000006f0
[ 133.107693] Call Trace:
[ 133.107709] <TASK>
[ 133.107713] ? __warn+0x83/0x130
[ 133.107716] ? rcutorture_oom_notify+0x48/0x2e0
[ 133.107720] ? report_bug+0x18e/0x1a0
[ 133.107723] ? handle_bug+0x54/0x90
[ 133.107727] ? exc_invalid_op+0x18/0x70
[ 133.107729] ? asm_exc_invalid_op+0x1a/0x20
[ 133.107733] ? rcutorture_oom_notify+0x48/0x2e0
[ 133.107736] notifier_call_chain+0x59/0xc0
[ 133.107744] blocking_notifier_call_chain+0x3c/0x60
[ 133.107746] out_of_memory+0x1f3/0x710
[ 133.107754] __alloc_pages_noprof+0xf27/0x10b0
[ 133.107764] ? timerqueue_del+0x2e/0x50
[ 133.107767] alloc_pages_mpol_noprof+0x43/0xf0
[ 133.107774] new_slab+0x37d/0x440
[ 133.107796] ___slab_alloc+0x480/0x9a0
[ 133.107801] ? rcu_torture_fwd_prog+0x344/0x9e0
[ 133.107803] ? preempt_schedule_thunk+0x1a/0x30
[ 133.107806] ? rcu_torture_fwd_prog+0x344/0x9e0
[ 133.107808] __kmalloc_cache_noprof+0x74/0x1f0
[ 133.107811] rcu_torture_fwd_prog+0x344/0x9e0
[ 133.107814] ? __pfx_rcu_torture_fwd_prog+0x10/0x10
[ 133.107816] ? kthread+0xd1/0x100
[ 133.107818] ? __pfx_rcu_torture_fwd_prog+0x10/0x10
[ 133.107819] kthread+0xd1/0x100
[ 133.107824] ? __pfx_kthread+0x10/0x10
[ 133.107826] ret_from_fork+0x2f/0x50
[ 133.107833] ? __pfx_kthread+0x10/0x10
[ 133.107835] ret_from_fork_asm+0x1a/0x30
[ 133.107842] </TASK>
[ 133.107843] ---[ end trace 0000000000000000 ]---
^ permalink raw reply related [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-04 20:20 ` Paul E. McKenney
@ 2025-02-05 14:50 ` Paul E. McKenney
2025-02-05 19:54 ` John Ogness
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-05 14:50 UTC (permalink / raw)
To: Sebastian Andrzej Siewior
Cc: rcu, linux-kernel, kernel-team, rostedt, Frederic Weisbecker,
Thomas Gleixner, Alexei Starovoitov, Andrii Nakryiko,
Mathieu Desnoyers, Masami Hiramatsu, linux-trace-kernel,
john.ogness
On Tue, Feb 04, 2025 at 12:20:30PM -0800, Paul E. McKenney wrote:
> On Tue, Feb 04, 2025 at 05:34:09PM +0100, Sebastian Andrzej Siewior wrote:
> > On 2025-02-04 03:51:48 [-0800], Paul E. McKenney wrote:
> > > On Tue, Feb 04, 2025 at 11:26:11AM +0100, Sebastian Andrzej Siewior wrote:
> > > > On 2025-01-30 10:53:19 [-0800], Paul E. McKenney wrote:
> > > > > The timer and hrtimer softirq processing has moved to dedicated threads
> > > > > for kernels built with CONFIG_IRQ_FORCED_THREADING=y. This results in
> > > > > timers not expiring until later in early boot, which in turn causes the
> > > > > RCU Tasks self-tests to hang in kernels built with CONFIG_PROVE_RCU=y,
> > > > > which further causes the entire kernel to hang. One fix would be to
> > > > > make timers work during this time, but there are no known users of RCU
> > > > > Tasks grace periods during that time, so no justification for the added
> > > > > complexity. Not yet, anyway.
> > > > >
> > > > > This commit therefore moves the call to rcu_init_tasks_generic() from
> > > > > kernel_init_freeable() to a core_initcall(). This works because the
> > > > > timer and hrtimer kthreads are created at early_initcall() time.
> > > >
> > > > Fixes: 49a17639508c3 ("softirq: Use a dedicated thread for timer wakeups on PREEMPT_RT.")
> > > > ?
> > >
> > > Quite possibly... I freely confess that I was more focused on the fix
> > > than on the bug's origin. Would you be willing to try this commit and
> > > its predecessor?
> >
> > Yes. Just verified.
> > Tested-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> > Reviewed-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
>
> Boqun, could you please apply Sebastian's tags, including the Fixes
> tag above?
>
> > > > I played with it and I can reproduce the issue with !RT + threadirqs but
> > > > not with RT (which implies threadirqs).
> > > > Is there anything in RT that avoids the problem?
> > >
> > > Not that I know of, but then again I did not try it. To your point,
> >
> > The change looks fine.
> >
> > > I do need to make a -rt rcutorture scenario. TREE03 has been intended to
> > > approximate this, and it uses the following Kconfig options:
> > >
> > > ------------------------------------------------------------------------
> > >
> > > CONFIG_SMP=y
> > > CONFIG_NR_CPUS=16
> > > CONFIG_PREEMPT_NONE=n
> > > CONFIG_PREEMPT_VOLUNTARY=n
> > > CONFIG_PREEMPT=y
> > > #CHECK#CONFIG_PREEMPT_RCU=y
> > > CONFIG_HZ_PERIODIC=y
> > > CONFIG_NO_HZ_IDLE=n
> > > CONFIG_NO_HZ_FULL=n
> > > CONFIG_RCU_TRACE=y
> > > CONFIG_HOTPLUG_CPU=y
> > > CONFIG_RCU_FANOUT=2
> > > CONFIG_RCU_FANOUT_LEAF=2
> > > CONFIG_RCU_NOCB_CPU=n
> > > CONFIG_DEBUG_LOCK_ALLOC=n
> > > CONFIG_RCU_BOOST=y
> > > CONFIG_DEBUG_OBJECTS_RCU_HEAD=n
> > > CONFIG_RCU_EXPERT=y
> >
> > You could enable CONFIG_PREEMPT_RT ;)
> > CONFIG_PREEMPT_LAZY is probably also set a lot.
> >
> > That should be it.
> >
> > > ------------------------------------------------------------------------
> > >
> > > And the following kernel-boot parameters:
> > >
> > > ------------------------------------------------------------------------
> > >
> > > rcutorture.onoff_interval=200 rcutorture.onoff_holdoff=30
> > > rcutree.gp_preinit_delay=12
> > > rcutree.gp_init_delay=3
> > > rcutree.gp_cleanup_delay=3
> > > rcutree.kthread_prio=2
> > > threadirqs
> > > rcutree.use_softirq=0
> > > rcutorture.preempt_duration=10
> > >
> > > ------------------------------------------------------------------------
> > >
> > > Some of these are for RCU's benefit, but what should I change to more
> > > closely approximate a typical real-time deployment?
> >
> > See above.
>
> Which got me this diff:
>
> ------------------------------------------------------------------------
>
> diff --git a/tools/testing/selftests/rcutorture/configs/rcu/TREE03 b/tools/testing/selftests/rcutorture/configs/rcu/TREE03
> index 2dc31b16e506..6158f5002497 100644
> --- a/tools/testing/selftests/rcutorture/configs/rcu/TREE03
> +++ b/tools/testing/selftests/rcutorture/configs/rcu/TREE03
> @@ -2,7 +2,9 @@ CONFIG_SMP=y
> CONFIG_NR_CPUS=16
> CONFIG_PREEMPT_NONE=n
> CONFIG_PREEMPT_VOLUNTARY=n
> -CONFIG_PREEMPT=y
> +CONFIG_PREEMPT=n
> +CONFIG_PREEMPT_LAZY=y
> +CONFIG_PREEMPT_RT=y
> #CHECK#CONFIG_PREEMPT_RCU=y
> CONFIG_HZ_PERIODIC=y
> CONFIG_NO_HZ_IDLE=n
> @@ -15,4 +17,5 @@ CONFIG_RCU_NOCB_CPU=n
> CONFIG_DEBUG_LOCK_ALLOC=n
> CONFIG_RCU_BOOST=y
> CONFIG_DEBUG_OBJECTS_RCU_HEAD=n
> +CONFIG_EXPERT=y
> CONFIG_RCU_EXPERT=y
>
> ------------------------------------------------------------------------
>
> But a 10-minute run got me the splat shown below, and in addition a
> shutdown-time hang.
>
> This is caused by RCU falling behind a callback-flooding kthread that
> invokes call_rcu() in a semi-tight loop. Setting rcutree.kthread_prio=40
> avoids the splat, but still gets the shutdown-time hang. Retrying with
> the default rcutree.kthread_prio=2 failed to reproduce the splat, but
> it did reproduce the shutdown-time hang.
>
> OK, maybe printk buffers are not being flushed? A 100-millisecond sleep
> at the end of of rcu_torture_cleanup() got all of rcutorture's output
> flushed, but lost the subsequent shutdown-time console traffic. The
> pr_flush(HZ/10,1) seems more sensible, but this is private to printk().
>
> I would like to log the shutdown-time console traffic because RCU can
> sometimes break things on that path.
>
> Thoughts?
Longer rcutorture runs showed (not unexpectedly) that the 100-millisecond
sleep was not always sufficient, nor was a 500-milliseconds sleep.
There is a call to kmsg_dump(KMSG_DUMP_SHUTDOWN) in kernel_power_off()
that appears to be intended to dump out the printk() buffers, but it
does not seem to do so in kernels built with CONFIG_PREEMPT_RT=y.
Does there need to be a pr_flush() call prior to the call to
migrate_to_reboot_cpu()? Or maybe even to do_kernel_power_off_prepare()
or kernel_shutdown_prepare()?
Adding John Ogness on CC so that he can tell me the error of my ways.
> PS: I will do longer runs in case that splat was not a one-off.
> My concern is that I might need to adjust something more in order
> to get a reliable callback-flooding test.
And this was not a one-off. Running 10 40-minute instances of the new-age
CONFIG_PREEMPT_RT=y TREE03 reliably triggers this. At first glance,
this appears to be an interaction between testing of RCU priority
boosting and RCU-callback flooding forward-progress testing. And disabling
testing of RCU priority boosting avoids these OOMs. As does running
without CONFIG_PREEMPT_RT=y.
My next step is to run with rcutorture.preempt_duration=0, which disables
within-guest-OS random preempting of kthreads. If that doesn't help,
I expect to play around with avoiding concurrent testing of RCU priority
boosting and RCU callback flooding forward progress.
Or is there a better way?
Thanx, Paul
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 14:50 ` Paul E. McKenney
@ 2025-02-05 19:54 ` John Ogness
2025-02-05 20:10 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: John Ogness @ 2025-02-05 19:54 UTC (permalink / raw)
To: paulmck, Sebastian Andrzej Siewior
Cc: rcu, linux-kernel, kernel-team, rostedt, Frederic Weisbecker,
Thomas Gleixner, Alexei Starovoitov, Andrii Nakryiko,
Mathieu Desnoyers, Masami Hiramatsu, linux-trace-kernel,
Petr Mladek
On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
>> This is caused by RCU falling behind a callback-flooding kthread that
>> invokes call_rcu() in a semi-tight loop. Setting rcutree.kthread_prio=40
>> avoids the splat, but still gets the shutdown-time hang. Retrying with
>> the default rcutree.kthread_prio=2 failed to reproduce the splat, but
>> it did reproduce the shutdown-time hang.
>>
>> OK, maybe printk buffers are not being flushed? A 100-millisecond sleep
>> at the end of of rcu_torture_cleanup() got all of rcutorture's output
>> flushed, but lost the subsequent shutdown-time console traffic. The
>> pr_flush(HZ/10,1) seems more sensible, but this is private to printk().
>>
>> I would like to log the shutdown-time console traffic because RCU can
>> sometimes break things on that path.
pr_flush() was changed to private because there were no users. It would
not be a problem to make it available. Adding a pr_flush() to
rcu_torture_cleanup() would be an appropriate workaround for now (more
on this at the end).
> There is a call to kmsg_dump(KMSG_DUMP_SHUTDOWN) in kernel_power_off()
> that appears to be intended to dump out the printk() buffers,
It only dumps the buffers to the registered kmsg_dumpers. It is not
responsible for flushing console backlogs.
> but it
> does not seem to do so in kernels built with CONFIG_PREEMPT_RT=y.
> Does there need to be a pr_flush() call prior to the call to
> migrate_to_reboot_cpu()? Or maybe even to do_kernel_power_off_prepare()
> or kernel_shutdown_prepare()?
With CONFIG_PREEMPT_RT=y, legacy consoles only print via a dedicated
kthread. Without a pr_flush() somewhere, there is basically no chance
that they will get backlogs flushed because noone is waitig for them.
The new console API (NBCON) provides support for "atomic consoles",
which _do_ flush by transitioning to synchronous printing during
shutdown/reboot. Unfortunately we still don't have any NBCON atomic
console implemented in the kernel. The 8250 UART will be our first
driver, most likely available in 6.15. (With the current PREEMPT_RT
patch applied, the 8250 NBCON atomic driver is used.)
Since only CONFIG_PREEMPT_RT=y has this issue, I am not sure if we want
to sprinkle pr_flush() calls on all sleepable shutdown/reboot paths,
although that is certainly one way to handle it. For your case, adding a
pr_flush() to rcu_torture_cleanup() and making pr_flush() non-private
would be an easy solution to avoid your problem.
John Ogness
^ permalink raw reply [flat|nested] 34+ messages in thread
* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 19:54 ` John Ogness
@ 2025-02-05 20:10 ` Paul E. McKenney
2025-02-05 20:31 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-05 20:10 UTC (permalink / raw)
To: John Ogness
Cc: Sebastian Andrzej Siewior, rcu, linux-kernel, kernel-team,
rostedt, Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel, Petr Mladek
On Wed, Feb 05, 2025 at 09:00:07PM +0106, John Ogness wrote:
> On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> >> This is caused by RCU falling behind a callback-flooding kthread that
> >> invokes call_rcu() in a semi-tight loop. Setting rcutree.kthread_prio=40
> >> avoids the splat, but still gets the shutdown-time hang. Retrying with
> >> the default rcutree.kthread_prio=2 failed to reproduce the splat, but
> >> it did reproduce the shutdown-time hang.
> >>
> >> OK, maybe printk buffers are not being flushed? A 100-millisecond sleep
> >> at the end of of rcu_torture_cleanup() got all of rcutorture's output
> >> flushed, but lost the subsequent shutdown-time console traffic. The
> >> pr_flush(HZ/10,1) seems more sensible, but this is private to printk().
> >>
> >> I would like to log the shutdown-time console traffic because RCU can
> >> sometimes break things on that path.
>
> pr_flush() was changed to private because there were no users. It would
> not be a problem to make it available. Adding a pr_flush() to
> rcu_torture_cleanup() would be an appropriate workaround for now (more
> on this at the end).
Ah, got it.
> > There is a call to kmsg_dump(KMSG_DUMP_SHUTDOWN) in kernel_power_off()
> > that appears to be intended to dump out the printk() buffers,
>
> It only dumps the buffers to the registered kmsg_dumpers. It is not
> responsible for flushing console backlogs.
That would explain its not doing much for me. ;-)
> > but it
> > does not seem to do so in kernels built with CONFIG_PREEMPT_RT=y.
> > Does there need to be a pr_flush() call prior to the call to
> > migrate_to_reboot_cpu()? Or maybe even to do_kernel_power_off_prepare()
> > or kernel_shutdown_prepare()?
>
> With CONFIG_PREEMPT_RT=y, legacy consoles only print via a dedicated
> kthread. Without a pr_flush() somewhere, there is basically no chance
> that they will get backlogs flushed because noone is waitig for them.
>
> The new console API (NBCON) provides support for "atomic consoles",
> which _do_ flush by transitioning to synchronous printing during
> shutdown/reboot. Unfortunately we still don't have any NBCON atomic
> console implemented in the kernel. The 8250 UART will be our first
> driver, most likely available in 6.15. (With the current PREEMPT_RT
> patch applied, the 8250 NBCON atomic driver is used.)
>
> Since only CONFIG_PREEMPT_RT=y has this issue, I am not sure if we want
> to sprinkle pr_flush() calls on all sleepable shutdown/reboot paths,
> although that is certainly one way to handle it. For your case, adding a
> pr_flush() to rcu_torture_cleanup() and making pr_flush() non-private
> would be an easy solution to avoid your problem.
Would it make sense to put a call to pr_flush() at the beginning of the
kernel_power_off() function? I suspect that would take care of much
more than just rcutorture.
Or maybe after the pr_emerg("Power down\n"), since that is normally
the last thing that shows up on rcutorture's console logs.
I will give that a shot and see what happens. ;-)
Thanx, Paul
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 20:10 ` Paul E. McKenney
@ 2025-02-05 20:31 ` Paul E. McKenney
2025-02-05 21:22 ` John Ogness
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-05 20:31 UTC (permalink / raw)
To: John Ogness
Cc: Sebastian Andrzej Siewior, rcu, linux-kernel, kernel-team,
rostedt, Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel, Petr Mladek
On Wed, Feb 05, 2025 at 12:10:53PM -0800, Paul E. McKenney wrote:
> On Wed, Feb 05, 2025 at 09:00:07PM +0106, John Ogness wrote:
> > On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > >> This is caused by RCU falling behind a callback-flooding kthread that
> > >> invokes call_rcu() in a semi-tight loop. Setting rcutree.kthread_prio=40
> > >> avoids the splat, but still gets the shutdown-time hang. Retrying with
> > >> the default rcutree.kthread_prio=2 failed to reproduce the splat, but
> > >> it did reproduce the shutdown-time hang.
> > >>
> > >> OK, maybe printk buffers are not being flushed? A 100-millisecond sleep
> > >> at the end of of rcu_torture_cleanup() got all of rcutorture's output
> > >> flushed, but lost the subsequent shutdown-time console traffic. The
> > >> pr_flush(HZ/10,1) seems more sensible, but this is private to printk().
> > >>
> > >> I would like to log the shutdown-time console traffic because RCU can
> > >> sometimes break things on that path.
> >
> > pr_flush() was changed to private because there were no users. It would
> > not be a problem to make it available. Adding a pr_flush() to
> > rcu_torture_cleanup() would be an appropriate workaround for now (more
> > on this at the end).
>
> Ah, got it.
>
> > > There is a call to kmsg_dump(KMSG_DUMP_SHUTDOWN) in kernel_power_off()
> > > that appears to be intended to dump out the printk() buffers,
> >
> > It only dumps the buffers to the registered kmsg_dumpers. It is not
> > responsible for flushing console backlogs.
>
> That would explain its not doing much for me. ;-)
>
> > > but it
> > > does not seem to do so in kernels built with CONFIG_PREEMPT_RT=y.
> > > Does there need to be a pr_flush() call prior to the call to
> > > migrate_to_reboot_cpu()? Or maybe even to do_kernel_power_off_prepare()
> > > or kernel_shutdown_prepare()?
> >
> > With CONFIG_PREEMPT_RT=y, legacy consoles only print via a dedicated
> > kthread. Without a pr_flush() somewhere, there is basically no chance
> > that they will get backlogs flushed because noone is waitig for them.
> >
> > The new console API (NBCON) provides support for "atomic consoles",
> > which _do_ flush by transitioning to synchronous printing during
> > shutdown/reboot. Unfortunately we still don't have any NBCON atomic
> > console implemented in the kernel. The 8250 UART will be our first
> > driver, most likely available in 6.15. (With the current PREEMPT_RT
> > patch applied, the 8250 NBCON atomic driver is used.)
> >
> > Since only CONFIG_PREEMPT_RT=y has this issue, I am not sure if we want
> > to sprinkle pr_flush() calls on all sleepable shutdown/reboot paths,
> > although that is certainly one way to handle it. For your case, adding a
> > pr_flush() to rcu_torture_cleanup() and making pr_flush() non-private
> > would be an easy solution to avoid your problem.
>
> Would it make sense to put a call to pr_flush() at the beginning of the
> kernel_power_off() function? I suspect that would take care of much
> more than just rcutorture.
>
> Or maybe after the pr_emerg("Power down\n"), since that is normally
> the last thing that shows up on rcutorture's console logs.
>
> I will give that a shot and see what happens. ;-)
And that does the trick! I specified 500ms, but maybe -1 would be
better? You tell me! ;-)
Thanx, Paul
------------------------------------------------------------------------
commit 172b692a79ec5801eab57cb55d2f9c398f244c62
Author: Paul E. McKenney <paulmck@kernel.org>
Date: Wed Feb 5 12:27:23 2025 -0800
printk: Flush console log from kernel_power_off()
Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
and shutdown time, which hides shutdown-time RCU issues from rcutorture.
Therefore, make pr_flush() public and invoke it after then last print
in kernel_power_off().
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: John Ogness <john.ogness@linutronix.de>
Cc: Sergey Senozhatsky <senozhatsky@chromium.org>
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 4217a9f412b2..b3e88ff1ecc3 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -806,4 +806,6 @@ static inline void print_hex_dump_debug(const char *prefix_str, int prefix_type,
#define print_hex_dump_bytes(prefix_str, prefix_type, buf, len) \
print_hex_dump_debug(prefix_str, prefix_type, 16, 1, buf, len, true)
+
+bool pr_flush(int timeout_ms, bool reset_on_progress);
#endif
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 80910bc3470c..e0c6e5a99897 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2461,7 +2461,7 @@ asmlinkage __visible int _printk(const char *fmt, ...)
}
EXPORT_SYMBOL(_printk);
-static bool pr_flush(int timeout_ms, bool reset_on_progress);
+bool pr_flush(int timeout_ms, bool reset_on_progress);
static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress);
#else /* CONFIG_PRINTK */
@@ -4466,7 +4466,7 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
* Context: Process context. May sleep while acquiring console lock.
* Return: true if all usable printers are caught up.
*/
-static bool pr_flush(int timeout_ms, bool reset_on_progress)
+bool pr_flush(int timeout_ms, bool reset_on_progress)
{
return __pr_flush(NULL, timeout_ms, reset_on_progress);
}
diff --git a/kernel/reboot.c b/kernel/reboot.c
index a701000bab34..3448e6ae3556 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -704,6 +704,7 @@ void kernel_power_off(void)
migrate_to_reboot_cpu();
syscore_shutdown();
pr_emerg("Power down\n");
+ pr_flush(500, 1);
kmsg_dump(KMSG_DUMP_SHUTDOWN);
machine_power_off();
}
^ permalink raw reply related [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 20:31 ` Paul E. McKenney
@ 2025-02-05 21:22 ` John Ogness
2025-02-05 21:55 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: John Ogness @ 2025-02-05 21:22 UTC (permalink / raw)
To: paulmck, Petr Mladek
Cc: Sebastian Andrzej Siewior, rcu, linux-kernel, kernel-team,
rostedt, Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel
On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
>> Would it make sense to put a call to pr_flush() at the beginning of the
>> kernel_power_off() function? I suspect that would take care of much
>> more than just rcutorture.
>>
>> Or maybe after the pr_emerg("Power down\n"), since that is normally
>> the last thing that shows up on rcutorture's console logs.
Yes, after the pr_emerg("Power down\n"), as in your patch below.
> And that does the trick! I specified 500ms, but maybe -1 would be
> better? You tell me! ;-)
I probably would have chosen 1000ms, but if the kthread has made no
forward progress after a few max timeslices, it probably is dead or will
not be scheduled anyway.
If there is no backlog, pr_flush() returns immediately.
I recommend _not_ using timeout_ms=-1 here, in case the kthread cannot
be scheduled (for whatever reason).
> ------------------------------------------------------------------------
>
> commit 172b692a79ec5801eab57cb55d2f9c398f244c62
> Author: Paul E. McKenney <paulmck@kernel.org>
> Date: Wed Feb 5 12:27:23 2025 -0800
>
> printk: Flush console log from kernel_power_off()
>
> Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> Therefore, make pr_flush() public and invoke it after then last print
> in kernel_power_off().
>
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> Cc: Petr Mladek <pmladek@suse.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: John Ogness <john.ogness@linutronix.de>
> Cc: Sergey Senozhatsky <senozhatsky@chromium.org>
>
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 4217a9f412b2..b3e88ff1ecc3 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -806,4 +806,6 @@ static inline void print_hex_dump_debug(const char *prefix_str, int prefix_type,
> #define print_hex_dump_bytes(prefix_str, prefix_type, buf, len) \
> print_hex_dump_debug(prefix_str, prefix_type, 16, 1, buf, len, true)
>
> +
> +bool pr_flush(int timeout_ms, bool reset_on_progress);
This will fail to link for !CONFIG_PRINTK.
In kernel/printk/printk.c currently there is:
#ifdef CONFIG_PRINTK
static bool pr_flush(int timeout_ms, bool reset_on_progress);
#else
static bool pr_flush(int timeout_ms, bool reset_on_progress) { return true; }
#endif
This would need to move to include/linux/printk.h
There you will find an existing CONFIG_PRINTK if/else block to move
those to.
> #endif
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 80910bc3470c..e0c6e5a99897 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2461,7 +2461,7 @@ asmlinkage __visible int _printk(const char *fmt, ...)
> }
> EXPORT_SYMBOL(_printk);
>
> -static bool pr_flush(int timeout_ms, bool reset_on_progress);
> +bool pr_flush(int timeout_ms, bool reset_on_progress);
> static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress);
>
> #else /* CONFIG_PRINTK */
> @@ -4466,7 +4466,7 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
> * Context: Process context. May sleep while acquiring console lock.
> * Return: true if all usable printers are caught up.
> */
> -static bool pr_flush(int timeout_ms, bool reset_on_progress)
> +bool pr_flush(int timeout_ms, bool reset_on_progress)
> {
> return __pr_flush(NULL, timeout_ms, reset_on_progress);
> }
> diff --git a/kernel/reboot.c b/kernel/reboot.c
> index a701000bab34..3448e6ae3556 100644
> --- a/kernel/reboot.c
> +++ b/kernel/reboot.c
> @@ -704,6 +704,7 @@ void kernel_power_off(void)
> migrate_to_reboot_cpu();
> syscore_shutdown();
> pr_emerg("Power down\n");
> + pr_flush(500, 1);
I would have chosen:
pr_flush(1000, true);
but I really don't have an argument either way.
> kmsg_dump(KMSG_DUMP_SHUTDOWN);
> machine_power_off();
> }
John Ogness
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 21:22 ` John Ogness
@ 2025-02-05 21:55 ` Paul E. McKenney
2025-02-05 22:20 ` John Ogness
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-05 21:55 UTC (permalink / raw)
To: John Ogness
Cc: Petr Mladek, Sebastian Andrzej Siewior, rcu, linux-kernel,
kernel-team, rostedt, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
On Wed, Feb 05, 2025 at 10:28:06PM +0106, John Ogness wrote:
> On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> >> Would it make sense to put a call to pr_flush() at the beginning of the
> >> kernel_power_off() function? I suspect that would take care of much
> >> more than just rcutorture.
> >>
> >> Or maybe after the pr_emerg("Power down\n"), since that is normally
> >> the last thing that shows up on rcutorture's console logs.
>
> Yes, after the pr_emerg("Power down\n"), as in your patch below.
>
> > And that does the trick! I specified 500ms, but maybe -1 would be
> > better? You tell me! ;-)
>
> I probably would have chosen 1000ms, but if the kthread has made no
> forward progress after a few max timeslices, it probably is dead or will
> not be scheduled anyway.
I picked 500ms randomly, so I am happy to make it be 1000ms.
> If there is no backlog, pr_flush() returns immediately.
OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
it, then?
> I recommend _not_ using timeout_ms=-1 here, in case the kthread cannot
> be scheduled (for whatever reason).
Sounds eminently reasonable to me!
> > ------------------------------------------------------------------------
> >
> > commit 172b692a79ec5801eab57cb55d2f9c398f244c62
> > Author: Paul E. McKenney <paulmck@kernel.org>
> > Date: Wed Feb 5 12:27:23 2025 -0800
> >
> > printk: Flush console log from kernel_power_off()
> >
> > Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> > and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> > Therefore, make pr_flush() public and invoke it after then last print
> > in kernel_power_off().
> >
> > Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> > Cc: Petr Mladek <pmladek@suse.com>
> > Cc: Steven Rostedt <rostedt@goodmis.org>
> > Cc: John Ogness <john.ogness@linutronix.de>
> > Cc: Sergey Senozhatsky <senozhatsky@chromium.org>
> >
> > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > index 4217a9f412b2..b3e88ff1ecc3 100644
> > --- a/include/linux/printk.h
> > +++ b/include/linux/printk.h
> > @@ -806,4 +806,6 @@ static inline void print_hex_dump_debug(const char *prefix_str, int prefix_type,
> > #define print_hex_dump_bytes(prefix_str, prefix_type, buf, len) \
> > print_hex_dump_debug(prefix_str, prefix_type, 16, 1, buf, len, true)
> >
> > +
> > +bool pr_flush(int timeout_ms, bool reset_on_progress);
>
> This will fail to link for !CONFIG_PRINTK.
>
> In kernel/printk/printk.c currently there is:
>
> #ifdef CONFIG_PRINTK
> static bool pr_flush(int timeout_ms, bool reset_on_progress);
> #else
> static bool pr_flush(int timeout_ms, bool reset_on_progress) { return true; }
> #endif
>
> This would need to move to include/linux/printk.h
>
> There you will find an existing CONFIG_PRINTK if/else block to move
> those to.
Thank you, will do!
> > #endif
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 80910bc3470c..e0c6e5a99897 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2461,7 +2461,7 @@ asmlinkage __visible int _printk(const char *fmt, ...)
> > }
> > EXPORT_SYMBOL(_printk);
> >
> > -static bool pr_flush(int timeout_ms, bool reset_on_progress);
> > +bool pr_flush(int timeout_ms, bool reset_on_progress);
> > static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress);
> >
> > #else /* CONFIG_PRINTK */
> > @@ -4466,7 +4466,7 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
> > * Context: Process context. May sleep while acquiring console lock.
> > * Return: true if all usable printers are caught up.
> > */
> > -static bool pr_flush(int timeout_ms, bool reset_on_progress)
> > +bool pr_flush(int timeout_ms, bool reset_on_progress)
> > {
> > return __pr_flush(NULL, timeout_ms, reset_on_progress);
> > }
> > diff --git a/kernel/reboot.c b/kernel/reboot.c
> > index a701000bab34..3448e6ae3556 100644
> > --- a/kernel/reboot.c
> > +++ b/kernel/reboot.c
> > @@ -704,6 +704,7 @@ void kernel_power_off(void)
> > migrate_to_reboot_cpu();
> > syscore_shutdown();
> > pr_emerg("Power down\n");
> > + pr_flush(500, 1);
>
> I would have chosen:
>
> pr_flush(1000, true);
>
> but I really don't have an argument either way.
Hey, of the two of us, you are the printk() expert, so I will make it
be 1000. ;-)
Thanx, Paul
> > kmsg_dump(KMSG_DUMP_SHUTDOWN);
> > machine_power_off();
> > }
>
> John Ogness
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 21:55 ` Paul E. McKenney
@ 2025-02-05 22:20 ` John Ogness
2025-02-05 22:31 ` John Ogness
0 siblings, 1 reply; 34+ messages in thread
From: John Ogness @ 2025-02-05 22:20 UTC (permalink / raw)
To: paulmck, Petr Mladek
Cc: Sebastian Andrzej Siewior, rcu, linux-kernel, kernel-team,
rostedt, Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel
On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
>> If there is no backlog, pr_flush() returns immediately.
>
> OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
> it, then?
For !CONFIG_PREEMPT_RT, if there are legacy consoles registered,
pr_flush() will additionally perform a blocking lock on the
console_lock. The kernel is in a clean shutdown path, so it should not
be a risk to block on the console_lock. But the console_lock is one of
the ugly global locks (semaphore, actually) we are working to remove
because sometimes it still causes problems.
@pmladek: What do you think? Should we have a CONFIG_PREEMPT_RT guard,
which would always be safe? Or do you feel comfortable performing a
console_lock() in the shutdown path for !CONFIG_PREEMPT_RT?
John
^ permalink raw reply [flat|nested] 34+ messages in thread
* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 22:20 ` John Ogness
@ 2025-02-05 22:31 ` John Ogness
2025-02-05 23:50 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: John Ogness @ 2025-02-05 22:31 UTC (permalink / raw)
To: paulmck, Petr Mladek
Cc: Sebastian Andrzej Siewior, rcu, linux-kernel, kernel-team,
rostedt, Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel
On 2025-02-05, John Ogness <john.ogness@linutronix.de> wrote:
>> OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
>> it, then?
>
> For !CONFIG_PREEMPT_RT, if there are legacy consoles registered,
> pr_flush() will additionally perform a blocking lock on the
> console_lock.
Sorry, I was just thinking about the flushing component of
pr_flush(). Later in the function it takes the console_lock even for
CONFIG_PREEMPT_RT. So please do _not_ have a guard.
pr_flush() should never hang on the console_lock during shutdown, but if
does, that is something that will need to be debugged and fixed.
@pmladek: Looking forward to reading your input on this.
John
^ permalink raw reply [flat|nested] 34+ messages in thread
* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 22:31 ` John Ogness
@ 2025-02-05 23:50 ` Paul E. McKenney
2025-02-06 8:28 ` John Ogness
` (2 more replies)
0 siblings, 3 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-05 23:50 UTC (permalink / raw)
To: John Ogness
Cc: Petr Mladek, Sebastian Andrzej Siewior, rcu, linux-kernel,
kernel-team, rostedt, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
On Wed, Feb 05, 2025 at 11:37:25PM +0106, John Ogness wrote:
> On 2025-02-05, John Ogness <john.ogness@linutronix.de> wrote:
> >> OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
> >> it, then?
> >
> > For !CONFIG_PREEMPT_RT, if there are legacy consoles registered,
> > pr_flush() will additionally perform a blocking lock on the
> > console_lock.
>
> Sorry, I was just thinking about the flushing component of
> pr_flush(). Later in the function it takes the console_lock even for
> CONFIG_PREEMPT_RT. So please do _not_ have a guard.
>
> pr_flush() should never hang on the console_lock during shutdown, but if
> does, that is something that will need to be debugged and fixed.
>
> @pmladek: Looking forward to reading your input on this.
Here is an updated commit, hopefully applying your feedback correctly.
Thanx, Paul
------------------------------------------------------------------------
commit 35679c18b062368855e183ee6712ca5c16145d8c
Author: Paul E. McKenney <paulmck@kernel.org>
Date: Wed Feb 5 12:27:23 2025 -0800
printk: Flush console log from kernel_power_off()
Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
and shutdown time, which hides shutdown-time RCU issues from rcutorture.
Therefore, make pr_flush() public and invoke it after then last print
in kernel_power_off().
[ paulmck: Apply John Ogness feedback. ]
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: John Ogness <john.ogness@linutronix.de>
Cc: Sergey Senozhatsky <senozhatsky@chromium.org>
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 4217a9f412b2..d658d7e81bef 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
extern bool nbcon_device_try_acquire(struct console *con);
extern void nbcon_device_release(struct console *con);
void nbcon_atomic_flush_unsafe(void);
+bool pr_flush(int timeout_ms, bool reset_on_progress);
#else
static inline __printf(1, 0)
int vprintk(const char *s, va_list args)
@@ -315,6 +316,11 @@ static inline void nbcon_atomic_flush_unsafe(void)
{
}
+static bool pr_flush(int timeout_ms, bool reset_on_progress)
+{
+ return true;
+}
+
#endif
bool this_cpu_in_panic(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 80910bc3470c..b9699eaacf19 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2461,7 +2461,6 @@ asmlinkage __visible int _printk(const char *fmt, ...)
}
EXPORT_SYMBOL(_printk);
-static bool pr_flush(int timeout_ms, bool reset_on_progress);
static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress);
#else /* CONFIG_PRINTK */
@@ -2474,7 +2473,6 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
static u64 syslog_seq;
-static bool pr_flush(int timeout_ms, bool reset_on_progress) { return true; }
static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress) { return true; }
#endif /* CONFIG_PRINTK */
@@ -4466,7 +4464,7 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
* Context: Process context. May sleep while acquiring console lock.
* Return: true if all usable printers are caught up.
*/
-static bool pr_flush(int timeout_ms, bool reset_on_progress)
+bool pr_flush(int timeout_ms, bool reset_on_progress)
{
return __pr_flush(NULL, timeout_ms, reset_on_progress);
}
diff --git a/kernel/reboot.c b/kernel/reboot.c
index a701000bab34..a84828d0757b 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -704,6 +704,7 @@ void kernel_power_off(void)
migrate_to_reboot_cpu();
syscore_shutdown();
pr_emerg("Power down\n");
+ pr_flush(1000, 1);
kmsg_dump(KMSG_DUMP_SHUTDOWN);
machine_power_off();
}
^ permalink raw reply related [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 23:50 ` Paul E. McKenney
@ 2025-02-06 8:28 ` John Ogness
2025-02-06 9:58 ` Paul E. McKenney
2025-02-06 9:02 ` Sebastian Andrzej Siewior
2025-02-06 11:06 ` Petr Mladek
2 siblings, 1 reply; 34+ messages in thread
From: John Ogness @ 2025-02-06 8:28 UTC (permalink / raw)
To: paulmck
Cc: Petr Mladek, Sebastian Andrzej Siewior, rcu, linux-kernel,
kernel-team, rostedt, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> commit 35679c18b062368855e183ee6712ca5c16145d8c
> Author: Paul E. McKenney <paulmck@kernel.org>
> Date: Wed Feb 5 12:27:23 2025 -0800
>
> printk: Flush console log from kernel_power_off()
>
> Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> Therefore, make pr_flush() public and invoke it after then last print
> in kernel_power_off().
>
> [ paulmck: Apply John Ogness feedback. ]
>
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Reviewed-by: John Ogness <john.ogness@linutronix.de>
^ permalink raw reply [flat|nested] 34+ messages in thread
* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-06 8:28 ` John Ogness
@ 2025-02-06 9:58 ` Paul E. McKenney
0 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-06 9:58 UTC (permalink / raw)
To: John Ogness
Cc: Petr Mladek, Sebastian Andrzej Siewior, rcu, linux-kernel,
kernel-team, rostedt, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
On Thu, Feb 06, 2025 at 09:34:01AM +0106, John Ogness wrote:
> On 2025-02-05, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > commit 35679c18b062368855e183ee6712ca5c16145d8c
> > Author: Paul E. McKenney <paulmck@kernel.org>
> > Date: Wed Feb 5 12:27:23 2025 -0800
> >
> > printk: Flush console log from kernel_power_off()
> >
> > Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> > and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> > Therefore, make pr_flush() public and invoke it after then last print
> > in kernel_power_off().
> >
> > [ paulmck: Apply John Ogness feedback. ]
> >
> > Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
>
> Reviewed-by: John Ogness <john.ogness@linutronix.de>
Thank you! I will apply this on my next rebase.
Thanx, Paul
^ permalink raw reply [flat|nested] 34+ messages in thread
* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 23:50 ` Paul E. McKenney
2025-02-06 8:28 ` John Ogness
@ 2025-02-06 9:02 ` Sebastian Andrzej Siewior
2025-02-06 9:59 ` Paul E. McKenney
2025-02-06 11:06 ` Petr Mladek
2 siblings, 1 reply; 34+ messages in thread
From: Sebastian Andrzej Siewior @ 2025-02-06 9:02 UTC (permalink / raw)
To: Paul E. McKenney
Cc: John Ogness, Petr Mladek, rcu, linux-kernel, kernel-team, rostedt,
Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel
On 2025-02-05 15:50:14 [-0800], Paul E. McKenney wrote:
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 4217a9f412b2..d658d7e81bef 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
> extern bool nbcon_device_try_acquire(struct console *con);
> extern void nbcon_device_release(struct console *con);
> void nbcon_atomic_flush_unsafe(void);
> +bool pr_flush(int timeout_ms, bool reset_on_progress);
…
> diff --git a/kernel/reboot.c b/kernel/reboot.c
> index a701000bab34..a84828d0757b 100644
> --- a/kernel/reboot.c
> +++ b/kernel/reboot.c
> @@ -704,6 +704,7 @@ void kernel_power_off(void)
> migrate_to_reboot_cpu();
> syscore_shutdown();
> pr_emerg("Power down\n");
> + pr_flush(1000, 1);
this could be true instead 1 given that the type is bool
> kmsg_dump(KMSG_DUMP_SHUTDOWN);
> machine_power_off();
> }
Sebastian
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-06 9:02 ` Sebastian Andrzej Siewior
@ 2025-02-06 9:59 ` Paul E. McKenney
2025-02-06 10:18 ` Paul E. McKenney
0 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-06 9:59 UTC (permalink / raw)
To: Sebastian Andrzej Siewior
Cc: John Ogness, Petr Mladek, rcu, linux-kernel, kernel-team, rostedt,
Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel
On Thu, Feb 06, 2025 at 10:02:49AM +0100, Sebastian Andrzej Siewior wrote:
> On 2025-02-05 15:50:14 [-0800], Paul E. McKenney wrote:
> > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > index 4217a9f412b2..d658d7e81bef 100644
> > --- a/include/linux/printk.h
> > +++ b/include/linux/printk.h
> > @@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
> > extern bool nbcon_device_try_acquire(struct console *con);
> > extern void nbcon_device_release(struct console *con);
> > void nbcon_atomic_flush_unsafe(void);
> > +bool pr_flush(int timeout_ms, bool reset_on_progress);
> …
> > diff --git a/kernel/reboot.c b/kernel/reboot.c
> > index a701000bab34..a84828d0757b 100644
> > --- a/kernel/reboot.c
> > +++ b/kernel/reboot.c
> > @@ -704,6 +704,7 @@ void kernel_power_off(void)
> > migrate_to_reboot_cpu();
> > syscore_shutdown();
> > pr_emerg("Power down\n");
> > + pr_flush(1000, 1);
>
> this could be true instead 1 given that the type is bool
Good point, and this matches other usage. Will fix on my next rebase.
Thanx, Paul
> > kmsg_dump(KMSG_DUMP_SHUTDOWN);
> > machine_power_off();
> > }
>
> Sebastian
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-06 9:59 ` Paul E. McKenney
@ 2025-02-06 10:18 ` Paul E. McKenney
0 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-06 10:18 UTC (permalink / raw)
To: Sebastian Andrzej Siewior
Cc: John Ogness, Petr Mladek, rcu, linux-kernel, kernel-team, rostedt,
Frederic Weisbecker, Thomas Gleixner, Alexei Starovoitov,
Andrii Nakryiko, Mathieu Desnoyers, Masami Hiramatsu,
linux-trace-kernel
On Thu, Feb 06, 2025 at 01:59:00AM -0800, Paul E. McKenney wrote:
> On Thu, Feb 06, 2025 at 10:02:49AM +0100, Sebastian Andrzej Siewior wrote:
> > On 2025-02-05 15:50:14 [-0800], Paul E. McKenney wrote:
> > > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > > index 4217a9f412b2..d658d7e81bef 100644
> > > --- a/include/linux/printk.h
> > > +++ b/include/linux/printk.h
> > > @@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
> > > extern bool nbcon_device_try_acquire(struct console *con);
> > > extern void nbcon_device_release(struct console *con);
> > > void nbcon_atomic_flush_unsafe(void);
> > > +bool pr_flush(int timeout_ms, bool reset_on_progress);
> > …
> > > diff --git a/kernel/reboot.c b/kernel/reboot.c
> > > index a701000bab34..a84828d0757b 100644
> > > --- a/kernel/reboot.c
> > > +++ b/kernel/reboot.c
> > > @@ -704,6 +704,7 @@ void kernel_power_off(void)
> > > migrate_to_reboot_cpu();
> > > syscore_shutdown();
> > > pr_emerg("Power down\n");
> > > + pr_flush(1000, 1);
> >
> > this could be true instead 1 given that the type is bool
>
> Good point, and this matches other usage. Will fix on my next rebase.
And here is the updated commit. Thoughts?
Thanx, Paul
------------------------------------------------------------------------
commit 04ccc09a6eb9a50f79c0a0e46fd273b5131b24f1
Author: Paul E. McKenney <paulmck@kernel.org>
Date: Wed Feb 5 12:27:23 2025 -0800
printk: Flush console log from kernel_power_off()
Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
and shutdown time, which hides shutdown-time RCU issues from rcutorture.
Therefore, make pr_flush() public and invoke it after then last print
in kernel_power_off().
[ paulmck: Apply John Ogness feedback. ]
[ paulmck: Appy Sebastian Andrzej Siewior feedback. ]
[ paulmck: Apply kernel test robot feedback. ]
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Reviewed-by: John Ogness <john.ogness@linutronix.de>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Sergey Senozhatsky <senozhatsky@chromium.org>
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 4217a9f412b2..5b462029d03c 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
extern bool nbcon_device_try_acquire(struct console *con);
extern void nbcon_device_release(struct console *con);
void nbcon_atomic_flush_unsafe(void);
+bool pr_flush(int timeout_ms, bool reset_on_progress);
#else
static inline __printf(1, 0)
int vprintk(const char *s, va_list args)
@@ -315,6 +316,11 @@ static inline void nbcon_atomic_flush_unsafe(void)
{
}
+static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
+{
+ return true;
+}
+
#endif
bool this_cpu_in_panic(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 80910bc3470c..b9699eaacf19 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2461,7 +2461,6 @@ asmlinkage __visible int _printk(const char *fmt, ...)
}
EXPORT_SYMBOL(_printk);
-static bool pr_flush(int timeout_ms, bool reset_on_progress);
static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress);
#else /* CONFIG_PRINTK */
@@ -2474,7 +2473,6 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
static u64 syslog_seq;
-static bool pr_flush(int timeout_ms, bool reset_on_progress) { return true; }
static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress) { return true; }
#endif /* CONFIG_PRINTK */
@@ -4466,7 +4464,7 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
* Context: Process context. May sleep while acquiring console lock.
* Return: true if all usable printers are caught up.
*/
-static bool pr_flush(int timeout_ms, bool reset_on_progress)
+bool pr_flush(int timeout_ms, bool reset_on_progress)
{
return __pr_flush(NULL, timeout_ms, reset_on_progress);
}
diff --git a/kernel/reboot.c b/kernel/reboot.c
index a701000bab34..3ba15b2c4066 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -704,6 +704,7 @@ void kernel_power_off(void)
migrate_to_reboot_cpu();
syscore_shutdown();
pr_emerg("Power down\n");
+ pr_flush(1000, true);
kmsg_dump(KMSG_DUMP_SHUTDOWN);
machine_power_off();
}
^ permalink raw reply related [flat|nested] 34+ messages in thread
* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-05 23:50 ` Paul E. McKenney
2025-02-06 8:28 ` John Ogness
2025-02-06 9:02 ` Sebastian Andrzej Siewior
@ 2025-02-06 11:06 ` Petr Mladek
2025-02-06 16:32 ` Paul E. McKenney
2 siblings, 1 reply; 34+ messages in thread
From: Petr Mladek @ 2025-02-06 11:06 UTC (permalink / raw)
To: Paul E. McKenney
Cc: John Ogness, Sebastian Andrzej Siewior, rcu, linux-kernel,
kernel-team, rostedt, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
On Wed 2025-02-05 15:50:14, Paul E. McKenney wrote:
> On Wed, Feb 05, 2025 at 11:37:25PM +0106, John Ogness wrote:
> > On 2025-02-05, John Ogness <john.ogness@linutronix.de> wrote:
> > >> OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
> > >> it, then?
> > >
> > > For !CONFIG_PREEMPT_RT, if there are legacy consoles registered,
> > > pr_flush() will additionally perform a blocking lock on the
> > > console_lock.
> >
> > Sorry, I was just thinking about the flushing component of
> > pr_flush(). Later in the function it takes the console_lock even for
> > CONFIG_PREEMPT_RT. So please do _not_ have a guard.
It should be possible to avoid this console_lock() when only NBCON
consoles are registered. We take it in pr_flush() for reading con->seq
and potential race with register_console(). But it can be handled
another way, for example, by restarting the cycle when non-NBCON
console suddenly appears.
But it might be done later. We do not have NBCON consoles at the
moment so the console_lock() is needed anyway.
> > pr_flush() should never hang on the console_lock during shutdown, but if
> > does, that is something that will need to be debugged and fixed.
> >
> > @pmladek: Looking forward to reading your input on this.
My only concern is that kernel_power_off() is called in many
code paths so it is not easy to review all scenarios.
But I haven't found any code path where it would be an obvious problem.
Especially, it seems that it is _not_ called in panic situations.
Also kernel_power_off() calls syscore_shutdown() which takes
syscore_ops_lock mutex. So that is must be called only in
a schedulable context even before this patch.
Summary: I do not see any obvious problem in the end.
Except, for some small details, see below.
> Here is an updated commit, hopefully applying your feedback correctly.
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> commit 35679c18b062368855e183ee6712ca5c16145d8c
> Author: Paul E. McKenney <paulmck@kernel.org>
> Date: Wed Feb 5 12:27:23 2025 -0800
>
> printk: Flush console log from kernel_power_off()
>
> Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> Therefore, make pr_flush() public and invoke it after then last print
> in kernel_power_off().
>
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
> extern bool nbcon_device_try_acquire(struct console *con);
> extern void nbcon_device_release(struct console *con);
> void nbcon_atomic_flush_unsafe(void);
> +bool pr_flush(int timeout_ms, bool reset_on_progress);
> #else
> static inline __printf(1, 0)
> int vprintk(const char *s, va_list args)
> @@ -315,6 +316,11 @@ static inline void nbcon_atomic_flush_unsafe(void)
> {
> }
>
> +static bool pr_flush(int timeout_ms, bool reset_on_progress)
There is missing "inline":
static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
Otherwise, I get
In file included from ./include/asm-generic/bug.h:22,
from ./arch/x86/include/asm/bug.h:99,
from ./include/linux/bug.h:5,
from ./include/linux/page-flags.h:10,
from kernel/bounds.c:10:
./include/linux/printk.h:319:13: warning: ‘pr_flush’ defined but not used [-Wunused-function]
> +{
> + return true;
> +}
> +
> #endif
>
> bool this_cpu_in_panic(void);
> --- a/kernel/reboot.c
> +++ b/kernel/reboot.c
> @@ -704,6 +704,7 @@ void kernel_power_off(void)
> migrate_to_reboot_cpu();
> syscore_shutdown();
> pr_emerg("Power down\n");
> + pr_flush(1000, 1);
This should be pr_flush(1000, true) as suggested by Sebastian.
> kmsg_dump(KMSG_DUMP_SHUTDOWN);
> machine_power_off();
> }
With the two changes:
Reviewed-by: Petr Mladek <pmladek@suse.com>
Paul, I assume that you will pass this via the RCU tree together with
the other changes. Or would you prefer to route this particular
change via printk tree? Both ways are fine to me.
Best Regards,
Petr
^ permalink raw reply [flat|nested] 34+ messages in thread* Re: [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall()
2025-02-06 11:06 ` Petr Mladek
@ 2025-02-06 16:32 ` Paul E. McKenney
0 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-06 16:32 UTC (permalink / raw)
To: Petr Mladek
Cc: John Ogness, Sebastian Andrzej Siewior, rcu, linux-kernel,
kernel-team, rostedt, Frederic Weisbecker, Thomas Gleixner,
Alexei Starovoitov, Andrii Nakryiko, Mathieu Desnoyers,
Masami Hiramatsu, linux-trace-kernel
On Thu, Feb 06, 2025 at 12:06:08PM +0100, Petr Mladek wrote:
> On Wed 2025-02-05 15:50:14, Paul E. McKenney wrote:
> > On Wed, Feb 05, 2025 at 11:37:25PM +0106, John Ogness wrote:
> > > On 2025-02-05, John Ogness <john.ogness@linutronix.de> wrote:
> > > >> OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
> > > >> it, then?
> > > >
> > > > For !CONFIG_PREEMPT_RT, if there are legacy consoles registered,
> > > > pr_flush() will additionally perform a blocking lock on the
> > > > console_lock.
> > >
> > > Sorry, I was just thinking about the flushing component of
> > > pr_flush(). Later in the function it takes the console_lock even for
> > > CONFIG_PREEMPT_RT. So please do _not_ have a guard.
Thank you all for looking this over!
> It should be possible to avoid this console_lock() when only NBCON
> consoles are registered. We take it in pr_flush() for reading con->seq
> and potential race with register_console(). But it can be handled
> another way, for example, by restarting the cycle when non-NBCON
> console suddenly appears.
>
> But it might be done later. We do not have NBCON consoles at the
> moment so the console_lock() is needed anyway.
Fair enough.
> > > pr_flush() should never hang on the console_lock during shutdown, but if
> > > does, that is something that will need to be debugged and fixed.
> > >
> > > @pmladek: Looking forward to reading your input on this.
>
> My only concern is that kernel_power_off() is called in many
> code paths so it is not easy to review all scenarios.
>
> But I haven't found any code path where it would be an obvious problem.
> Especially, it seems that it is _not_ called in panic situations.
>
> Also kernel_power_off() calls syscore_shutdown() which takes
> syscore_ops_lock mutex. So that is must be called only in
> a schedulable context even before this patch.
>
> Summary: I do not see any obvious problem in the end.
> Except, for some small details, see below.
The presence of that syscore_shutdown() call greatly reduced my level
of anxiety as well. ;-)
> > Here is an updated commit, hopefully applying your feedback correctly.
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > commit 35679c18b062368855e183ee6712ca5c16145d8c
> > Author: Paul E. McKenney <paulmck@kernel.org>
> > Date: Wed Feb 5 12:27:23 2025 -0800
> >
> > printk: Flush console log from kernel_power_off()
> >
> > Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> > and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> > Therefore, make pr_flush() public and invoke it after then last print
> > in kernel_power_off().
> >
> > --- a/include/linux/printk.h
> > +++ b/include/linux/printk.h
> > @@ -207,6 +207,7 @@ void printk_legacy_allow_panic_sync(void);
> > extern bool nbcon_device_try_acquire(struct console *con);
> > extern void nbcon_device_release(struct console *con);
> > void nbcon_atomic_flush_unsafe(void);
> > +bool pr_flush(int timeout_ms, bool reset_on_progress);
> > #else
> > static inline __printf(1, 0)
> > int vprintk(const char *s, va_list args)
> > @@ -315,6 +316,11 @@ static inline void nbcon_atomic_flush_unsafe(void)
> > {
> > }
> >
> > +static bool pr_flush(int timeout_ms, bool reset_on_progress)
>
> There is missing "inline":
>
> static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
>
>
> Otherwise, I get
>
> In file included from ./include/asm-generic/bug.h:22,
> from ./arch/x86/include/asm/bug.h:99,
> from ./include/linux/bug.h:5,
> from ./include/linux/page-flags.h:10,
> from kernel/bounds.c:10:
> ./include/linux/printk.h:319:13: warning: ‘pr_flush’ defined but not used [-Wunused-function]
Fixed, thank you both!
> > +{
> > + return true;
> > +}
> > +
> > #endif
> >
> > bool this_cpu_in_panic(void);
> > --- a/kernel/reboot.c
> > +++ b/kernel/reboot.c
> > @@ -704,6 +704,7 @@ void kernel_power_off(void)
> > migrate_to_reboot_cpu();
> > syscore_shutdown();
> > pr_emerg("Power down\n");
> > + pr_flush(1000, 1);
>
> This should be pr_flush(1000, true) as suggested by Sebastian.
Also fixed, also thank you both!
> > kmsg_dump(KMSG_DUMP_SHUTDOWN);
> > machine_power_off();
> > }
>
> With the two changes:
>
> Reviewed-by: Petr Mladek <pmladek@suse.com>
>
> Paul, I assume that you will pass this via the RCU tree together with
> the other changes. Or would you prefer to route this particular
> change via printk tree? Both ways are fine to me.
One advantage of carrying it via RCU is that I can arrange things so that
rcutorture users don't see this problem. So unless a problem arises,
thank you, and I do plan to send this up via RCU.
Thanx, Paul
^ permalink raw reply [flat|nested] 34+ messages in thread
* [PATCH rcu v2] 5/5] rcu/nocb: Print segment lengths in show_rcu_nocb_gp_state()
2025-01-30 18:53 ` [PATCH rcu 0/5] Miscellaneous fixes Paul E. McKenney
` (3 preceding siblings ...)
2025-01-30 18:53 ` [PATCH rcu v2] 4/5] rcu-tasks: Move RCU Tasks self-tests to core_initcall() Paul E. McKenney
@ 2025-01-30 18:53 ` Paul E. McKenney
2025-02-06 10:15 ` [PATCH rcu 6/5] Make RCU watch ct_kernel_exit_state() warning Paul E. McKenney
5 siblings, 0 replies; 34+ messages in thread
From: Paul E. McKenney @ 2025-01-30 18:53 UTC (permalink / raw)
To: rcu; +Cc: linux-kernel, kernel-team, rostedt, Paul E. McKenney
Analysis of an rcutorture callback-based forward-progress test failure was
hampered by the lack of ->cblist segment lengths. This commit therefore
adds this information, so that what would have been ".W85620.N." (there
are some callbacks waiting for grace period sequence number 85620 and
some number more that have not yet been assigned to a grace period)
now prints as ".W2(85620).N6." (there are 2 callbacks waiting for grace
period 85620 and 6 not yet assigned to a grace period). Note that
"D" (done), "N" (next and not yet assigned to a grace period, and "B"
(bypass, also not yet assigned to a grace period) have just the number
of callbacks without the parenthesized grace-period sequence number.
In contrast, "W" (waiting for the current grace period) and "R" (ready
to wait for the next grace period to start) both have parenthesized
grace-period sequence numbers.
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
---
kernel/rcu/tree_nocb.h | 20 +++++++++++++++-----
1 file changed, 15 insertions(+), 5 deletions(-)
diff --git a/kernel/rcu/tree_nocb.h b/kernel/rcu/tree_nocb.h
index 2605dd234a13..5ff3bc56ff51 100644
--- a/kernel/rcu/tree_nocb.h
+++ b/kernel/rcu/tree_nocb.h
@@ -1557,8 +1557,11 @@ static void show_rcu_nocb_gp_state(struct rcu_data *rdp)
/* Dump out nocb kthread state for the specified rcu_data structure. */
static void show_rcu_nocb_state(struct rcu_data *rdp)
{
- char bufw[20];
- char bufr[20];
+ char bufd[22];
+ char bufw[45];
+ char bufr[45];
+ char bufn[22];
+ char bufb[22];
struct rcu_data *nocb_next_rdp;
struct rcu_segcblist *rsclp = &rdp->cblist;
bool waslocked;
@@ -1572,9 +1575,13 @@ static void show_rcu_nocb_state(struct rcu_data *rdp)
typeof(*rdp),
nocb_entry_rdp);
- sprintf(bufw, "%ld", rsclp->gp_seq[RCU_WAIT_TAIL]);
- sprintf(bufr, "%ld", rsclp->gp_seq[RCU_NEXT_READY_TAIL]);
- pr_info(" CB %d^%d->%d %c%c%c%c%c F%ld L%ld C%d %c%c%s%c%s%c%c q%ld %c CPU %d%s\n",
+ sprintf(bufd, "%ld", rsclp->seglen[RCU_DONE_TAIL]);
+ sprintf(bufw, "%ld(%ld)", rsclp->seglen[RCU_WAIT_TAIL], rsclp->gp_seq[RCU_WAIT_TAIL]);
+ sprintf(bufr, "%ld(%ld)", rsclp->seglen[RCU_NEXT_READY_TAIL],
+ rsclp->gp_seq[RCU_NEXT_READY_TAIL]);
+ sprintf(bufn, "%ld", rsclp->seglen[RCU_NEXT_TAIL]);
+ sprintf(bufb, "%ld", rcu_cblist_n_cbs(&rdp->nocb_bypass));
+ pr_info(" CB %d^%d->%d %c%c%c%c%c F%ld L%ld C%d %c%s%c%s%c%s%c%s%c%s q%ld %c CPU %d%s\n",
rdp->cpu, rdp->nocb_gp_rdp->cpu,
nocb_next_rdp ? nocb_next_rdp->cpu : -1,
"kK"[!!rdp->nocb_cb_kthread],
@@ -1586,12 +1593,15 @@ static void show_rcu_nocb_state(struct rcu_data *rdp)
jiffies - rdp->nocb_nobypass_last,
rdp->nocb_nobypass_count,
".D"[rcu_segcblist_ready_cbs(rsclp)],
+ rcu_segcblist_segempty(rsclp, RCU_DONE_TAIL) ? "" : bufd,
".W"[!rcu_segcblist_segempty(rsclp, RCU_WAIT_TAIL)],
rcu_segcblist_segempty(rsclp, RCU_WAIT_TAIL) ? "" : bufw,
".R"[!rcu_segcblist_segempty(rsclp, RCU_NEXT_READY_TAIL)],
rcu_segcblist_segempty(rsclp, RCU_NEXT_READY_TAIL) ? "" : bufr,
".N"[!rcu_segcblist_segempty(rsclp, RCU_NEXT_TAIL)],
+ rcu_segcblist_segempty(rsclp, RCU_NEXT_TAIL) ? "" : bufn,
".B"[!!rcu_cblist_n_cbs(&rdp->nocb_bypass)],
+ !rcu_cblist_n_cbs(&rdp->nocb_bypass) ? "" : bufb,
rcu_segcblist_n_cbs(&rdp->cblist),
rdp->nocb_cb_kthread ? task_state_to_char(rdp->nocb_cb_kthread) : '.',
rdp->nocb_cb_kthread ? (int)task_cpu(rdp->nocb_cb_kthread) : -1,
--
2.40.1
^ permalink raw reply related [flat|nested] 34+ messages in thread* [PATCH rcu 6/5] Make RCU watch ct_kernel_exit_state() warning
2025-01-30 18:53 ` [PATCH rcu 0/5] Miscellaneous fixes Paul E. McKenney
` (4 preceding siblings ...)
2025-01-30 18:53 ` [PATCH rcu v2] 5/5] rcu/nocb: Print segment lengths in show_rcu_nocb_gp_state() Paul E. McKenney
@ 2025-02-06 10:15 ` Paul E. McKenney
2025-02-06 17:38 ` Boqun Feng
5 siblings, 1 reply; 34+ messages in thread
From: Paul E. McKenney @ 2025-02-06 10:15 UTC (permalink / raw)
To: rcu
Cc: linux-kernel, kernel-team, rostedt, leitao, vschneid, frederic,
boqun.feng
The WARN_ON_ONCE() in ct_kernel_exit_state() follows the call to
ct_state_inc(), which means that RCU is not watching this WARN_ON_ONCE().
This can (and does) result in extraneous lockdep warnings when this
WARN_ON_ONCE() triggers. These extraneous warnings are the opposite
of helpful.
Therefore, invert the WARN_ON_ONCE() condition and move it before the
call to ct_state_inc(). This does mean that the ct_state_inc() return
value can no longer be used in the WARN_ON_ONCE() condition, so discard
this return value and instead use a call to rcu_is_watching_curr_cpu().
This call is executed only in CONFIG_RCU_EQS_DEBUG=y kernels, so there
is no added overhead in production use.
Reported-by: Breno Leitao <leitao@debian.org>
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Reviewed-by: Valentin Schneider <vschneid@redhat.com>
Reviewed-by: Frederic Weisbecker <frederic@kernel.org>
diff --git a/kernel/context_tracking.c b/kernel/context_tracking.c
index 938c48952d26..fb5be6e9b423 100644
--- a/kernel/context_tracking.c
+++ b/kernel/context_tracking.c
@@ -80,17 +80,16 @@ static __always_inline void rcu_task_trace_heavyweight_exit(void)
*/
static noinstr void ct_kernel_exit_state(int offset)
{
- int seq;
-
/*
* CPUs seeing atomic_add_return() must see prior RCU read-side
* critical sections, and we also must force ordering with the
* next idle sojourn.
*/
rcu_task_trace_heavyweight_enter(); // Before CT state update!
- seq = ct_state_inc(offset);
- // RCU is no longer watching. Better be in extended quiescent state!
- WARN_ON_ONCE(IS_ENABLED(CONFIG_RCU_EQS_DEBUG) && (seq & CT_RCU_WATCHING));
+ // RCU is still watching. Better not be in extended quiescent state!
+ WARN_ON_ONCE(IS_ENABLED(CONFIG_RCU_EQS_DEBUG) && !rcu_is_watching_curr_cpu());
+ (void)ct_state_inc(offset);
+ // RCU is no longer watching.
}
/*
^ permalink raw reply related [flat|nested] 34+ messages in thread* Re: [PATCH rcu 6/5] Make RCU watch ct_kernel_exit_state() warning
2025-02-06 10:15 ` [PATCH rcu 6/5] Make RCU watch ct_kernel_exit_state() warning Paul E. McKenney
@ 2025-02-06 17:38 ` Boqun Feng
0 siblings, 0 replies; 34+ messages in thread
From: Boqun Feng @ 2025-02-06 17:38 UTC (permalink / raw)
To: Paul E. McKenney
Cc: rcu, linux-kernel, kernel-team, rostedt, leitao, vschneid,
frederic
On Thu, Feb 06, 2025 at 02:15:09AM -0800, Paul E. McKenney wrote:
> The WARN_ON_ONCE() in ct_kernel_exit_state() follows the call to
> ct_state_inc(), which means that RCU is not watching this WARN_ON_ONCE().
> This can (and does) result in extraneous lockdep warnings when this
> WARN_ON_ONCE() triggers. These extraneous warnings are the opposite
> of helpful.
>
> Therefore, invert the WARN_ON_ONCE() condition and move it before the
> call to ct_state_inc(). This does mean that the ct_state_inc() return
> value can no longer be used in the WARN_ON_ONCE() condition, so discard
> this return value and instead use a call to rcu_is_watching_curr_cpu().
> This call is executed only in CONFIG_RCU_EQS_DEBUG=y kernels, so there
> is no added overhead in production use.
>
> Reported-by: Breno Leitao <leitao@debian.org>
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> Reviewed-by: Valentin Schneider <vschneid@redhat.com>
> Reviewed-by: Frederic Weisbecker <frederic@kernel.org>
>
Queued at:
git://git.kernel.org/pub/scm/linux/kernel/git/rcu/linux.git misc.2025.02.06a
I added the "context_tracking:" tag to the title while I'm at it.
Regards,
Boqun
> diff --git a/kernel/context_tracking.c b/kernel/context_tracking.c
> index 938c48952d26..fb5be6e9b423 100644
> --- a/kernel/context_tracking.c
> +++ b/kernel/context_tracking.c
> @@ -80,17 +80,16 @@ static __always_inline void rcu_task_trace_heavyweight_exit(void)
> */
> static noinstr void ct_kernel_exit_state(int offset)
> {
> - int seq;
> -
> /*
> * CPUs seeing atomic_add_return() must see prior RCU read-side
> * critical sections, and we also must force ordering with the
> * next idle sojourn.
> */
> rcu_task_trace_heavyweight_enter(); // Before CT state update!
> - seq = ct_state_inc(offset);
> - // RCU is no longer watching. Better be in extended quiescent state!
> - WARN_ON_ONCE(IS_ENABLED(CONFIG_RCU_EQS_DEBUG) && (seq & CT_RCU_WATCHING));
> + // RCU is still watching. Better not be in extended quiescent state!
> + WARN_ON_ONCE(IS_ENABLED(CONFIG_RCU_EQS_DEBUG) && !rcu_is_watching_curr_cpu());
> + (void)ct_state_inc(offset);
> + // RCU is no longer watching.
> }
>
> /*
>
^ permalink raw reply [flat|nested] 34+ messages in thread