From: John Ogness <john.ogness@linutronix.de> Date: Mon, 18 Sep 2023 20:27:41 +0000 Subject: [PATCH 32/48] lockdep: Mark emergency sections in lockdep splats Mark emergency sections wherever multiple lines of lock debugging output are generated. In an emergency section the CPU will not perform console output for the printk() calls. Instead, a flushing of the console output is triggered when exiting the emergency section. This allows the full message block to be stored as quickly as possible in the ringbuffer. Signed-off-by: John Ogness <john.ogness@linutronix.de> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de> --- kernel/locking/lockdep.c | 91 +++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 88 insertions(+), 3 deletions(-) Index: linux-6.8.2-rt10/kernel/locking/lockdep.c =================================================================== @ linux-6.8.2-rt10/kernel/locking/lockdep.c:59 @ #include <linux/kprobes.h> #include <linux/lockdep.h> #include <linux/context_tracking.h> +#include <linux/console.h> #include <asm/sections.h> @ linux-6.8.2-rt10/kernel/locking/lockdep.c:578 @ static struct lock_trace *save_trace(voi if (!debug_locks_off_graph_unlock()) return NULL; + nbcon_cpu_emergency_enter(); print_lockdep_off("BUG: MAX_STACK_TRACE_ENTRIES too low!"); dump_stack(); + nbcon_cpu_emergency_exit(); return NULL; } @ linux-6.8.2-rt10/kernel/locking/lockdep.c:788 @ static void lockdep_print_held_locks(str { int i, depth = READ_ONCE(p->lockdep_depth); + nbcon_cpu_emergency_enter(); + if (!depth) printk("no locks held by %s/%d.\n", p->comm, task_pid_nr(p)); else @ linux-6.8.2-rt10/kernel/locking/lockdep.c:800 @ static void lockdep_print_held_locks(str * and it's not the current task. */ if (p != current && task_is_running(p)) - return; + goto out; for (i = 0; i < depth; i++) { printk(" #%d: ", i); print_lock(p->held_locks + i); } +out: + nbcon_cpu_emergency_exit(); } static void print_kernel_ident(void) @ linux-6.8.2-rt10/kernel/locking/lockdep.c:898 @ look_up_lock_class(const struct lockdep_ if (unlikely(subclass >= MAX_LOCKDEP_SUBCLASSES)) { instrumentation_begin(); debug_locks_off(); + nbcon_cpu_emergency_enter(); printk(KERN_ERR "BUG: looking up invalid subclass: %u\n", subclass); printk(KERN_ERR "turning off the locking correctness validator.\n"); dump_stack(); + nbcon_cpu_emergency_exit(); instrumentation_end(); return NULL; } @ linux-6.8.2-rt10/kernel/locking/lockdep.c:981 @ static bool assign_lock_key(struct lockd else { /* Debug-check: all keys must be persistent! */ debug_locks_off(); + nbcon_cpu_emergency_enter(); pr_err("INFO: trying to register non-static key.\n"); pr_err("The code is fine but needs lockdep annotation, or maybe\n"); pr_err("you didn't initialize this object before use?\n"); pr_err("turning off the locking correctness validator.\n"); dump_stack(); + nbcon_cpu_emergency_exit(); return false; } @ linux-6.8.2-rt10/kernel/locking/lockdep.c:1331 @ register_lock_class(struct lockdep_map * return NULL; } + nbcon_cpu_emergency_enter(); print_lockdep_off("BUG: MAX_LOCKDEP_KEYS too low!"); dump_stack(); + nbcon_cpu_emergency_exit(); return NULL; } nr_lock_classes++; @ linux-6.8.2-rt10/kernel/locking/lockdep.c:1366 @ register_lock_class(struct lockdep_map * if (verbose(class)) { graph_unlock(); + nbcon_cpu_emergency_enter(); printk("\nnew class %px: %s", class->key, class->name); if (class->name_version > 1) printk(KERN_CONT "#%d", class->name_version); printk(KERN_CONT "\n"); dump_stack(); + nbcon_cpu_emergency_exit(); if (!graph_lock()) { return NULL; @ linux-6.8.2-rt10/kernel/locking/lockdep.c:1411 @ static struct lock_list *alloc_list_entr if (!debug_locks_off_graph_unlock()) return NULL; + nbcon_cpu_emergency_enter(); print_lockdep_off("BUG: MAX_LOCKDEP_ENTRIES too low!"); dump_stack(); + nbcon_cpu_emergency_exit(); return NULL; } nr_list_entries++; @ linux-6.8.2-rt10/kernel/locking/lockdep.c:2060 @ static noinline void print_circular_bug( depth = get_lock_depth(target); + nbcon_cpu_emergency_enter(); + print_circular_bug_header(target, depth, check_src, check_tgt); parent = get_lock_parent(target); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:2080 @ static noinline void print_circular_bug( printk("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } static noinline void print_bfs_bug(int ret) @ linux-6.8.2-rt10/kernel/locking/lockdep.c:2594 @ print_bad_irq_dependency(struct task_str if (!debug_locks_off_graph_unlock() || debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("=====================================================\n"); pr_warn("WARNING: %s-safe -> %s-unsafe lock order detected\n", @ linux-6.8.2-rt10/kernel/locking/lockdep.c:2645 @ print_bad_irq_dependency(struct task_str pr_warn(" and %s-irq-unsafe lock:\n", irqclass); next_root->trace = save_trace(); if (!next_root->trace) - return; + goto out; print_shortest_lock_dependencies(forwards_entry, next_root); pr_warn("\nstack backtrace:\n"); dump_stack(); +out: + nbcon_cpu_emergency_exit(); } static const char *state_names[] = { @ linux-6.8.2-rt10/kernel/locking/lockdep.c:3016 @ print_deadlock_bug(struct task_struct *c if (!debug_locks_off_graph_unlock() || debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("============================================\n"); pr_warn("WARNING: possible recursive locking detected\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:3040 @ print_deadlock_bug(struct task_struct *c pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } /* @ linux-6.8.2-rt10/kernel/locking/lockdep.c:3639 @ static void print_collision(struct task_ struct held_lock *hlock_next, struct lock_chain *chain) { + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("============================\n"); pr_warn("WARNING: chain_key collision\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:3657 @ static void print_collision(struct task_ pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } #endif @ linux-6.8.2-rt10/kernel/locking/lockdep.c:3749 @ static inline int add_chain_cache(struct if (!debug_locks_off_graph_unlock()) return 0; + nbcon_cpu_emergency_enter(); print_lockdep_off("BUG: MAX_LOCKDEP_CHAINS too low!"); dump_stack(); + nbcon_cpu_emergency_exit(); return 0; } chain->chain_key = chain_key; @ linux-6.8.2-rt10/kernel/locking/lockdep.c:3769 @ static inline int add_chain_cache(struct if (!debug_locks_off_graph_unlock()) return 0; + nbcon_cpu_emergency_enter(); print_lockdep_off("BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low!"); dump_stack(); + nbcon_cpu_emergency_exit(); return 0; } @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4011 @ print_usage_bug(struct task_struct *curr if (!debug_locks_off() || debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("================================\n"); pr_warn("WARNING: inconsistent lock state\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4041 @ print_usage_bug(struct task_struct *curr pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } /* @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4077 @ print_irq_inversion_bug(struct task_stru if (!debug_locks_off_graph_unlock() || debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("========================================================\n"); pr_warn("WARNING: possible irq lock inversion dependency detected\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4119 @ print_irq_inversion_bug(struct task_stru pr_warn("\nthe shortest dependencies between 2nd lock and 1st lock:\n"); root->trace = save_trace(); if (!root->trace) - return; + goto out; print_shortest_lock_dependencies(other, root); pr_warn("\nstack backtrace:\n"); dump_stack(); +out: + nbcon_cpu_emergency_exit(); } /* @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4202 @ void print_irqtrace_events(struct task_s { const struct irqtrace_events *trace = &curr->irqtrace; + nbcon_cpu_emergency_enter(); + printk("irq event stamp: %u\n", trace->irq_events); printk("hardirqs last enabled at (%u): [<%px>] %pS\n", trace->hardirq_enable_event, (void *)trace->hardirq_enable_ip, @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4217 @ void print_irqtrace_events(struct task_s printk("softirqs last disabled at (%u): [<%px>] %pS\n", trace->softirq_disable_event, (void *)trace->softirq_disable_ip, (void *)trace->softirq_disable_ip); + + nbcon_cpu_emergency_exit(); } static int HARDIRQ_verbose(struct lock_class *class) @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4739 @ unlock: * We must printk outside of the graph_lock: */ if (ret == 2) { + nbcon_cpu_emergency_enter(); printk("\nmarked lock as {%s}:\n", usage_str[new_bit]); print_lock(this); print_irqtrace_events(curr); dump_stack(); + nbcon_cpu_emergency_exit(); } return ret; @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4785 @ print_lock_invalid_wait_context(struct t if (debug_locks_silent) return 0; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("=============================\n"); pr_warn("[ BUG: Invalid wait context ]\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:4806 @ print_lock_invalid_wait_context(struct t pr_warn("stack backtrace:\n"); dump_stack(); + nbcon_cpu_emergency_exit(); + return 0; } @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5012 @ print_lock_nested_lock_not_held(struct t if (debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("==================================\n"); pr_warn("WARNING: Nested lock was not taken\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5034 @ print_lock_nested_lock_not_held(struct t pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } static int __lock_is_held(const struct lockdep_map *lock, int read); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5081 @ static int __lock_acquire(struct lockdep debug_class_ops_inc(class); if (very_verbose(class)) { + nbcon_cpu_emergency_enter(); printk("\nacquire class [%px] %s", class->key, class->name); if (class->name_version > 1) printk(KERN_CONT "#%d", class->name_version); printk(KERN_CONT "\n"); dump_stack(); + nbcon_cpu_emergency_exit(); } /* @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5214 @ static int __lock_acquire(struct lockdep #endif if (unlikely(curr->lockdep_depth >= MAX_LOCK_DEPTH)) { debug_locks_off(); + nbcon_cpu_emergency_enter(); print_lockdep_off("BUG: MAX_LOCK_DEPTH too low!"); printk(KERN_DEBUG "depth: %i max: %lu!\n", curr->lockdep_depth, MAX_LOCK_DEPTH); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5222 @ static int __lock_acquire(struct lockdep lockdep_print_held_locks(current); debug_show_all_locks(); dump_stack(); + nbcon_cpu_emergency_exit(); return 0; } @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5242 @ static void print_unlock_imbalance_bug(s if (debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("=====================================\n"); pr_warn("WARNING: bad unlock balance detected!\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5260 @ static void print_unlock_imbalance_bug(s pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } static noinstr int match_held_lock(const struct held_lock *hlock, @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5965 @ static void print_lock_contention_bug(st if (debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("=================================\n"); pr_warn("WARNING: bad contention detected!\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:5983 @ static void print_lock_contention_bug(st pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } static void @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6598 @ print_freed_lock_bug(struct task_struct if (debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("=========================\n"); pr_warn("WARNING: held lock freed!\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6612 @ print_freed_lock_bug(struct task_struct pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } static inline int not_in_range(const void* mem_from, unsigned long mem_len, @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6660 @ static void print_held_locks_bug(void) if (debug_locks_silent) return; + nbcon_cpu_emergency_enter(); + pr_warn("\n"); pr_warn("====================================\n"); pr_warn("WARNING: %s/%d still has locks held!\n", @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6671 @ static void print_held_locks_bug(void) lockdep_print_held_locks(current); pr_warn("\nstack backtrace:\n"); dump_stack(); + + nbcon_cpu_emergency_exit(); } void debug_check_no_locks_held(void) @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6691 @ void debug_show_all_locks(void) pr_warn("INFO: lockdep is turned off.\n"); return; } + nbcon_cpu_emergency_enter(); pr_warn("\nShowing all locks held in the system:\n"); rcu_read_lock(); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6706 @ void debug_show_all_locks(void) pr_warn("\n"); pr_warn("=============================================\n\n"); + nbcon_cpu_emergency_exit(); } EXPORT_SYMBOL_GPL(debug_show_all_locks); #endif @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6732 @ asmlinkage __visible void lockdep_sys_ex if (unlikely(curr->lockdep_depth)) { if (!debug_locks_off()) return; + nbcon_cpu_emergency_enter(); pr_warn("\n"); pr_warn("================================================\n"); pr_warn("WARNING: lock held when returning to user space!\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6741 @ asmlinkage __visible void lockdep_sys_ex pr_warn("%s/%d is leaving the kernel with locks still held!\n", curr->comm, curr->pid); lockdep_print_held_locks(curr); + nbcon_cpu_emergency_exit(); } /* @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6758 @ void lockdep_rcu_suspicious(const char * bool rcu = warn_rcu_enter(); /* Note: the following can be executed concurrently, so be careful. */ + nbcon_cpu_emergency_enter(); pr_warn("\n"); pr_warn("=============================\n"); pr_warn("WARNING: suspicious RCU usage\n"); @ linux-6.8.2-rt10/kernel/locking/lockdep.c:6797 @ void lockdep_rcu_suspicious(const char * lockdep_print_held_locks(curr); pr_warn("\nstack backtrace:\n"); dump_stack(); + nbcon_cpu_emergency_exit(); warn_rcu_exit(rcu); } EXPORT_SYMBOL_GPL(lockdep_rcu_suspicious);