Re: [tip:core/urgent] locking/lockdep: Print chain_key collision information

Peter Zijlstra
2016-05-10T09:10:09Z

Wanpeng Li hit a collision report; which contained:

[67170.324532] ======================
[67170.327923] [chain_key collision ]
[67170.331317] 4.6.0-rc3+ #5 Tainted: G W OE
[67170.336184] ----------------------
[67170.339576] swapper/0/0: Hash chain already cached but the contents don't match!
[67170.346970] Held locks:depth: 2
[67170.350117] class_idx:548 -> chain_key:0000000000000224 (jiffies_lock){-.-.-.}, at: [<ffffffff811120db>] tick_do_update_jiffies64+0x3b/0x150
[67170.362842] class_idx:549 -> chain_key:0000000000448225 (jiffies_lock#2){---.--}, at: [<ffffffff81112221>] tick_sched_do_timer+0x31/0x50
[67170.375229] Locks in cached chain:depth: 2
[67170.379326] class_idx:2222 -> chain_key:00000000000008ae (&us_interface_key[i]){+.+...}
[67170.387442] class_idx:680 -> chain_key:000000000115c2a8 (&dev->mutex){......}

Full splat at: http://pastebin.com/raw/Qbi49DBN

>From this its not at all clear there actually was a collision; the
hashes do not match. Is there something wrong with the print stuff?

Would some additional info like per the below make sense?

---
kernel/locking/lockdep.c | 31 +++++++++++++++++++------------
1 file changed, 19 insertions(+), 12 deletions(-)

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 81f1a7107c0e..8d4a9d0cf14a 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -2004,13 +2004,14 @@ static inline int get_first_held_lock(struct task_struct *curr,
/*
* Returns the next chain_key iteration
*/
-static u64 print_chain_key_iteration(int class_idx, u64 chain_key)
+static u64 print_chain_key_iteration(int class_idx, u64 chain_key, u64 prev_key)
{
u64 new_chain_key = iterate_chain_key(chain_key, class_idx);

- printk(" class_idx:%d -> chain_key:%016Lx",
+ printk(" class_idx: %d -> chain_key: %016Lx (%016Lx)",
class_idx,
- (unsigned long long)new_chain_key);
+ (unsigned long long)new_chain_key,
+ (unsigned long long)prev_key);
return new_chain_key;
}

@@ -2025,7 +2026,8 @@ print_chain_keys_held_locks(struct task_struct *curr, struct held_lock *hlock_ne
printk("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);
+ chain_key = print_chain_key_iteration(hlock->class_idx, chain_key,
+ hlock->prev_chain_key);

print_lock(hlock);
}
@@ -2043,7 +2045,7 @@ static void print_chain_keys_chain(struct lock_chain *chain)
printk("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);
+ chain_key = print_chain_key_iteration(class_id + 1, chain_key, 0);

print_lock_name(lock_classes + class_id);
printk("\n");
@@ -2052,7 +2054,8 @@ static void print_chain_keys_chain(struct lock_chain *chain)

static void print_collision(struct task_struct *curr,
struct held_lock *hlock_next,
- struct lock_chain *chain)
+ struct lock_chain *chain,
+ u64 chain_key)
{
printk("\n");
printk("======================\n");
@@ -2061,11 +2064,14 @@ static void print_collision(struct task_struct *curr,
printk("----------------------\n");
printk("%s/%d: ", current->comm, task_pid_nr(current));
printk("Hash chain already cached but the contents don't match!\n");
+ printk("chain->chain_key: %016Lx chain_key: %016Lx\n",
+ (unsigned long long)chain->chain_key,
+ (unsigned long long)chain_key);

- printk("Held locks:");
+ printk("Held locks: ");
print_chain_keys_held_locks(curr, hlock_next);

- printk("Locks in cached chain:");
+ printk("Locks in cached chain: ");
print_chain_keys_chain(chain);

printk("\nstack backtrace:\n");
@@ -2081,7 +2087,8 @@ static void print_collision(struct task_struct *curr,
*/
static int check_no_collision(struct task_struct *curr,
struct held_lock *hlock,
- struct lock_chain *chain)
+ struct lock_chain *chain,
+ u64 chain_key)
{
#ifdef CONFIG_DEBUG_LOCKDEP
int i, j, id;
@@ -2089,7 +2096,7 @@ static int check_no_collision(struct task_struct *curr,
i = get_first_held_lock(curr, hlock);

if (DEBUG_LOCKS_WARN_ON(chain->depth != curr->lockdep_depth - (i - 1))) {
- print_collision(curr, hlock, chain);
+ print_collision(curr, hlock, chain, chain_key);
return 0;
}

@@ -2097,7 +2104,7 @@ static int check_no_collision(struct task_struct *curr,
id = curr->held_locks[i].class_idx - 1;

if (DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id)) {
- print_collision(curr, hlock, chain);
+ print_collision(curr, hlock, chain, chain_key);
return 0;
}
}
@@ -2135,7 +2142,7 @@ static inline int lookup_chain_cache(struct task_struct *curr,
if (chain->chain_key == chain_key) {
cache_hit:
debug_atomic_inc(chain_lookup_hits);
- if (!check_no_collision(curr, hlock, chain))
+ if (!check_no_collision(curr, hlock, chain, chain_key))
return 0;

if (very_verbose(class))