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

[Peter Zijlstra]

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))