Re: [PATCH printk v2 09/12] printk: add functions to prefer direct printing

Paul E. McKenney
2022-04-09T15:57:37Z

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 <john.ogness@linutronix.de>

From an RCU perspective:

Acked-by: Paul E. McKenney <paulmck@kernel.org>

> ---
> 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
>