Messages in this thread | | | Date | Sat, 9 Apr 2022 08:57:31 -0700 | From | "Paul E. McKenney" <> | Subject | Re: [PATCH printk v2 09/12] printk: add functions to prefer direct printing |
| |
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 >
| |