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. Signed-off-by: Corentin Labbe <[email protected]> --- kernel/locking/lockdep.c | 152 +++++++++++++++++++++++------------------------ 1 file changed, 76 insertions(+), 76 deletions(-) diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c index 1efada2..9454597 100644 --- a/kernel/locking/lockdep.c +++ b/kernel/locking/lockdep.c @@ -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_ne int 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); -- 2.7.4
