This is v2 of a series to implement a kthread for each registered
console. v1 is here [0]. The kthreads locklessly retrieve the
records from the printk ringbuffer and also do not cause any lock
contention between each other. This allows consoles to run at full
speed. For example, a netconsole is able to dump records much
faster than a serial or vt console. Also, during normal operation,
it completely decouples printk() callers from console printing.
There are situations where kthread printing is not sufficient. For
example, during panic situations, where the kthreads may not get a
chance to schedule. In such cases, the current method of attempting
to print directly within the printk() caller context is used. New
functions printk_prefer_direct_enter() and
printk_prefer_direct_exit() are made available to mark areas of the
kernel where direct printing is preferred. (These should only be
areas that do not occur during normal operation.)
This series also introduces pr_flush(): a might_sleep() function
that will block until all active printing threads have caught up
to the latest record at the time of the pr_flush() call. This
function is useful, for example, to wait until pending records
are flushed to consoles before suspending.
Note that this series does *not* increase the reliability of console
printing. Rather it focuses on the non-interference aspect of
printk() by decoupling printk() callers from printing (during normal
operation). Nonetheless, the reliability aspect should not worsen
due to this series.
Changes since v1:
- Rename nearly all new variables, functions, macros, and flags:
variables:
@console_lock_count --> @console_kthreads_active
@consoles_paused --> @console_kthreads_blocked
@kthreads_started --> @printk_kthreads_available
@printk_direct --> @printk_prefer_direct
functions/macros:
console_excl_trylock() --> console_kthreads_atomic_tryblock()
console_excl_unlock() --> console_kthreads_atomic_unblock()
console_printer_tryenter() --> console_kthread_printing_tryenter()
console_printer_exit() --> console_kthread_printing_exit()
pause_all_consoles() --> console_kthreads_block()
unpause_all_consoles() --> console_kthreads_unblock()
printk_direct_enter() --> printk_prefer_direct_enter()
printk_direct_exit() --> printk_prefer_direct_exit()
start_printk_kthread() --> printk_start_kthread()
console flags:
CON_PAUSED --> CON_THD_BLOCKED
- Drop the patch to avoid VT printing if in an atomic context. (This
can only be done after the Linux BSoD feature is implemented.)
- Keep printk_delay() in the printk() context. (We may want to move
this into printer contexts later.)
- Keep console_trylock() usage to reacquire the console lock in
console_unlock().
- Keep cpu_online(raw_smp_processor_id()) in the check if a console
is usable and remove the printk_percpu_data_ready() check (percpu
data is always ready for consoles).
- Start console printer threads as an early_initcall. This means
threads are active before multiple CPUs come online.
- Remove "system_state < SYSTEM_RUNNING" as a reason to allow direct
printing. @kthreads_started is used for the early boot decision.
- Add console_kthreads_atomically_blocked() macro.
- Add printk_console_msg() macro to printk messages with console
details. The macro allows print indexing.
- Add __pr_flush() to allow waiting for only a single console.
- Add a full memory barrier in wake_up_klogd() to ensure new records
are visible before checking if the waitqueue is empty.
- Wake kthreads when exiting preferred direct mode.
- Wake kthreads when a CPU comes online.
- In unregister_console(), stop the printer thread before acquiring
the console lock.
- Print "thread started" message after all allocations successful.
- Permanently enable preferred direct printing if there are any
errors setting up any of the threaded console printers.
- Keep threaded printers asleep if there is no con->write()
callback.
- Keep threaded printers asleep if preferred direct printing is
active.
- Always allow handovers if the console is locked.
- Only stop irqsoff tracing if handovers are allowed.
- console_emit_next_record() is for when the console is not locked,
console_emit_next_record_transferable() is for when the console is
locked.
- Wait for console printers to catch up after unblanking the screen.
- In console_stop(), only wait for the stopping console.
- In console_start(), only wait for the starting console.
- Print only 1 record per wait cycle to increase chances of direct
printing taking over.
- Repurpose the irqwork flag PRINTK_PENDING_OUTPUT for direct
printing.
- Add caution notice and tips to description of
printk_cpu_sync_get_irqsave() on how to use it correctly.
- Improve the comments explaining why preemption is disabled during
direct printing.
- Improve commit message to explain the motivation for expanding the
console lock and how it works.
John Ogness
[0] https://lore.kernel.org/all/[email protected]
John Ogness (12):
printk: rename cpulock functions
printk: cpu sync always disable interrupts
printk: get caller_id/timestamp after migration disable
printk: call boot_delay_msec() in printk_delay()
printk: add macro for console detail messages
printk: refactor and rework printing logic
printk: move buffer definitions into console_emit_next_record() caller
printk: add pr_flush()
printk: add functions to prefer direct printing
printk: add kthread console printers
printk: extend console_lock for proper kthread support
printk: remove @console_locked
drivers/tty/sysrq.c | 2 +
include/linux/console.h | 19 +
include/linux/printk.h | 82 ++-
kernel/hung_task.c | 11 +-
kernel/panic.c | 4 +
kernel/printk/printk.c | 1070 +++++++++++++++++++++++++++++----------
kernel/rcu/tree_stall.h | 2 +
kernel/reboot.c | 14 +-
kernel/watchdog.c | 4 +
kernel/watchdog_hld.c | 4 +
lib/dump_stack.c | 4 +-
lib/nmi_backtrace.c | 4 +-
12 files changed, 908 insertions(+), 312 deletions(-)
base-commit: 3ef4ea3d84ca568dcd57816b9521e82e3bd94f08
--
2.30.2
Once kthread printing is available, console printing will no longer
occur in the context of the printk caller. However, there are some
special contexts where it is desirable for the printk caller to
directly print out kernel messages. Using pr_flush() to wait for
threaded printers is only possible if the caller is in a sleepable
context and the kthreads are active. That is not always the case.
Introduce printk_prefer_direct_enter() and printk_prefer_direct_exit()
functions to explicitly (and globally) activate/deactivate preferred
direct console printing. The term "direct console printing" refers to
printing to all enabled consoles from the context of the printk
caller. The term "prefer" is used because this type of printing is
only best effort. If the console is currently locked or other
printers are already actively printing, the printk caller will need
to rely on the other contexts to handle the printing.
This preferred direct printing is how all printing is currently
handled (unless explicitly deferred).
When kthread printing is introduced, there may be some unanticipated
problems due to kthreads being unable to flush important messages.
In order to minimize such risks, preferred direct printing is
activated for the primary important messages when the system
experiences general types of major errors. These are:
- emergency reboot/shutdown
- cpu and rcu stalls
- hard and soft lockups
- hung tasks
- warn
- sysrq
Note that since kthread printing does not yet exist, no behavior
changes result from this commit. This is only implementing the
counter and marking the various places where preferred direct
printing is active.
Signed-off-by: John Ogness <[email protected]>
---
drivers/tty/sysrq.c | 2 ++
include/linux/printk.h | 11 +++++++++++
kernel/hung_task.c | 11 ++++++++++-
kernel/panic.c | 4 ++++
kernel/printk/printk.c | 28 ++++++++++++++++++++++++++++
kernel/rcu/tree_stall.h | 2 ++
kernel/reboot.c | 14 +++++++++++++-
kernel/watchdog.c | 4 ++++
kernel/watchdog_hld.c | 4 ++++
9 files changed, 78 insertions(+), 2 deletions(-)
diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index bbfd004449b5..2884cd638d64 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -578,6 +578,7 @@ void __handle_sysrq(int key, bool check_mask)
rcu_sysrq_start();
rcu_read_lock();
+ printk_prefer_direct_enter();
/*
* Raise the apparent loglevel to maximum so that the sysrq header
* is shown to provide the user with positive feedback. We do not
@@ -619,6 +620,7 @@ void __handle_sysrq(int key, bool check_mask)
pr_cont("\n");
console_loglevel = orig_log_level;
}
+ printk_prefer_direct_exit();
rcu_read_unlock();
rcu_sysrq_end();
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 091fba7283e1..cd26aab0ab2a 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -170,6 +170,9 @@ extern void __printk_safe_exit(void);
#define printk_deferred_enter __printk_safe_enter
#define printk_deferred_exit __printk_safe_exit
+extern void printk_prefer_direct_enter(void);
+extern void printk_prefer_direct_exit(void);
+
extern bool pr_flush(int timeout_ms, bool reset_on_progress);
/*
@@ -222,6 +225,14 @@ static inline void printk_deferred_exit(void)
{
}
+static inline void printk_prefer_direct_enter(void)
+{
+}
+
+static inline void printk_prefer_direct_exit(void)
+{
+}
+
static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
{
return true;
diff --git a/kernel/hung_task.c b/kernel/hung_task.c
index 52501e5f7655..02a65d554340 100644
--- a/kernel/hung_task.c
+++ b/kernel/hung_task.c
@@ -127,6 +127,8 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout)
* complain:
*/
if (sysctl_hung_task_warnings) {
+ printk_prefer_direct_enter();
+
if (sysctl_hung_task_warnings > 0)
sysctl_hung_task_warnings--;
pr_err("INFO: task %s:%d blocked for more than %ld seconds.\n",
@@ -142,6 +144,8 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout)
if (sysctl_hung_task_all_cpu_backtrace)
hung_task_show_all_bt = true;
+
+ printk_prefer_direct_exit();
}
touch_nmi_watchdog();
@@ -204,12 +208,17 @@ static void check_hung_uninterruptible_tasks(unsigned long timeout)
}
unlock:
rcu_read_unlock();
- if (hung_task_show_lock)
+ if (hung_task_show_lock) {
+ printk_prefer_direct_enter();
debug_show_all_locks();
+ printk_prefer_direct_exit();
+ }
if (hung_task_show_all_bt) {
hung_task_show_all_bt = false;
+ printk_prefer_direct_enter();
trigger_all_cpu_backtrace();
+ printk_prefer_direct_exit();
}
if (hung_task_call_panic)
diff --git a/kernel/panic.c b/kernel/panic.c
index 55b50e052ec3..7d422597403f 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -560,6 +560,8 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
{
disable_trace_on_warning();
+ printk_prefer_direct_enter();
+
if (file)
pr_warn("WARNING: CPU: %d PID: %d at %s:%d %pS\n",
raw_smp_processor_id(), current->pid, file, line,
@@ -597,6 +599,8 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
/* Just a warning, don't kill lockdep. */
add_taint(taint, LOCKDEP_STILL_OK);
+
+ printk_prefer_direct_exit();
}
#ifndef __WARN_FLAGS
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d0369afaf365..258d02cff140 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -362,6 +362,34 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
static DEFINE_MUTEX(syslog_lock);
#ifdef CONFIG_PRINTK
+static atomic_t printk_prefer_direct = ATOMIC_INIT(0);
+
+/**
+ * printk_prefer_direct_enter - cause printk() calls to attempt direct
+ * printing to all enabled consoles
+ *
+ * Since it is not possible to call into the console printing code from any
+ * context, there is no guarantee that direct printing will occur.
+ *
+ * This globally effects all printk() callers.
+ *
+ * Context: Any context.
+ */
+void printk_prefer_direct_enter(void)
+{
+ atomic_inc(&printk_prefer_direct);
+}
+
+/**
+ * printk_prefer_direct_exit - restore printk() behavior
+ *
+ * Context: Any context.
+ */
+void printk_prefer_direct_exit(void)
+{
+ WARN_ON(atomic_dec_if_positive(&printk_prefer_direct) < 0);
+}
+
DECLARE_WAIT_QUEUE_HEAD(log_wait);
/* All 3 protected by @syslog_lock. */
/* the next printk record to read by syslog(READ) or /proc/kmsg */
diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h
index 0c5d8516516a..d612707c2ed0 100644
--- a/kernel/rcu/tree_stall.h
+++ b/kernel/rcu/tree_stall.h
@@ -619,6 +619,7 @@ static void print_cpu_stall(unsigned long gps)
* See Documentation/RCU/stallwarn.rst for info on how to debug
* RCU CPU stall warnings.
*/
+ printk_prefer_direct_enter();
trace_rcu_stall_warning(rcu_state.name, TPS("SelfDetected"));
pr_err("INFO: %s self-detected stall on CPU\n", rcu_state.name);
raw_spin_lock_irqsave_rcu_node(rdp->mynode, flags);
@@ -656,6 +657,7 @@ static void print_cpu_stall(unsigned long gps)
*/
set_tsk_need_resched(current);
set_preempt_need_resched();
+ printk_prefer_direct_exit();
}
static void check_cpu_stall(struct rcu_data *rdp)
diff --git a/kernel/reboot.c b/kernel/reboot.c
index 6bcc5d6a6572..4177645e74d6 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -447,9 +447,11 @@ static int __orderly_reboot(void)
ret = run_cmd(reboot_cmd);
if (ret) {
+ printk_prefer_direct_enter();
pr_warn("Failed to start orderly reboot: forcing the issue\n");
emergency_sync();
kernel_restart(NULL);
+ printk_prefer_direct_exit();
}
return ret;
@@ -462,6 +464,7 @@ static int __orderly_poweroff(bool force)
ret = run_cmd(poweroff_cmd);
if (ret && force) {
+ printk_prefer_direct_enter();
pr_warn("Failed to start orderly shutdown: forcing the issue\n");
/*
@@ -471,6 +474,7 @@ static int __orderly_poweroff(bool force)
*/
emergency_sync();
kernel_power_off();
+ printk_prefer_direct_exit();
}
return ret;
@@ -528,6 +532,8 @@ EXPORT_SYMBOL_GPL(orderly_reboot);
*/
static void hw_failure_emergency_poweroff_func(struct work_struct *work)
{
+ printk_prefer_direct_enter();
+
/*
* We have reached here after the emergency shutdown waiting period has
* expired. This means orderly_poweroff has not been able to shut off
@@ -544,6 +550,8 @@ static void hw_failure_emergency_poweroff_func(struct work_struct *work)
*/
pr_emerg("Hardware protection shutdown failed. Trying emergency restart\n");
emergency_restart();
+
+ printk_prefer_direct_exit();
}
static DECLARE_DELAYED_WORK(hw_failure_emergency_poweroff_work,
@@ -582,11 +590,13 @@ void hw_protection_shutdown(const char *reason, int ms_until_forced)
{
static atomic_t allow_proceed = ATOMIC_INIT(1);
+ printk_prefer_direct_enter();
+
pr_emerg("HARDWARE PROTECTION shutdown (%s)\n", reason);
/* Shutdown should be initiated only once. */
if (!atomic_dec_and_test(&allow_proceed))
- return;
+ goto out;
/*
* Queue a backup emergency shutdown in the event of
@@ -594,6 +604,8 @@ void hw_protection_shutdown(const char *reason, int ms_until_forced)
*/
hw_failure_emergency_poweroff(ms_until_forced);
orderly_poweroff(true);
+out:
+ printk_prefer_direct_exit();
}
EXPORT_SYMBOL_GPL(hw_protection_shutdown);
diff --git a/kernel/watchdog.c b/kernel/watchdog.c
index 9166220457bc..40024e03d422 100644
--- a/kernel/watchdog.c
+++ b/kernel/watchdog.c
@@ -424,6 +424,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
/* Start period for the next softlockup warning. */
update_report_ts();
+ printk_prefer_direct_enter();
+
pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
smp_processor_id(), duration,
current->comm, task_pid_nr(current));
@@ -442,6 +444,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
add_taint(TAINT_SOFTLOCKUP, LOCKDEP_STILL_OK);
if (softlockup_panic)
panic("softlockup: hung tasks");
+
+ printk_prefer_direct_exit();
}
return HRTIMER_RESTART;
diff --git a/kernel/watchdog_hld.c b/kernel/watchdog_hld.c
index 247bf0b1582c..701f35f0e2d4 100644
--- a/kernel/watchdog_hld.c
+++ b/kernel/watchdog_hld.c
@@ -135,6 +135,8 @@ static void watchdog_overflow_callback(struct perf_event *event,
if (__this_cpu_read(hard_watchdog_warn) == true)
return;
+ printk_prefer_direct_enter();
+
pr_emerg("Watchdog detected hard LOCKUP on cpu %d\n",
this_cpu);
print_modules();
@@ -155,6 +157,8 @@ static void watchdog_overflow_callback(struct perf_event *event,
if (hardlockup_panic)
nmi_panic(regs, "Hard LOCKUP");
+ printk_prefer_direct_exit();
+
__this_cpu_write(hard_watchdog_warn, true);
return;
}
--
2.30.2
On Tue 2022-04-05 15:31:32, John Ogness wrote:
> Once kthread printing is available, console printing will no longer
> occur in the context of the printk caller. However, there are some
> special contexts where it is desirable for the printk caller to
> directly print out kernel messages. Using pr_flush() to wait for
> threaded printers is only possible if the caller is in a sleepable
> context and the kthreads are active. That is not always the case.
>
> Introduce printk_prefer_direct_enter() and printk_prefer_direct_exit()
> functions to explicitly (and globally) activate/deactivate preferred
> direct console printing. The term "direct console printing" refers to
> printing to all enabled consoles from the context of the printk
> caller. The term "prefer" is used because this type of printing is
> only best effort. If the console is currently locked or other
> printers are already actively printing, the printk caller will need
> to rely on the other contexts to handle the printing.
>
> This preferred direct printing is how all printing is currently
> handled (unless explicitly deferred).
>
> When kthread printing is introduced, there may be some unanticipated
> problems due to kthreads being unable to flush important messages.
> In order to minimize such risks, preferred direct printing is
> activated for the primary important messages when the system
> experiences general types of major errors. These are:
>
> - emergency reboot/shutdown
> - cpu and rcu stalls
> - hard and soft lockups
> - hung tasks
> - warn
> - sysrq
>
> Note that since kthread printing does not yet exist, no behavior
> changes result from this commit. This is only implementing the
> counter and marking the various places where preferred direct
> printing is active.
>
> Signed-off-by: John Ogness <[email protected]>
Looks good to me. Let's see how it works in practice.
It is possible that we will need to add it on more
locations. But it is also possible that we will be
able to remove it somewhere.
Reviewed-by: Petr Mladek <[email protected]>
Best Regards,
Petr
On 4/7/22 11:56, Petr Mladek wrote:
> On Tue 2022-04-05 15:31:32, John Ogness wrote:
>> Once kthread printing is available, console printing will no longer
>> occur in the context of the printk caller. However, there are some
>> special contexts where it is desirable for the printk caller to
>> directly print out kernel messages. Using pr_flush() to wait for
>> threaded printers is only possible if the caller is in a sleepable
>> context and the kthreads are active. That is not always the case.
>>
>> Introduce printk_prefer_direct_enter() and printk_prefer_direct_exit()
>> functions to explicitly (and globally) activate/deactivate preferred
>> direct console printing. The term "direct console printing" refers to
>> printing to all enabled consoles from the context of the printk
>> caller. The term "prefer" is used because this type of printing is
>> only best effort. If the console is currently locked or other
>> printers are already actively printing, the printk caller will need
>> to rely on the other contexts to handle the printing.
>>
>> This preferred direct printing is how all printing is currently
>> handled (unless explicitly deferred).
>>
>> When kthread printing is introduced, there may be some unanticipated
>> problems due to kthreads being unable to flush important messages.
>> In order to minimize such risks, preferred direct printing is
>> activated for the primary important messages when the system
>> experiences general types of major errors. These are:
>>
>> - emergency reboot/shutdown
>> - cpu and rcu stalls
>> - hard and soft lockups
>> - hung tasks
>> - warn
>> - sysrq
I agree that those needs direct printing.
Did you maybe checked how much (e.g. in percentage) of a normal log is then
still left to be printed threadened? Just in case it's not much,
is there still a benefit to introduce threadened printing?
Or another example, e.g. when running on a slow console (the best
testcase I know of is a 9600 baud serial port), where some printks
are threadened. Then a warn printk() has to be shown, doesn't it mean
all threadened printks have to be flushed (waited for) until
the warning can be shown. Will there then still be a measureable time benefit?
Just wondering...
Helge
On 2022-04-07, Helge Deller <[email protected]> wrote:
>>> - emergency reboot/shutdown
>>> - cpu and rcu stalls
>>> - hard and soft lockups
>>> - hung tasks
>>> - warn
>>> - sysrq
>
> I agree that those needs direct printing.
> Did you maybe checked how much (e.g. in percentage) of a normal log is
> then still left to be printed threadened? Just in case it's not much,
> is there still a benefit to introduce threadened printing?
A "normal" log can still contain many many messages. There have been
reports [0] where the system died because _printk_ killed it. This was
not any of the scenarios that we want direct printing for. It was just a
lot of messages that some driver wanted to output.
Until now the response was always to reduce printk usage or avoid it
altogether. printk has a bad reputation because it is so unpredictable
and expensive. So we are fixing printk. With threaded printers, we make
a dramatic change. printk becomes 100% lockless and consistently quite
fast. You can use it to debug or log messages within any code in the
kernel and not need to worry about horrible latencies being introduced.
For drivers that start dumping tons of messages, there is no concern
that the system will die because of the messages.
> Or another example, e.g. when running on a slow console (the best
> testcase I know of is a 9600 baud serial port), where some printks are
> threadened. Then a warn printk() has to be shown, doesn't it mean all
> threadened printks have to be flushed (waited for) until the warning
> can be shown. Will there then still be a measureable time benefit?
Now you are talking about something else, unrelated to the threaded
printing. A warn is considered a serious non-normal event. In this case,
printk temporarily falls back to the direct, slow, unpredictable,
printk-caller-context behavior we know today.
If we see that direct printing is being used during normal operation
(i.e. developers are performing warns just for fun), then we should not
mark warns for direct printing. We will need to get some real-world
experience here, but the goal is that systems do not use direct printing
unless a real serious emergency is going on. Otherwise, the system risks
dying because of the messages rather than the problem being reported.
John
[0] https://lore.kernel.org/all/[email protected]
Hi John,
On 4/7/22 16:35, John Ogness wrote:
> On 2022-04-07, Helge Deller <[email protected]> wrote:
>>>> - emergency reboot/shutdown
>>>> - cpu and rcu stalls
>>>> - hard and soft lockups
>>>> - hung tasks
>>>> - warn
>>>> - sysrq
>>
>> I agree that those needs direct printing.
>> Did you maybe checked how much (e.g. in percentage) of a normal log is
>> then still left to be printed threadened? Just in case it's not much,
>> is there still a benefit to introduce threadened printing?
>
> A "normal" log can still contain many many messages. There have been
> reports [0] where the system died because _printk_ killed it. This was
> not any of the scenarios that we want direct printing for. It was just a
> lot of messages that some driver wanted to output.
>
> Until now the response was always to reduce printk usage or avoid it
> altogether. printk has a bad reputation because it is so unpredictable
> and expensive. So we are fixing printk. With threaded printers, we make
> a dramatic change. printk becomes 100% lockless and consistently quite
> fast. You can use it to debug or log messages within any code in the
> kernel and not need to worry about horrible latencies being introduced.
>
> For drivers that start dumping tons of messages, there is no concern
> that the system will die because of the messages.
Thank you for this good explanation!
In my case - while I debug low-level kernel code - I then just need to use
pr_warn() or pr_emerg() and get it printed non-threadened. That's sufficient for me.
>> Or another example, e.g. when running on a slow console (the best
>> testcase I know of is a 9600 baud serial port), where some printks are
>> threadened. Then a warn printk() has to be shown, doesn't it mean all
>> threadened printks have to be flushed (waited for) until the warning
>> can be shown. Will there then still be a measureable time benefit?
>
> Now you are talking about something else, unrelated to the threaded
> printing. A warn is considered a serious non-normal event. In this case,
> printk temporarily falls back to the direct, slow, unpredictable,
> printk-caller-context behavior we know today.
Good.
> If we see that direct printing is being used during normal operation
> (i.e. developers are performing warns just for fun), then we should not
> mark warns for direct printing. We will need to get some real-world
> experience here, but the goal is that systems do not use direct printing
> unless a real serious emergency is going on. Otherwise, the system risks
> dying because of the messages rather than the problem being reported.
I agree, it's good if this gets fixed at some point.
Thanks!
Helge
> John
>
> [0] https://lore.kernel.org/all/[email protected]
On 2022-04-07, Helge Deller <[email protected]> wrote:
> In my case - while I debug low-level kernel code - I then just need to
> use pr_warn() or pr_emerg() and get it printed non-threadened. That's
> sufficient for me.
Actually, no. The loglevel does not determine if a message is direct
printed or not. By "warn" I was referring to WARN_ON(condition).
If you are debugging low-level kernel code, you usually will _want_
threaded printing. The timestamps match the printk() call, so you will
get accurate logs. And the runtime performance of your low-level kernel
code will not be significantly affected by the printk() call.
If for some reason you really want non-threaded printing, the patch we
are discussing creates new functions to manually activate it:
printk_prefer_direct_enter();
pr_info("debugging\n");
printk_prefer_direct_exit();
But then your pr_info() will cause significant latencies. The timestamp
would be the same, with or without direct printing.
John
On 4/7/22 22:04, John Ogness wrote:
> On 2022-04-07, Helge Deller <[email protected]> wrote:
>> In my case - while I debug low-level kernel code - I then just need to
>> use pr_warn() or pr_emerg() and get it printed non-threadened. That's
>> sufficient for me.
>
> Actually, no. The loglevel does not determine if a message is direct
> printed or not. By "warn" I was referring to WARN_ON(condition).
Oh, then there was a misunderstanding on my side.
> If you are debugging low-level kernel code, you usually will _want_
> threaded printing. The timestamps match the printk() call, so you will
> get accurate logs. And the runtime performance of your low-level kernel
> code will not be significantly affected by the printk() call.
That really much depends on what you debug.
Currently I'm debugging some CPU hotplug stuff, and I really want my
debug info printed immediately, otherwise it's too late to analyze what's
going wrong. I can imaginge other use cases like trying to find memory
leaks are similiar.
> If for some reason you really want non-threaded printing, the patch we
> are discussing creates new functions to manually activate it:
>
> printk_prefer_direct_enter();
> pr_info("debugging\n");
> printk_prefer_direct_exit();
That's quite unhandy. At least I would have thought that pr_emerg() would
do that call sequence.
Wouldn't it make sense to make pr_emerg() work unthreadened, as it's
used quite seldom and only in special situations...
> But then your pr_info() will cause significant latencies. The timestamp
> would be the same, with or without direct printing.
Yes, but that would be Ok in my case.
Helge
On Tue, Apr 05, 2022 at 03:31:32PM +0206, John Ogness wrote:
> Once kthread printing is available, console printing will no longer
> occur in the context of the printk caller. However, there are some
> special contexts where it is desirable for the printk caller to
> directly print out kernel messages. Using pr_flush() to wait for
> threaded printers is only possible if the caller is in a sleepable
> context and the kthreads are active. That is not always the case.
>
> Introduce printk_prefer_direct_enter() and printk_prefer_direct_exit()
> functions to explicitly (and globally) activate/deactivate preferred
> direct console printing. The term "direct console printing" refers to
> printing to all enabled consoles from the context of the printk
> caller. The term "prefer" is used because this type of printing is
> only best effort. If the console is currently locked or other
> printers are already actively printing, the printk caller will need
> to rely on the other contexts to handle the printing.
>
> This preferred direct printing is how all printing is currently
> handled (unless explicitly deferred).
>
> When kthread printing is introduced, there may be some unanticipated
> problems due to kthreads being unable to flush important messages.
> In order to minimize such risks, preferred direct printing is
> activated for the primary important messages when the system
> experiences general types of major errors. These are:
>
> - emergency reboot/shutdown
> - cpu and rcu stalls
> - hard and soft lockups
> - hung tasks
> - warn
> - sysrq
>
> Note that since kthread printing does not yet exist, no behavior
> changes result from this commit. This is only implementing the
> counter and marking the various places where preferred direct
> printing is active.
>
> Signed-off-by: John Ogness <[email protected]>
From an RCU perspective:
Acked-by: Paul E. McKenney <[email protected]>
> ---
> drivers/tty/sysrq.c | 2 ++
> include/linux/printk.h | 11 +++++++++++
> kernel/hung_task.c | 11 ++++++++++-
> kernel/panic.c | 4 ++++
> kernel/printk/printk.c | 28 ++++++++++++++++++++++++++++
> kernel/rcu/tree_stall.h | 2 ++
> kernel/reboot.c | 14 +++++++++++++-
> kernel/watchdog.c | 4 ++++
> kernel/watchdog_hld.c | 4 ++++
> 9 files changed, 78 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
> index bbfd004449b5..2884cd638d64 100644
> --- a/drivers/tty/sysrq.c
> +++ b/drivers/tty/sysrq.c
> @@ -578,6 +578,7 @@ void __handle_sysrq(int key, bool check_mask)
>
> rcu_sysrq_start();
> rcu_read_lock();
> + printk_prefer_direct_enter();
> /*
> * Raise the apparent loglevel to maximum so that the sysrq header
> * is shown to provide the user with positive feedback. We do not
> @@ -619,6 +620,7 @@ void __handle_sysrq(int key, bool check_mask)
> pr_cont("\n");
> console_loglevel = orig_log_level;
> }
> + printk_prefer_direct_exit();
> rcu_read_unlock();
> rcu_sysrq_end();
>
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 091fba7283e1..cd26aab0ab2a 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -170,6 +170,9 @@ extern void __printk_safe_exit(void);
> #define printk_deferred_enter __printk_safe_enter
> #define printk_deferred_exit __printk_safe_exit
>
> +extern void printk_prefer_direct_enter(void);
> +extern void printk_prefer_direct_exit(void);
> +
> extern bool pr_flush(int timeout_ms, bool reset_on_progress);
>
> /*
> @@ -222,6 +225,14 @@ static inline void printk_deferred_exit(void)
> {
> }
>
> +static inline void printk_prefer_direct_enter(void)
> +{
> +}
> +
> +static inline void printk_prefer_direct_exit(void)
> +{
> +}
> +
> static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
> {
> return true;
> diff --git a/kernel/hung_task.c b/kernel/hung_task.c
> index 52501e5f7655..02a65d554340 100644
> --- a/kernel/hung_task.c
> +++ b/kernel/hung_task.c
> @@ -127,6 +127,8 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout)
> * complain:
> */
> if (sysctl_hung_task_warnings) {
> + printk_prefer_direct_enter();
> +
> if (sysctl_hung_task_warnings > 0)
> sysctl_hung_task_warnings--;
> pr_err("INFO: task %s:%d blocked for more than %ld seconds.\n",
> @@ -142,6 +144,8 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout)
>
> if (sysctl_hung_task_all_cpu_backtrace)
> hung_task_show_all_bt = true;
> +
> + printk_prefer_direct_exit();
> }
>
> touch_nmi_watchdog();
> @@ -204,12 +208,17 @@ static void check_hung_uninterruptible_tasks(unsigned long timeout)
> }
> unlock:
> rcu_read_unlock();
> - if (hung_task_show_lock)
> + if (hung_task_show_lock) {
> + printk_prefer_direct_enter();
> debug_show_all_locks();
> + printk_prefer_direct_exit();
> + }
>
> if (hung_task_show_all_bt) {
> hung_task_show_all_bt = false;
> + printk_prefer_direct_enter();
> trigger_all_cpu_backtrace();
> + printk_prefer_direct_exit();
> }
>
> if (hung_task_call_panic)
> diff --git a/kernel/panic.c b/kernel/panic.c
> index 55b50e052ec3..7d422597403f 100644
> --- a/kernel/panic.c
> +++ b/kernel/panic.c
> @@ -560,6 +560,8 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
> {
> disable_trace_on_warning();
>
> + printk_prefer_direct_enter();
> +
> if (file)
> pr_warn("WARNING: CPU: %d PID: %d at %s:%d %pS\n",
> raw_smp_processor_id(), current->pid, file, line,
> @@ -597,6 +599,8 @@ void __warn(const char *file, int line, void *caller, unsigned taint,
>
> /* Just a warning, don't kill lockdep. */
> add_taint(taint, LOCKDEP_STILL_OK);
> +
> + printk_prefer_direct_exit();
> }
>
> #ifndef __WARN_FLAGS
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index d0369afaf365..258d02cff140 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -362,6 +362,34 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
> static DEFINE_MUTEX(syslog_lock);
>
> #ifdef CONFIG_PRINTK
> +static atomic_t printk_prefer_direct = ATOMIC_INIT(0);
> +
> +/**
> + * printk_prefer_direct_enter - cause printk() calls to attempt direct
> + * printing to all enabled consoles
> + *
> + * Since it is not possible to call into the console printing code from any
> + * context, there is no guarantee that direct printing will occur.
> + *
> + * This globally effects all printk() callers.
> + *
> + * Context: Any context.
> + */
> +void printk_prefer_direct_enter(void)
> +{
> + atomic_inc(&printk_prefer_direct);
> +}
> +
> +/**
> + * printk_prefer_direct_exit - restore printk() behavior
> + *
> + * Context: Any context.
> + */
> +void printk_prefer_direct_exit(void)
> +{
> + WARN_ON(atomic_dec_if_positive(&printk_prefer_direct) < 0);
> +}
> +
> DECLARE_WAIT_QUEUE_HEAD(log_wait);
> /* All 3 protected by @syslog_lock. */
> /* the next printk record to read by syslog(READ) or /proc/kmsg */
> diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h
> index 0c5d8516516a..d612707c2ed0 100644
> --- a/kernel/rcu/tree_stall.h
> +++ b/kernel/rcu/tree_stall.h
> @@ -619,6 +619,7 @@ static void print_cpu_stall(unsigned long gps)
> * See Documentation/RCU/stallwarn.rst for info on how to debug
> * RCU CPU stall warnings.
> */
> + printk_prefer_direct_enter();
> trace_rcu_stall_warning(rcu_state.name, TPS("SelfDetected"));
> pr_err("INFO: %s self-detected stall on CPU\n", rcu_state.name);
> raw_spin_lock_irqsave_rcu_node(rdp->mynode, flags);
> @@ -656,6 +657,7 @@ static void print_cpu_stall(unsigned long gps)
> */
> set_tsk_need_resched(current);
> set_preempt_need_resched();
> + printk_prefer_direct_exit();
> }
>
> static void check_cpu_stall(struct rcu_data *rdp)
> diff --git a/kernel/reboot.c b/kernel/reboot.c
> index 6bcc5d6a6572..4177645e74d6 100644
> --- a/kernel/reboot.c
> +++ b/kernel/reboot.c
> @@ -447,9 +447,11 @@ static int __orderly_reboot(void)
> ret = run_cmd(reboot_cmd);
>
> if (ret) {
> + printk_prefer_direct_enter();
> pr_warn("Failed to start orderly reboot: forcing the issue\n");
> emergency_sync();
> kernel_restart(NULL);
> + printk_prefer_direct_exit();
> }
>
> return ret;
> @@ -462,6 +464,7 @@ static int __orderly_poweroff(bool force)
> ret = run_cmd(poweroff_cmd);
>
> if (ret && force) {
> + printk_prefer_direct_enter();
> pr_warn("Failed to start orderly shutdown: forcing the issue\n");
>
> /*
> @@ -471,6 +474,7 @@ static int __orderly_poweroff(bool force)
> */
> emergency_sync();
> kernel_power_off();
> + printk_prefer_direct_exit();
> }
>
> return ret;
> @@ -528,6 +532,8 @@ EXPORT_SYMBOL_GPL(orderly_reboot);
> */
> static void hw_failure_emergency_poweroff_func(struct work_struct *work)
> {
> + printk_prefer_direct_enter();
> +
> /*
> * We have reached here after the emergency shutdown waiting period has
> * expired. This means orderly_poweroff has not been able to shut off
> @@ -544,6 +550,8 @@ static void hw_failure_emergency_poweroff_func(struct work_struct *work)
> */
> pr_emerg("Hardware protection shutdown failed. Trying emergency restart\n");
> emergency_restart();
> +
> + printk_prefer_direct_exit();
> }
>
> static DECLARE_DELAYED_WORK(hw_failure_emergency_poweroff_work,
> @@ -582,11 +590,13 @@ void hw_protection_shutdown(const char *reason, int ms_until_forced)
> {
> static atomic_t allow_proceed = ATOMIC_INIT(1);
>
> + printk_prefer_direct_enter();
> +
> pr_emerg("HARDWARE PROTECTION shutdown (%s)\n", reason);
>
> /* Shutdown should be initiated only once. */
> if (!atomic_dec_and_test(&allow_proceed))
> - return;
> + goto out;
>
> /*
> * Queue a backup emergency shutdown in the event of
> @@ -594,6 +604,8 @@ void hw_protection_shutdown(const char *reason, int ms_until_forced)
> */
> hw_failure_emergency_poweroff(ms_until_forced);
> orderly_poweroff(true);
> +out:
> + printk_prefer_direct_exit();
> }
> EXPORT_SYMBOL_GPL(hw_protection_shutdown);
>
> diff --git a/kernel/watchdog.c b/kernel/watchdog.c
> index 9166220457bc..40024e03d422 100644
> --- a/kernel/watchdog.c
> +++ b/kernel/watchdog.c
> @@ -424,6 +424,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
> /* Start period for the next softlockup warning. */
> update_report_ts();
>
> + printk_prefer_direct_enter();
> +
> pr_emerg("BUG: soft lockup - CPU#%d stuck for %us! [%s:%d]\n",
> smp_processor_id(), duration,
> current->comm, task_pid_nr(current));
> @@ -442,6 +444,8 @@ static enum hrtimer_restart watchdog_timer_fn(struct hrtimer *hrtimer)
> add_taint(TAINT_SOFTLOCKUP, LOCKDEP_STILL_OK);
> if (softlockup_panic)
> panic("softlockup: hung tasks");
> +
> + printk_prefer_direct_exit();
> }
>
> return HRTIMER_RESTART;
> diff --git a/kernel/watchdog_hld.c b/kernel/watchdog_hld.c
> index 247bf0b1582c..701f35f0e2d4 100644
> --- a/kernel/watchdog_hld.c
> +++ b/kernel/watchdog_hld.c
> @@ -135,6 +135,8 @@ static void watchdog_overflow_callback(struct perf_event *event,
> if (__this_cpu_read(hard_watchdog_warn) == true)
> return;
>
> + printk_prefer_direct_enter();
> +
> pr_emerg("Watchdog detected hard LOCKUP on cpu %d\n",
> this_cpu);
> print_modules();
> @@ -155,6 +157,8 @@ static void watchdog_overflow_callback(struct perf_event *event,
> if (hardlockup_panic)
> nmi_panic(regs, "Hard LOCKUP");
>
> + printk_prefer_direct_exit();
> +
> __this_cpu_write(hard_watchdog_warn, true);
> return;
> }
> --
> 2.30.2
>
On Thu 2022-04-07 22:20:30, Helge Deller wrote:
> On 4/7/22 22:04, John Ogness wrote:
> > On 2022-04-07, Helge Deller <[email protected]> wrote:
> >> In my case - while I debug low-level kernel code - I then just need to
> >> use pr_warn() or pr_emerg() and get it printed non-threadened. That's
> >> sufficient for me.
> >
> > Actually, no. The loglevel does not determine if a message is direct
> > printed or not. By "warn" I was referring to WARN_ON(condition).
>
> Oh, then there was a misunderstanding on my side.
>
> > If you are debugging low-level kernel code, you usually will _want_
> > threaded printing. The timestamps match the printk() call, so you will
> > get accurate logs. And the runtime performance of your low-level kernel
> > code will not be significantly affected by the printk() call.
>
> That really much depends on what you debug.
> Currently I'm debugging some CPU hotplug stuff, and I really want my
> debug info printed immediately, otherwise it's too late to analyze what's
> going wrong. I can imaginge other use cases like trying to find memory
> leaks are similiar.
So, it is not about severity of the messages but about the context,
in this case the suspend. We try to address this. 10th patch from
this patchset adds:
static inline bool allow_direct_printing(void)
{
return (!printk_kthreads_available ||
system_state > SYSTEM_RUNNING ||
oops_in_progress ||
atomic_read(&printk_prefer_direct));
}
It means that printk() inside the SYSTEM_SUSPEND state will
automatically try to handle the console directly.
I intentionally mention "try" because printk() uses console_trylock().
It fails when anyone else already does the printing, including
a kthread. trylock() is needed because printk() must be usable also
in atomic context. It has worked this way for more than two decades.
It came with SMP support.
> > If for some reason you really want non-threaded printing, the patch we
> > are discussing creates new functions to manually activate it:
> >
> > printk_prefer_direct_enter();
> > pr_info("debugging\n");
> > printk_prefer_direct_exit();
>
> That's quite unhandy. At least I would have thought that pr_emerg() would
> do that call sequence.
> Wouldn't it make sense to make pr_emerg() work unthreadened, as it's
> used quite seldom and only in special situations...
It is true that pr_emerg() is relatively special.
But I would really like to avoid a situation where developers
use non-appropriate printk level just to get the message
directly.
Instead, we should allow using the direct context in some
situation easily. We could also add a command line parameter
to disable the kthreads completely.
Best Regards,
Petr