locking/lockdep: replace simple printk by pr_info
RFC PATCH 1/1 locking/lockdep: replace simple printk by pr_info
While working on detector of new warn/err/crit/... messages, I found that the following messages was printed with the warn loglevel:
[ 0.001607] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [ 0.001625] ... MAX_LOCKDEP_SUBCLASSES: 8 [ 0.001641] ... MAX_LOCK_DEPTH: 48 [ 0.001658] ... MAX_LOCKDEP_KEYS: 8191 [ 0.001673] ... CLASSHASH_SIZE: 4096 [ 0.001689] ... MAX_LOCKDEP_ENTRIES: 32768 [ 0.001704] ... MAX_LOCKDEP_CHAINS: 65536 [ 0.001719] ... CHAINHASH_SIZE: 32768 [ 0.001735] memory used by lock dependency info: 4623 kB
While the cause is still unknown to me, converting printk to pr_info fixed the issue.
--- kernel/locking/lockdep.c | 152 +++++++++++++++++++++++------------------------ 1 file changed, 76 insertions(+), 76 deletions(-)
kernel/locking/lockdep.c +76 -76
@@ -560,9 +560,9 @@ static void lockdep_print_held_locks(struct task_struct *p)int i, depth =READ_ONCE (p->lockdep_depth);if (!depth) -printk ("no locks held by %s/%d.\n" , p->comm,task_pid_nr (p)); +pr_info ("no locks held by %s/%d.\n" , p->comm,task_pid_nr (p));else -printk ("%d lock%s held by %s/%d:\n" , depth, +pr_info ("%d lock%s held by %s/%d:\n" , depth, depth >1 ?"s" :"" , p->comm,task_pid_nr (p));/* * It's not reliable to print a task's held locks if it's not sleeping
@@ -571,14 +571,14 @@ static void lockdep_print_held_locks(struct task_struct *p)if (p->state ==TASK_RUNNING && p != current)return ;for (i =0 ; i < depth; i++) { -printk (" #%d: " , i); +pr_info (" #%d: " , i);print_lock (p->held_locks + i); } }static void print_kernel_ident (void ) { -printk ("%s %.*s %s\n" ,init_utsname ()->release, +pr_info ("%s %.*s %s\n" ,init_utsname ()->release, (int )strcspn (init_utsname ()->version," " ),init_utsname ()->version,print_tainted ());
@@ -806,7 +806,7 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)if (verbose (class)) {graph_unlock (); -printk ("\nnew class %px: %s" , class->key, class->name); +pr_info ("\nnew class %px: %s" , class->key, class->name);if (class->name_version >1 )printk (KERN_CONT "#%d" , class->name_version);printk (KERN_CONT "\n" );
@@ -1085,7 +1085,7 @@ print_circular_bug_entry(struct lock_list *target, int depth) {if (debug_locks_silent)return 0 ; -printk ("\n-> #%u" , depth); +pr_info ("\n-> #%u" , depth);print_lock_name (target->class);printk (KERN_CONT ":\n" );print_stack_trace (&target->trace,6 );
@@ -1116,7 +1116,7 @@ print_circular_lock_scenario(struct held_lock *src,* from the safe_class lock to the unsafe_class lock. */ if (parent != source) { -printk ("Chain exists of:\n " ); +pr_info ("Chain exists of:\n " );__print_lock_name (source);printk (KERN_CONT " --> " );__print_lock_name (parent);
@@ -1125,22 +1125,22 @@ print_circular_lock_scenario(struct held_lock *src,printk (KERN_CONT "\n\n" ); } -printk (" Possible unsafe locking scenario:\n\n" ); -printk (" CPU0 CPU1\n" ); -printk (" ---- ----\n" ); -printk (" lock(" ); +pr_info (" Possible unsafe locking scenario:\n\n" ); +pr_info (" CPU0 CPU1\n" ); +pr_info (" ---- ----\n" ); +pr_info (" lock(" );__print_lock_name (target);printk (KERN_CONT ");\n" ); -printk (" lock(" ); +pr_info (" lock(" );__print_lock_name (parent);printk (KERN_CONT ");\n" ); -printk (" lock(" ); +pr_info (" lock(" );__print_lock_name (target);printk (KERN_CONT ");\n" ); -printk (" lock(" ); +pr_info (" lock(" );__print_lock_name (source);printk (KERN_CONT ");\n" ); -printk ("\n *** DEADLOCK ***\n\n" ); +pr_info ("\n *** DEADLOCK ***\n\n" ); }/*
@@ -1211,13 +1211,13 @@ static noinline int print_circular_bug(struct lock_list *this, parent =get_lock_parent (parent); } -printk ("\nother info that might help us debug this:\n\n" ); +pr_info ("\nother info that might help us debug this:\n\n" );print_circular_lock_scenario (check_src, check_tgt, first_parent);lockdep_print_held_locks (curr); -printk ("\nstack backtrace:\n" ); +pr_info ("\nstack backtrace:\n" );dump_stack ();return 0 ;
@@ -1389,7 +1389,7 @@ static void print_lock_class_header(struct lock_class *class, int depth) {int bit; -printk ("%*s->" , depth,"" ); +pr_info ("%*s->" , depth,"" );print_lock_name (class);#ifdef CONFIG_DEBUG_LOCKDEP printk (KERN_CONT " ops: %lu" ,debug_class_ops_read (class));
@@ -1400,14 +1400,14 @@ static void print_lock_class_header(struct lock_class *class, int depth)if (class->usage_mask & (1 << bit)) {int len = depth; - len +=printk ("%*s %s" , depth,"" , usage_str[bit]); + len +=pr_info ("%*s %s" , depth,"" , usage_str[bit]); len +=printk (KERN_CONT " at:\n" );print_stack_trace (class->usage_traces + bit, len); } } -printk ("%*s }\n" , depth,"" ); +pr_info ("%*s }\n" , depth,"" ); -printk ("%*s ... key at: [<%px>] %pS\n" , +pr_info ("%*s ... key at: [<%px>] %pS\n" , depth,"" , class->key, class->key); }
@@ -1426,12 +1426,12 @@ print_shortest_lock_dependencies(struct lock_list *leaf, do { print_lock_class_header(entry->class, depth); - printk("%*s ... acquired at:\n", depth, ""); + pr_info("%*s ... acquired at:\n", depth, ""); print_stack_trace(&entry->trace, 2); - printk("\n"); + pr_info("\n"); if (depth == 0 && (entry != root)) { - printk("lockdep:%s bad path found in chain graph\n", __func__); + pr_info("lockdep:%s bad path found in chain graph\n", __func__); break; }
@@ -1469,7 +1469,7 @@ print_irq_lock_scenario(struct lock_list *safe_entry,* from the safe_class lock to the unsafe_class lock. */ if (middle_class != unsafe_class) { -printk ("Chain exists of:\n " ); +pr_info ("Chain exists of:\n " );__print_lock_name (safe_class);printk (KERN_CONT " --> " );__print_lock_name (middle_class);
@@ -1478,24 +1478,24 @@ print_irq_lock_scenario(struct lock_list *safe_entry,printk (KERN_CONT "\n\n" ); } -printk (" Possible interrupt unsafe locking scenario:\n\n" ); -printk (" CPU0 CPU1\n" ); -printk (" ---- ----\n" ); -printk (" lock(" ); +pr_info (" Possible interrupt unsafe locking scenario:\n\n" ); +pr_info (" CPU0 CPU1\n" ); +pr_info (" ---- ----\n" ); +pr_info (" lock(" );__print_lock_name (unsafe_class);printk (KERN_CONT ");\n" ); -printk (" local_irq_disable();\n" ); -printk (" lock(" ); +pr_info (" local_irq_disable();\n" ); +pr_info (" lock(" );__print_lock_name (safe_class);printk (KERN_CONT ");\n" ); -printk (" lock(" ); +pr_info (" lock(" );__print_lock_name (middle_class);printk (KERN_CONT ");\n" ); -printk (" <Interrupt>\n" ); -printk (" lock(" ); +pr_info (" <Interrupt>\n" ); +pr_info (" lock(" );__print_lock_name (safe_class);printk (KERN_CONT ");\n" ); -printk ("\n *** DEADLOCK ***\n\n" ); +pr_info ("\n *** DEADLOCK ***\n\n" ); } static int
@@ -1722,17 +1722,17 @@ print_deadlock_scenario(struct held_lock *nxt,struct lock_class *next =hlock_class (nxt);struct lock_class *prev =hlock_class (prv); -printk (" Possible unsafe locking scenario:\n\n" ); -printk (" CPU0\n" ); -printk (" ----\n" ); -printk (" lock(" ); +pr_info (" Possible unsafe locking scenario:\n\n" ); +pr_info (" CPU0\n" ); +pr_info (" ----\n" ); +pr_info (" lock(" );__print_lock_name (prev);printk (KERN_CONT ");\n" ); -printk (" lock(" ); +pr_info (" lock(" );__print_lock_name (next);printk (KERN_CONT ");\n" ); -printk ("\n *** DEADLOCK ***\n\n" ); -printk (" May be due to missing lock nesting notation\n\n" ); +pr_info ("\n *** DEADLOCK ***\n\n" ); +pr_info (" May be due to missing lock nesting notation\n\n" ); } static int
@@ -2052,7 +2052,7 @@ static u64 print_chain_key_iteration(int class_idx, u64 chain_key) {u64 new_chain_key =iterate_chain_key (chain_key, class_idx); -printk (" class_idx:%d -> chain_key:%016Lx" , +pr_info (" class_idx:%d -> chain_key:%016Lx" , class_idx, (unsigned long long )new_chain_key);return new_chain_key;
@@ -2066,7 +2066,7 @@ print_chain_keys_held_locks(struct task_struct *curr, struct held_lock *hlock_neint depth = curr->lockdep_depth;int i; -printk ("depth: %u\n" , depth +1 ); +pr_info ("depth: %u\n" , depth +1 );for (i =get_first_held_lock (curr, hlock_next); i < depth; i++) { hlock = curr->held_locks + i; chain_key =print_chain_key_iteration (hlock->class_idx, chain_key);
@@ -2084,13 +2084,13 @@ static void print_chain_keys_chain(struct lock_chain *chain)u64 chain_key =0 ;int class_id; -printk ("depth: %u\n" , chain->depth); +pr_info ("depth: %u\n" , chain->depth);for (i =0 ; i < chain->depth; i++) { class_id = chain_hlocks[chain->base + i]; chain_key =print_chain_key_iteration (class_id +1 , chain_key);print_lock_name (lock_classes + class_id); -printk ("\n" ); +pr_info ("\n" ); } }
@@ -2269,7 +2269,7 @@ static inline int lookup_chain_cache_add(struct task_struct *curr,return 0 ;if (very_verbose (class)) { -printk ("\nhash chain already cached, key: " +pr_info ("\nhash chain already cached, key: " "%016Lx tail class: [%px] %s\n" , (unsigned long long )chain_key, class->key, class->name);
@@ -2279,7 +2279,7 @@ static inline int lookup_chain_cache_add(struct task_struct *curr, }if (very_verbose (class)) { -printk ("\nnew hash chain, key: %016Lx tail class: [%px] %s\n" , +pr_info ("\nnew hash chain, key: %016Lx tail class: [%px] %s\n" , (unsigned long long )chain_key, class->key, class->name); }
@@ -2422,17 +2422,17 @@ print_usage_bug_scenario(struct held_lock *lock) {struct lock_class *class =hlock_class (lock); -printk (" Possible unsafe locking scenario:\n\n" ); -printk (" CPU0\n" ); -printk (" ----\n" ); -printk (" lock(" ); +pr_info (" Possible unsafe locking scenario:\n\n" ); +pr_info (" CPU0\n" ); +pr_info (" ----\n" ); +pr_info (" lock(" );__print_lock_name (class);printk (KERN_CONT ");\n" ); -printk (" <Interrupt>\n" ); -printk (" lock(" ); +pr_info (" <Interrupt>\n" ); +pr_info (" lock(" );__print_lock_name (class);printk (KERN_CONT ");\n" ); -printk ("\n *** DEADLOCK ***\n\n" ); +pr_info ("\n *** DEADLOCK ***\n\n" ); } static int
@@ -2605,17 +2605,17 @@ check_usage_backwards(struct task_struct *curr, struct held_lock *this,void print_irqtrace_events (struct task_struct *curr) { -printk ("irq event stamp: %u\n" , curr->irq_events); -printk ("hardirqs last enabled at (%u): [<%px>] %pS\n" , +pr_info ("irq event stamp: %u\n" , curr->irq_events); +pr_info ("hardirqs last enabled at (%u): [<%px>] %pS\n" , curr->hardirq_enable_event, (void *)curr->hardirq_enable_ip, (void *)curr->hardirq_enable_ip); -printk ("hardirqs last disabled at (%u): [<%px>] %pS\n" , +pr_info ("hardirqs last disabled at (%u): [<%px>] %pS\n" , curr->hardirq_disable_event, (void *)curr->hardirq_disable_ip, (void *)curr->hardirq_disable_ip); -printk ("softirqs last enabled at (%u): [<%px>] %pS\n" , +pr_info ("softirqs last enabled at (%u): [<%px>] %pS\n" , curr->softirq_enable_event, (void *)curr->softirq_enable_ip, (void *)curr->softirq_enable_ip); -printk ("softirqs last disabled at (%u): [<%px>] %pS\n" , +pr_info ("softirqs last disabled at (%u): [<%px>] %pS\n" , curr->softirq_disable_event, (void *)curr->softirq_disable_ip, (void *)curr->softirq_disable_ip); }
@@ -3076,7 +3076,7 @@ static int mark_lock(struct task_struct *curr, struct held_lock *this,* We must printk outside of the graph_lock: */ if (ret ==2 ) { -printk ("\nmarked lock as {%s}:\n" , usage_str[new_bit]); +pr_info ("\nmarked lock as {%s}:\n" , usage_str[new_bit]);print_lock (this);print_irqtrace_events (curr);dump_stack ();
@@ -3119,7 +3119,7 @@ static void __lockdep_init_map(struct lockdep_map *lock, const char *name,* Sanity check, the lock-class key must be persistent: */ if (!static_obj (key)) { -printk ("BUG: key %px not in .data!\n" , key); +pr_info ("BUG: key %px not in .data!\n" , key);/* * What it says above ^^^^^, I suggest you read it. */
@@ -3232,7 +3232,7 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,debug_class_ops_inc (class);if (very_verbose (class)) { -printk ("\nacquire class [%px] %s" , class->key, class->name); +pr_info ("\nacquire class [%px] %s" , class->key, class->name);if (class->name_version >1 )printk (KERN_CONT "#%d" , class->name_version);printk (KERN_CONT "\n" );
@@ -3759,11 +3759,11 @@ static void check_flags(unsigned long flags)if (irqs_disabled_flags (flags)) {if (DEBUG_LOCKS_WARN_ON (current->hardirqs_enabled)) { -printk ("possible reason: unannotated irqs-off.\n" ); +pr_info ("possible reason: unannotated irqs-off.\n" ); } }else {if (DEBUG_LOCKS_WARN_ON (!current->hardirqs_enabled)) { -printk ("possible reason: unannotated irqs-on.\n" ); +pr_info ("possible reason: unannotated irqs-on.\n" ); } }
@@ -4258,17 +4258,17 @@ void lockdep_reset_lock(struct lockdep_map *lock)void __init lockdep_init (void ) { -printk ("Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar\n" ); +pr_info ("Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar\n" ); -printk ("... MAX_LOCKDEP_SUBCLASSES: %lu\n" ,MAX_LOCKDEP_SUBCLASSES ); -printk ("... MAX_LOCK_DEPTH: %lu\n" ,MAX_LOCK_DEPTH ); -printk ("... MAX_LOCKDEP_KEYS: %lu\n" ,MAX_LOCKDEP_KEYS ); -printk ("... CLASSHASH_SIZE: %lu\n" ,CLASSHASH_SIZE ); -printk ("... MAX_LOCKDEP_ENTRIES: %lu\n" ,MAX_LOCKDEP_ENTRIES ); -printk ("... MAX_LOCKDEP_CHAINS: %lu\n" ,MAX_LOCKDEP_CHAINS ); -printk ("... CHAINHASH_SIZE: %lu\n" ,CHAINHASH_SIZE ); +pr_info ("... MAX_LOCKDEP_SUBCLASSES: %lu\n" ,MAX_LOCKDEP_SUBCLASSES ); +pr_info ("... MAX_LOCK_DEPTH: %lu\n" ,MAX_LOCK_DEPTH ); +pr_info ("... MAX_LOCKDEP_KEYS: %lu\n" ,MAX_LOCKDEP_KEYS ); +pr_info ("... CLASSHASH_SIZE: %lu\n" ,CLASSHASH_SIZE ); +pr_info ("... MAX_LOCKDEP_ENTRIES: %lu\n" ,MAX_LOCKDEP_ENTRIES ); +pr_info ("... MAX_LOCKDEP_CHAINS: %lu\n" ,MAX_LOCKDEP_CHAINS ); +pr_info ("... CHAINHASH_SIZE: %lu\n" ,CHAINHASH_SIZE ); - printk(" memory used by lock dependency info: %lu kB\n", + pr_info(" memory used by lock dependency info: %lu kB\n", (sizeof(struct lock_class) * MAX_LOCKDEP_KEYS + sizeof(struct list_head) * CLASSHASH_SIZE + sizeof(struct lock_list) * MAX_LOCKDEP_ENTRIES +
@@ -4280,7 +4280,7 @@ void __init lockdep_init(void) ) / 1024 ); -printk (" per task-struct memory footprint: %lu bytes\n" , +pr_info (" per task-struct memory footprint: %lu bytes\n" ,sizeof (struct held_lock ) *MAX_LOCK_DEPTH ); }
@@ -4403,7 +4403,7 @@ EXPORT_SYMBOL_GPL(debug_show_all_locks);void debug_show_held_locks (struct task_struct *task) {if (unlikely (!debug_locks)) { -printk ("INFO: lockdep is turned off.\n" ); +pr_info ("INFO: lockdep is turned off.\n" );return ; }lockdep_print_held_locks (task);
Signature · 1 line
2.7.4
Quoted 12 lines · Corentin Labbe
While working on detector of new warn/err/crit/... messages, I found that the following messages was printed with the warn loglevel:
[ 0.001607] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [ 0.001625] ... MAX_LOCKDEP_SUBCLASSES: 8 [ 0.001641] ... MAX_LOCK_DEPTH: 48 [ 0.001658] ... MAX_LOCKDEP_KEYS: 8191 [ 0.001673] ... CLASSHASH_SIZE: 4096 [ 0.001689] ... MAX_LOCKDEP_ENTRIES: 32768 [ 0.001704] ... MAX_LOCKDEP_CHAINS: 65536 [ 0.001719] ... CHAINHASH_SIZE: 32768 [ 0.001735] memory used by lock dependency info: 4623 kB
Quoted 1 line
While the cause is still unknown to me, converting printk to
pr_infofixed the issue.
because in lib/Kconfig.debug
config MESSAGE_LOGLEVEL_DEFAULT
int "Default message log level (1-7)"
range 1 7
default "4"
help
Default log level for printk statements with no specified priority.
This was hard-coded to KERN_WARNING since at least 2.6.10 but folks that are auditing their logs closely may want to set it to a lower priority.