>From 93930c92c664d8b834e1e04b92c00023626fc07a Mon Sep 17 00:00:00 2001 From: Jan Kara Date: Thu, 19 Jun 2014 15:36:09 +0200 Subject: [PATCH] lockdep: Dump info via tracing Signed-off-by: Jan Kara --- kernel/locking/lockdep.c | 707 +++++++++++++++++++++++++++-------------------- 1 file changed, 402 insertions(+), 305 deletions(-) diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c index d24e4339b46d..b15e7dec55f6 100644 --- a/kernel/locking/lockdep.c +++ b/kernel/locking/lockdep.c @@ -77,6 +77,26 @@ module_param(lock_stat, int, 0644); */ static arch_spinlock_t lockdep_lock = (arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED; +static void sprint_ip_sym(char *buf, unsigned long ip) +{ + sprintf(buf, "[<%p>] %pS\n", (void *) ip, (void *) ip); +} + +static void trace_print_stack_trace(struct stack_trace *trace, int spaces) +{ + int i, n; + char buf[256]; + + if (!trace->entries) + return; + + for (i = 0; i < trace->nr_entries; i++) { + n = sprintf(buf, "%*c", 1 + spaces, ' '); + sprint_ip_sym(buf + n, trace->entries[i]); + trace_printk(buf); + } +} + static int graph_lock(void) { arch_spin_lock(&lockdep_lock); @@ -382,9 +402,9 @@ static unsigned long stack_trace[MAX_STACK_TRACE_ENTRIES]; static void print_lockdep_off(const char *bug_msg) { - printk(KERN_DEBUG "%s\n", bug_msg); - printk(KERN_DEBUG "turning off the locking correctness validator.\n"); - printk(KERN_DEBUG "Please attach the output of /proc/lock_stat to the bug report\n"); + trace_printk("%s\n", bug_msg); + trace_printk("turning off the locking correctness validator.\n"); + trace_printk("Please attach the output of /proc/lock_stat to the bug report\n"); } static int save_trace(struct stack_trace *trace) @@ -417,7 +437,7 @@ static int save_trace(struct stack_trace *trace) return 0; print_lockdep_off("BUG: MAX_STACK_TRACE_ENTRIES too low!"); - dump_stack(); + trace_dump_stack(0); return 0; } @@ -506,7 +526,7 @@ void get_usage_chars(struct lock_class *class, char usage[LOCK_USAGE_CHARS]) usage[i] = '\0'; } -static void __print_lock_name(struct lock_class *class) +static void __sprint_lock_name(char *buf, struct lock_class *class) { char str[KSYM_NAME_LEN]; const char *name; @@ -514,28 +534,28 @@ static void __print_lock_name(struct lock_class *class) name = class->name; if (!name) { name = __get_key_name(class->key, str); - printk("%s", name); + strcpy(buf, name); } else { - printk("%s", name); + strcpy(buf, name); if (class->name_version > 1) - printk("#%d", class->name_version); + sprintf(buf + strlen(buf), "#%d", class->name_version); if (class->subclass) - printk("/%d", class->subclass); + sprintf(buf + strlen(buf), "/%d", class->subclass); } } -static void print_lock_name(struct lock_class *class) +static void sprint_lock_name(char *buf, struct lock_class *class) { char usage[LOCK_USAGE_CHARS]; get_usage_chars(class, usage); - printk(" ("); - __print_lock_name(class); - printk("){%s}", usage); + strcpy(buf, " ("); + __sprint_lock_name(buf, class); + sprintf(buf + strlen(buf), "){%s}", usage); } -static void print_lockdep_cache(struct lockdep_map *lock) +static void sprint_lockdep_cache(char *buf, struct lockdep_map *lock) { const char *name; char str[KSYM_NAME_LEN]; @@ -544,14 +564,14 @@ static void print_lockdep_cache(struct lockdep_map *lock) if (!name) name = __get_key_name(lock->key->subkeys, str); - printk("%s", name); + strcpy(buf, name); } -static void print_lock(struct held_lock *hlock) +static void sprint_lock(char *buf, struct held_lock *hlock) { - print_lock_name(hlock_class(hlock)); - printk(", at: "); - print_ip_sym(hlock->acquire_ip); + sprint_lock_name(buf, hlock_class(hlock)); + strcat(buf, ", at: "); + sprint_ip_sym(buf + strlen(buf), hlock->acquire_ip); } static void lockdep_print_held_locks(struct task_struct *curr) @@ -559,21 +579,24 @@ static void lockdep_print_held_locks(struct task_struct *curr) int i, depth = curr->lockdep_depth; if (!depth) { - printk("no locks held by %s/%d.\n", curr->comm, task_pid_nr(curr)); + trace_printk("no locks held by %s/%d.\n", curr->comm, task_pid_nr(curr)); return; } - printk("%d lock%s held by %s/%d:\n", + trace_printk("%d lock%s held by %s/%d:\n", depth, depth > 1 ? "s" : "", curr->comm, task_pid_nr(curr)); for (i = 0; i < depth; i++) { - printk(" #%d: ", i); - print_lock(curr->held_locks + i); + char buf[256]; + + sprintf(buf, " #%d: ", i); + sprint_lock(buf + strlen(buf), curr->held_locks + i); + trace_printk(buf); } } static void print_kernel_ident(void) { - printk("%s %.*s %s\n", init_utsname()->release, + trace_printk("%s %.*s %s\n", init_utsname()->release, (int)strcspn(init_utsname()->version, " "), init_utsname()->version, print_tainted()); @@ -669,11 +692,11 @@ look_up_lock_class(struct lockdep_map *lock, unsigned int subclass) if (unlikely(subclass >= MAX_LOCKDEP_SUBCLASSES)) { debug_locks_off(); - printk(KERN_ERR + trace_printk( "BUG: looking up invalid subclass: %u\n", subclass); - printk(KERN_ERR + trace_printk(KERN_ERR "turning off the locking correctness validator.\n"); - dump_stack(); + trace_dump_stack(0); return NULL; } @@ -737,10 +760,10 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force) */ if (!static_obj(lock->key)) { debug_locks_off(); - printk("INFO: trying to register non-static key.\n"); - printk("the code is fine but needs lockdep annotation.\n"); - printk("turning off the locking correctness validator.\n"); - dump_stack(); + trace_printk("INFO: trying to register non-static key.\n"); + trace_printk("the code is fine but needs lockdep annotation.\n"); + trace_printk("turning off the locking correctness validator.\n"); + trace_dump_stack(0); return NULL; } @@ -772,7 +795,7 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force) raw_local_irq_restore(flags); print_lockdep_off("BUG: MAX_LOCKDEP_KEYS too low!"); - dump_stack(); + trace_dump_stack(0); return NULL; } class = lock_classes + nr_lock_classes++; @@ -798,11 +821,11 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force) graph_unlock(); raw_local_irq_restore(flags); - printk("\nnew class %p: %s", class->key, class->name); + trace_printk("\nnew class %p: %s", class->key, class->name); if (class->name_version > 1) - printk("#%d", class->name_version); - printk("\n"); - dump_stack(); + trace_printk("#%d", class->name_version); + trace_printk("\n"); + trace_dump_stack(0); raw_local_irq_save(flags); if (!graph_lock()) { @@ -842,7 +865,7 @@ static struct lock_list *alloc_list_entry(void) return NULL; print_lockdep_off("BUG: MAX_LOCKDEP_ENTRIES too low!"); - dump_stack(); + trace_dump_stack(0); return NULL; } return list_entries + nr_list_entries++; @@ -1078,12 +1101,15 @@ static inline int __bfs_backwards(struct lock_list *src_entry, static noinline int print_circular_bug_entry(struct lock_list *target, int depth) { + char buf[256]; + if (debug_locks_silent) return 0; - printk("\n-> #%u", depth); - print_lock_name(target->class); - printk(":\n"); - print_stack_trace(&target->trace, 6); + sprintf(buf, "\n-> #%u", depth); + sprint_lock_name(buf + strlen(buf), target->class); + strcat(buf, ":\n"); + trace_printk(buf); + trace_print_stack_trace(&target->trace, 6); return 0; } @@ -1096,6 +1122,7 @@ print_circular_lock_scenario(struct held_lock *src, struct lock_class *source = hlock_class(src); struct lock_class *target = hlock_class(tgt); struct lock_class *parent = prt->class; + char buf[256]; /* * A direct locking problem where unsafe_class lock is taken @@ -1111,31 +1138,36 @@ 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 "); - __print_lock_name(source); - printk(" --> "); - __print_lock_name(parent); - printk(" --> "); - __print_lock_name(target); - printk("\n\n"); + trace_printk("Chain exists of:\n "); + __sprint_lock_name(buf, source); + strcat(buf, " --> "); + __sprint_lock_name(buf + strlen(buf), parent); + strcat(buf, " --> "); + __sprint_lock_name(buf + strlen(buf), target); + strcat(buf, "\n\n"); + trace_printk(buf); } - printk(" Possible unsafe locking scenario:\n\n"); - printk(" CPU0 CPU1\n"); - printk(" ---- ----\n"); - printk(" lock("); - __print_lock_name(target); - printk(");\n"); - printk(" lock("); - __print_lock_name(parent); - printk(");\n"); - printk(" lock("); - __print_lock_name(target); - printk(");\n"); - printk(" lock("); - __print_lock_name(source); - printk(");\n"); - printk("\n *** DEADLOCK ***\n\n"); + trace_printk(" Possible unsafe locking scenario:\n\n"); + trace_printk(" CPU0 CPU1\n"); + trace_printk(" ---- ----\n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), target); + strcat(buf, ");\n"); + trace_printk(buf); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), parent); + strcat(buf, ");\n"); + trace_printk(buf); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), target); + strcat(buf, ");\n"); + trace_printk(buf); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), source); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk("\n *** DEADLOCK ***\n\n"); } /* @@ -1148,22 +1180,25 @@ print_circular_bug_header(struct lock_list *entry, unsigned int depth, struct held_lock *check_tgt) { struct task_struct *curr = current; + char buf[256]; if (debug_locks_silent) return 0; - printk("\n"); - printk("======================================================\n"); - printk("[ INFO: possible circular locking dependency detected ]\n"); + trace_printk("\n"); + trace_printk("======================================================\n"); + trace_printk("[ INFO: possible circular locking dependency detected ]\n"); print_kernel_ident(); - printk("-------------------------------------------------------\n"); - printk("%s/%d is trying to acquire lock:\n", + trace_printk("-------------------------------------------------------\n"); + sprintf(buf, "%s/%d is trying to acquire lock:\n", curr->comm, task_pid_nr(curr)); - print_lock(check_src); - printk("\nbut task is already holding lock:\n"); - print_lock(check_tgt); - printk("\nwhich lock already depends on the new lock.\n\n"); - printk("\nthe existing dependency chain (in reverse order) is:\n"); + sprint_lock(buf + strlen(buf), check_src); + trace_printk(buf); + trace_printk("\nbut task is already holding lock:\n"); + sprint_lock(buf, check_tgt); + trace_printk(buf); + trace_printk("\nwhich lock already depends on the new lock.\n\n"); + trace_printk("\nthe existing dependency chain (in reverse order) is:\n"); print_circular_bug_entry(entry, depth); @@ -1203,14 +1238,14 @@ 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"); + trace_printk("\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"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -1367,25 +1402,28 @@ find_usage_backwards(struct lock_list *root, enum lock_usage_bit bit, static void print_lock_class_header(struct lock_class *class, int depth) { int bit; + char buf[256]; - printk("%*s->", depth, ""); - print_lock_name(class); - printk(" ops: %lu", class->ops); - printk(" {\n"); + sprintf(buf, "%*s->", depth, ""); + sprint_lock_name(buf + strlen(buf), class); + sprintf(buf + strlen(buf), " ops: %lu {\n", class->ops); + trace_printk(buf); for (bit = 0; bit < LOCK_USAGE_STATES; bit++) { if (class->usage_mask & (1 << bit)) { int len = depth; - len += printk("%*s %s", depth, "", usage_str[bit]); - len += printk(" at:\n"); - print_stack_trace(class->usage_traces + bit, len); + len += sprintf(buf, "%*s %s", depth, "", usage_str[bit]); + len += sprintf(buf + strlen(buf), " at:\n"); + trace_printk(buf); + trace_print_stack_trace(class->usage_traces + bit, len); } } - printk("%*s }\n", depth, ""); + trace_printk("%*s }\n", depth, ""); - printk("%*s ... key at: ",depth,""); - print_ip_sym((unsigned long)class->key); + sprintf(buf, "%*s ... key at: ",depth,""); + sprint_ip_sym(buf + strlen(buf), (unsigned long)class->key); + trace_printk(buf); } /* @@ -1403,12 +1441,12 @@ print_shortest_lock_dependencies(struct lock_list *leaf, do { print_lock_class_header(entry->class, depth); - printk("%*s ... acquired at:\n", depth, ""); - print_stack_trace(&entry->trace, 2); - printk("\n"); + trace_printk("%*s ... acquired at:\n", depth, ""); + trace_print_stack_trace(&entry->trace, 2); + trace_printk("\n"); if (depth == 0 && (entry != root)) { - printk("lockdep:%s bad path found in chain graph\n", __func__); + trace_printk("lockdep:%s bad path found in chain graph\n", __func__); break; } @@ -1428,6 +1466,7 @@ print_irq_lock_scenario(struct lock_list *safe_entry, struct lock_class *safe_class = safe_entry->class; struct lock_class *unsafe_class = unsafe_entry->class; struct lock_class *middle_class = prev_class; + char buf[256]; if (middle_class == safe_class) middle_class = next_class; @@ -1446,33 +1485,39 @@ 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 "); - __print_lock_name(safe_class); - printk(" --> "); - __print_lock_name(middle_class); - printk(" --> "); - __print_lock_name(unsafe_class); - printk("\n\n"); + trace_printk("Chain exists of:\n"); + strcpy(buf, " "); + __sprint_lock_name(buf + strlen(buf), safe_class); + strcat(buf, " --> "); + __sprint_lock_name(buf + strlen(buf), middle_class); + strcat(buf, " --> "); + __sprint_lock_name(buf + strlen(buf), unsafe_class); + strcat(buf, "\n\n"); + trace_printk(buf); } - printk(" Possible interrupt unsafe locking scenario:\n\n"); - printk(" CPU0 CPU1\n"); - printk(" ---- ----\n"); - printk(" lock("); - __print_lock_name(unsafe_class); - printk(");\n"); - printk(" local_irq_disable();\n"); - printk(" lock("); - __print_lock_name(safe_class); - printk(");\n"); - printk(" lock("); - __print_lock_name(middle_class); - printk(");\n"); - printk(" \n"); - printk(" lock("); - __print_lock_name(safe_class); - printk(");\n"); - printk("\n *** DEADLOCK ***\n\n"); + trace_printk(" Possible interrupt unsafe locking scenario:\n\n"); + trace_printk(" CPU0 CPU1\n"); + trace_printk(" ---- ----\n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), unsafe_class); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk(" local_irq_disable();\n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), safe_class); + strcat(buf, ");\n"); + trace_printk(buf); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), middle_class); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk(" \n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), safe_class); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk("\n *** DEADLOCK ***\n\n"); } static int @@ -1487,65 +1532,74 @@ print_bad_irq_dependency(struct task_struct *curr, enum lock_usage_bit bit2, const char *irqclass) { + char buf[256]; + if (!debug_locks_off_graph_unlock() || debug_locks_silent) return 0; - printk("\n"); - printk("======================================================\n"); - printk("[ INFO: %s-safe -> %s-unsafe lock order detected ]\n", + trace_printk("\n"); + trace_printk("======================================================\n"); + trace_printk("[ INFO: %s-safe -> %s-unsafe lock order detected ]\n", irqclass, irqclass); print_kernel_ident(); - printk("------------------------------------------------------\n"); - printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] is trying to acquire:\n", + trace_printk("------------------------------------------------------\n"); + trace_printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] is trying to acquire:\n", curr->comm, task_pid_nr(curr), curr->hardirq_context, hardirq_count() >> HARDIRQ_SHIFT, curr->softirq_context, softirq_count() >> SOFTIRQ_SHIFT, curr->hardirqs_enabled, curr->softirqs_enabled); - print_lock(next); - - printk("\nand this task is already holding:\n"); - print_lock(prev); - printk("which would create a new lock dependency:\n"); - print_lock_name(hlock_class(prev)); - printk(" ->"); - print_lock_name(hlock_class(next)); - printk("\n"); - - printk("\nbut this new dependency connects a %s-irq-safe lock:\n", + sprint_lock(buf, next); + trace_printk(buf); + + trace_printk("\nand this task is already holding:\n"); + sprint_lock(buf, prev); + trace_printk(buf); + trace_printk("which would create a new lock dependency:\n"); + sprint_lock_name(buf, hlock_class(prev)); + strcat(buf, " ->"); + sprint_lock_name(buf + strlen(buf), hlock_class(next)); + strcat(buf, "\n"); + trace_printk(buf); + + trace_printk("\nbut this new dependency connects a %s-irq-safe lock:\n", irqclass); - print_lock_name(backwards_entry->class); - printk("\n... which became %s-irq-safe at:\n", irqclass); + sprint_lock_name(buf, backwards_entry->class); + strcat(buf, "\n"); + trace_printk(buf); + trace_printk("... which became %s-irq-safe at:\n", irqclass); - print_stack_trace(backwards_entry->class->usage_traces + bit1, 1); + trace_print_stack_trace(backwards_entry->class->usage_traces + bit1, 1); - printk("\nto a %s-irq-unsafe lock:\n", irqclass); - print_lock_name(forwards_entry->class); - printk("\n... which became %s-irq-unsafe at:\n", irqclass); - printk("..."); + trace_printk("\nto a %s-irq-unsafe lock:\n", irqclass); + sprint_lock_name(buf, forwards_entry->class); + strcat(buf, "\n"); + trace_printk(buf); + trace_printk("... which became %s-irq-unsafe at:\n", irqclass); + trace_printk("..."); - print_stack_trace(forwards_entry->class->usage_traces + bit2, 1); + trace_print_stack_trace(forwards_entry->class->usage_traces + bit2, 1); - printk("\nother info that might help us debug this:\n\n"); + trace_printk("\nother info that might help us debug this:\n\n"); print_irq_lock_scenario(backwards_entry, forwards_entry, hlock_class(prev), hlock_class(next)); lockdep_print_held_locks(curr); - printk("\nthe dependencies between %s-irq-safe lock", irqclass); - printk(" and the holding lock:\n"); + trace_printk("\nthe dependencies between %s-irq-safe lock", irqclass); + trace_printk(" and the holding lock:\n"); if (!save_trace(&prev_root->trace)) return 0; print_shortest_lock_dependencies(backwards_entry, prev_root); - printk("\nthe dependencies between the lock to be acquired"); - printk(" and %s-irq-unsafe lock:\n", irqclass); + trace_printk("\nthe dependencies between the lock to be acquired"); + trace_printk(" and %s-irq-unsafe lock:\n", irqclass); if (!save_trace(&next_root->trace)) return 0; print_shortest_lock_dependencies(forwards_entry, next_root); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -1699,44 +1753,51 @@ 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("); - __print_lock_name(prev); - printk(");\n"); - printk(" lock("); - __print_lock_name(next); - printk(");\n"); - printk("\n *** DEADLOCK ***\n\n"); - printk(" May be due to missing lock nesting notation\n\n"); + char buf[256]; + + trace_printk(" Possible unsafe locking scenario:\n\n"); + trace_printk(" CPU0\n"); + trace_printk(" ----\n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), prev); + strcat(buf, ");\n"); + trace_printk(buf); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), next); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk("\n *** DEADLOCK ***\n\n"); + trace_printk(" May be due to missing lock nesting notation\n\n"); } static int print_deadlock_bug(struct task_struct *curr, struct held_lock *prev, struct held_lock *next) { + char buf[256]; + if (!debug_locks_off_graph_unlock() || debug_locks_silent) return 0; - printk("\n"); - printk("=============================================\n"); - printk("[ INFO: possible recursive locking detected ]\n"); + trace_printk("\n"); + trace_printk("=============================================\n"); + trace_printk("[ INFO: possible recursive locking detected ]\n"); print_kernel_ident(); - printk("---------------------------------------------\n"); - printk("%s/%d is trying to acquire lock:\n", + trace_printk("---------------------------------------------\n"); + trace_printk("%s/%d is trying to acquire lock:\n", curr->comm, task_pid_nr(curr)); - print_lock(next); - printk("\nbut task is already holding lock:\n"); - print_lock(prev); + sprint_lock(buf, next); + trace_printk(buf); + trace_printk("\nbut task is already holding lock:\n"); + sprint_lock(buf, prev); + trace_printk(buf); - printk("\nother info that might help us debug this:\n"); + trace_printk("\nother info that might help us debug this:\n"); print_deadlock_scenario(next, prev); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -1894,13 +1955,16 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev, * Debugging printouts: */ if (verbose(hlock_class(prev)) || verbose(hlock_class(next))) { + char buf[256]; + graph_unlock(); - printk("\n new dependency: "); - print_lock_name(hlock_class(prev)); - printk(" => "); - print_lock_name(hlock_class(next)); - printk("\n"); - dump_stack(); + strcpy(buf, "\n new dependency: "); + sprint_lock_name(buf + strlen(buf), hlock_class(prev)); + strcat(buf, " => "); + sprint_lock_name(buf + strlen(buf), hlock_class(next)); + strcat(buf, "\n"); + trace_printk(buf); + trace_dump_stack(0); return graph_lock(); } return 1; @@ -2025,7 +2089,7 @@ static inline int lookup_chain_cache(struct task_struct *curr, cache_hit: debug_atomic_inc(chain_lookup_hits); if (very_verbose(class)) - printk("\nhash chain already cached, key: " + trace_printk("\nhash chain already cached, key: " "%016Lx tail class: [%p] %s\n", (unsigned long long)chain_key, class->key, class->name); @@ -2033,7 +2097,7 @@ cache_hit: } } if (very_verbose(class)) - printk("\nnew hash chain, key: %016Lx tail class: [%p] %s\n", + trace_printk("\nnew hash chain, key: %016Lx tail class: [%p] %s\n", (unsigned long long)chain_key, class->key, class->name); /* * Allocate a new chain entry from the static array, and add @@ -2055,7 +2119,7 @@ cache_hit: return 0; print_lockdep_off("BUG: MAX_LOCKDEP_CHAINS too low!"); - dump_stack(); + trace_dump_stack(0); return 0; } chain = lock_chains + nr_lock_chains++; @@ -2203,55 +2267,61 @@ static void 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("); - __print_lock_name(class); - printk(");\n"); - printk(" \n"); - printk(" lock("); - __print_lock_name(class); - printk(");\n"); - printk("\n *** DEADLOCK ***\n\n"); + char buf[256]; + + trace_printk(" Possible unsafe locking scenario:\n\n"); + trace_printk(" CPU0\n"); + trace_printk(" ----\n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), class); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk(" \n"); + strcpy(buf, " lock("); + __sprint_lock_name(buf + strlen(buf), class); + strcat(buf, ");\n"); + trace_printk(buf); + trace_printk("\n *** DEADLOCK ***\n\n"); } static int print_usage_bug(struct task_struct *curr, struct held_lock *this, enum lock_usage_bit prev_bit, enum lock_usage_bit new_bit) { + char buf[256]; + if (!debug_locks_off_graph_unlock() || debug_locks_silent) return 0; - printk("\n"); - printk("=================================\n"); - printk("[ INFO: inconsistent lock state ]\n"); + trace_printk("\n"); + trace_printk("=================================\n"); + trace_printk("[ INFO: inconsistent lock state ]\n"); print_kernel_ident(); - printk("---------------------------------\n"); + trace_printk("---------------------------------\n"); - printk("inconsistent {%s} -> {%s} usage.\n", + trace_printk("inconsistent {%s} -> {%s} usage.\n", usage_str[prev_bit], usage_str[new_bit]); - printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] takes:\n", + trace_printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] takes:\n", curr->comm, task_pid_nr(curr), trace_hardirq_context(curr), hardirq_count() >> HARDIRQ_SHIFT, trace_softirq_context(curr), softirq_count() >> SOFTIRQ_SHIFT, trace_hardirqs_enabled(curr), trace_softirqs_enabled(curr)); - print_lock(this); + sprint_lock(buf, this); + trace_printk(buf); - printk("{%s} state was registered at:\n", usage_str[prev_bit]); - print_stack_trace(hlock_class(this)->usage_traces + prev_bit, 1); + trace_printk("{%s} state was registered at:\n", usage_str[prev_bit]); + trace_print_stack_trace(hlock_class(this)->usage_traces + prev_bit, 1); print_irqtrace_events(curr); - printk("\nother info that might help us debug this:\n"); + trace_printk("\nother info that might help us debug this:\n"); print_usage_bug_scenario(this); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -2285,32 +2355,36 @@ print_irq_inversion_bug(struct task_struct *curr, struct lock_list *entry = other; struct lock_list *middle = NULL; int depth; + char buf[256]; if (!debug_locks_off_graph_unlock() || debug_locks_silent) return 0; - printk("\n"); - printk("=========================================================\n"); - printk("[ INFO: possible irq lock inversion dependency detected ]\n"); + trace_printk("\n"); + trace_printk("=========================================================\n"); + trace_printk("[ INFO: possible irq lock inversion dependency detected ]\n"); print_kernel_ident(); - printk("---------------------------------------------------------\n"); - printk("%s/%d just changed the state of lock:\n", + trace_printk("---------------------------------------------------------\n"); + trace_printk("%s/%d just changed the state of lock:\n", curr->comm, task_pid_nr(curr)); - print_lock(this); + sprint_lock(buf, this); + trace_printk(buf); if (forwards) - printk("but this lock took another, %s-unsafe lock in the past:\n", irqclass); + trace_printk("but this lock took another, %s-unsafe lock in the past:\n", irqclass); else - printk("but this lock was taken by another, %s-safe lock in the past:\n", irqclass); - print_lock_name(other->class); - printk("\n\nand interrupts could create inverse lock ordering between them.\n\n"); + trace_printk("but this lock was taken by another, %s-safe lock in the past:\n", irqclass); + sprint_lock_name(buf, other->class); + strcat(buf, "\n"); + trace_printk(buf); + trace_printk("\nand interrupts could create inverse lock ordering between them.\n\n"); - printk("\nother info that might help us debug this:\n"); + trace_printk("\nother info that might help us debug this:\n"); /* Find a middle lock (if one exists) */ depth = get_lock_depth(other); do { if (depth == 0 && (entry != root)) { - printk("lockdep:%s bad path found in chain graph\n", __func__); + trace_printk("lockdep:%s bad path found in chain graph\n", __func__); break; } middle = entry; @@ -2326,13 +2400,13 @@ print_irq_inversion_bug(struct task_struct *curr, lockdep_print_held_locks(curr); - printk("\nthe shortest dependencies between 2nd lock and 1st lock:\n"); + trace_printk("\nthe shortest dependencies between 2nd lock and 1st lock:\n"); if (!save_trace(&root->trace)) return 0; print_shortest_lock_dependencies(other, root); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -2387,15 +2461,21 @@ 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): ", curr->hardirq_enable_event); - print_ip_sym(curr->hardirq_enable_ip); - printk("hardirqs last disabled at (%u): ", curr->hardirq_disable_event); - print_ip_sym(curr->hardirq_disable_ip); - printk("softirqs last enabled at (%u): ", curr->softirq_enable_event); - print_ip_sym(curr->softirq_enable_ip); - printk("softirqs last disabled at (%u): ", curr->softirq_disable_event); - print_ip_sym(curr->softirq_disable_ip); + char buf[256]; + + trace_printk("irq event stamp: %u\n", curr->irq_events); + sprintf(buf, "hardirqs last enabled at (%u): ", curr->hardirq_enable_event); + sprint_ip_sym(buf + strlen(buf), curr->hardirq_enable_ip); + trace_printk(buf); + sprintf(buf, "hardirqs last disabled at (%u): ", curr->hardirq_disable_event); + sprint_ip_sym(buf + strlen(buf), curr->hardirq_disable_ip); + trace_printk(buf); + sprintf(buf, "softirqs last enabled at (%u): ", curr->softirq_enable_event); + sprint_ip_sym(buf + strlen(buf), curr->softirq_enable_ip); + trace_printk(buf); + sprintf(buf, "softirqs last disabled at (%u): ", curr->softirq_disable_event); + sprint_ip_sym(buf + strlen(buf), curr->softirq_disable_ip); + trace_printk(buf); } static int HARDIRQ_verbose(struct lock_class *class) @@ -2937,10 +3017,13 @@ 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]); - print_lock(this); + char buf[256]; + + trace_printk("\nmarked lock as {%s}:\n", usage_str[new_bit]); + sprint_lock(buf, this); + trace_printk(buf); print_irqtrace_events(curr); - dump_stack(); + trace_dump_stack(0); } return ret; @@ -2982,7 +3065,7 @@ 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 %p not in .data!\n", key); + trace_printk("BUG: key %p not in .data!\n", key); /* * What it says above ^^^^^, I suggest you read it. */ @@ -3007,31 +3090,34 @@ print_lock_nested_lock_not_held(struct task_struct *curr, struct held_lock *hlock, unsigned long ip) { + char buf[256]; + if (!debug_locks_off()) return 0; if (debug_locks_silent) return 0; - printk("\n"); - printk("==================================\n"); - printk("[ BUG: Nested lock was not taken ]\n"); + trace_printk("\n"); + trace_printk("==================================\n"); + trace_printk("[ BUG: Nested lock was not taken ]\n"); print_kernel_ident(); - printk("----------------------------------\n"); + trace_printk("----------------------------------\n"); - printk("%s/%d is trying to lock:\n", curr->comm, task_pid_nr(curr)); - print_lock(hlock); + trace_printk("%s/%d is trying to lock:\n", curr->comm, task_pid_nr(curr)); + sprint_lock(buf, hlock); + trace_printk(buf); - printk("\nbut this task is not holding:\n"); - printk("%s\n", hlock->nest_lock->name); + trace_printk("\nbut this task is not holding:\n"); + trace_printk("%s\n", hlock->nest_lock->name); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); - printk("\nother info that might help us debug this:\n"); + trace_printk("\nother info that might help us debug this:\n"); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -3081,11 +3167,11 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass, } atomic_inc((atomic_t *)&class->ops); if (very_verbose(class)) { - printk("\nacquire class [%p] %s", class->key, class->name); + trace_printk("\nacquire class [%p] %s", class->key, class->name); if (class->name_version > 1) - printk("#%d", class->name_version); - printk("\n"); - dump_stack(); + trace_printk("#%d", class->name_version); + trace_printk("\n"); + trace_dump_stack(0); } /* @@ -3192,12 +3278,12 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass, if (unlikely(curr->lockdep_depth >= MAX_LOCK_DEPTH)) { debug_locks_off(); print_lockdep_off("BUG: MAX_LOCK_DEPTH too low!"); - printk(KERN_DEBUG "depth: %i max: %lu!\n", + trace_printk("depth: %i max: %lu!\n", curr->lockdep_depth, MAX_LOCK_DEPTH); lockdep_print_held_locks(current); debug_show_all_locks(); - dump_stack(); + trace_dump_stack(0); return 0; } @@ -3212,27 +3298,31 @@ static int print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock, unsigned long ip) { + char buf[256]; + if (!debug_locks_off()) return 0; if (debug_locks_silent) return 0; - printk("\n"); - printk("=====================================\n"); - printk("[ BUG: bad unlock balance detected! ]\n"); + trace_printk("\n"); + trace_printk("=====================================\n"); + trace_printk("[ BUG: bad unlock balance detected! ]\n"); print_kernel_ident(); - printk("-------------------------------------\n"); - printk("%s/%d is trying to release lock (", + trace_printk("-------------------------------------\n"); + sprintf(buf, "%s/%d is trying to release lock (", curr->comm, task_pid_nr(curr)); - print_lockdep_cache(lock); - printk(") at:\n"); - print_ip_sym(ip); - printk("but there are no more locks to release!\n"); - printk("\nother info that might help us debug this:\n"); + sprint_lockdep_cache(buf + strlen(buf), lock); + strcat(buf, ") at:\n"); + trace_printk(buf); + sprint_ip_sym(buf, ip); + trace_printk(buf); + trace_printk("but there are no more locks to release!\n"); + trace_printk("\nother info that might help us debug this:\n"); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -3532,11 +3622,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"); + trace_printk("possible reason: unannotated irqs-off.\n"); } } else { if (DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled)) { - printk("possible reason: unannotated irqs-on.\n"); + trace_printk("possible reason: unannotated irqs-on.\n"); } } @@ -3657,27 +3747,31 @@ static int print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock, unsigned long ip) { + char buf[256]; + if (!debug_locks_off()) return 0; if (debug_locks_silent) return 0; - printk("\n"); - printk("=================================\n"); - printk("[ BUG: bad contention detected! ]\n"); + trace_printk("\n"); + trace_printk("=================================\n"); + trace_printk("[ BUG: bad contention detected! ]\n"); print_kernel_ident(); - printk("---------------------------------\n"); - printk("%s/%d is trying to contend lock (", + trace_printk("---------------------------------\n"); + sprintf(buf, "%s/%d is trying to contend lock (", curr->comm, task_pid_nr(curr)); - print_lockdep_cache(lock); - printk(") at:\n"); - print_ip_sym(ip); - printk("but there are no locks held!\n"); - printk("\nother info that might help us debug this:\n"); + sprint_lockdep_cache(buf + strlen(buf), lock); + strcat(buf, ") at:\n"); + trace_printk(buf); + sprint_ip_sym(buf, ip); + trace_printk(buf); + trace_printk("but there are no locks held!\n"); + trace_printk("\nother info that might help us debug this:\n"); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); return 0; } @@ -4033,23 +4127,26 @@ static void print_freed_lock_bug(struct task_struct *curr, const void *mem_from, const void *mem_to, struct held_lock *hlock) { + char buf[256]; + if (!debug_locks_off()) return; if (debug_locks_silent) return; - printk("\n"); - printk("=========================\n"); - printk("[ BUG: held lock freed! ]\n"); + trace_printk("\n"); + trace_printk("=========================\n"); + trace_printk("[ BUG: held lock freed! ]\n"); print_kernel_ident(); - printk("-------------------------\n"); - printk("%s/%d is freeing memory %p-%p, with a lock still held there!\n", + trace_printk("-------------------------\n"); + trace_printk("%s/%d is freeing memory %p-%p, with a lock still held there!\n", curr->comm, task_pid_nr(curr), mem_from, mem_to-1); - print_lock(hlock); + sprint_lock(buf, hlock); + trace_printk(buf); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); } static inline int not_in_range(const void* mem_from, unsigned long mem_len, @@ -4096,15 +4193,15 @@ static void print_held_locks_bug(void) if (debug_locks_silent) return; - printk("\n"); - printk("=====================================\n"); - printk("[ BUG: %s/%d still has locks held! ]\n", + trace_printk("\n"); + trace_printk("=====================================\n"); + trace_printk("[ BUG: %s/%d still has locks held! ]\n", current->comm, task_pid_nr(current)); print_kernel_ident(); - printk("-------------------------------------\n"); + trace_printk("-------------------------------------\n"); lockdep_print_held_locks(current); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); } void debug_check_no_locks_held(void) @@ -4195,12 +4292,12 @@ asmlinkage __visible void lockdep_sys_exit(void) if (unlikely(curr->lockdep_depth)) { if (!debug_locks_off()) return; - printk("\n"); - printk("================================================\n"); - printk("[ BUG: lock held when returning to user space! ]\n"); + trace_printk("\n"); + trace_printk("================================================\n"); + trace_printk("[ BUG: lock held when returning to user space! ]\n"); print_kernel_ident(); - printk("------------------------------------------------\n"); - printk("%s/%d is leaving the kernel with locks still held!\n", + trace_printk("------------------------------------------------\n"); + trace_printk("%s/%d is leaving the kernel with locks still held!\n", curr->comm, curr->pid); lockdep_print_held_locks(curr); } @@ -4215,14 +4312,14 @@ void lockdep_rcu_suspicious(const char *file, const int line, const char *s) return; #endif /* #ifdef CONFIG_PROVE_RCU_REPEATEDLY */ /* Note: the following can be executed concurrently, so be careful. */ - printk("\n"); - printk("===============================\n"); - printk("[ INFO: suspicious RCU usage. ]\n"); + trace_printk("\n"); + trace_printk("===============================\n"); + trace_printk("[ INFO: suspicious RCU usage. ]\n"); print_kernel_ident(); - printk("-------------------------------\n"); - printk("%s:%d %s!\n", file, line, s); - printk("\nother info that might help us debug this:\n\n"); - printk("\n%srcu_scheduler_active = %d, debug_locks = %d\n", + trace_printk("-------------------------------\n"); + trace_printk("%s:%d %s!\n", file, line, s); + trace_printk("\nother info that might help us debug this:\n\n"); + trace_printk("\n%srcu_scheduler_active = %d, debug_locks = %d\n", !rcu_lockdep_current_cpu_online() ? "RCU used illegally from offline CPU!\n" : !rcu_is_watching() @@ -4249,10 +4346,10 @@ void lockdep_rcu_suspicious(const char *file, const int line, const char *s) * rcu_read_lock_bh() and so on from extended quiescent states. */ if (!rcu_is_watching()) - printk("RCU used illegally from extended quiescent state!\n"); + trace_printk("RCU used illegally from extended quiescent state!\n"); lockdep_print_held_locks(curr); - printk("\nstack backtrace:\n"); - dump_stack(); + trace_printk("\nstack backtrace:\n"); + trace_dump_stack(0); } EXPORT_SYMBOL_GPL(lockdep_rcu_suspicious); -- 1.8.1.4