Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1365105 > unrolled thread

Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260

Started byLinus Torvalds <torvalds@linux-foundation.org>
First post2016-03-27 14:10 +0200
Last post2016-03-30 11:40 +0200
Articles 7 on this page of 27 — 8 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Linus Torvalds <torvalds@linux-foundation.org> - 2016-03-27 14:10 +0200
    Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Boqun Feng <boqun.feng@gmail.com> - 2016-03-27 15:40 +0200
    Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Theodore Ts'o <tytso@mit.edu> - 2016-03-27 20:30 +0200
      Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-27 21:50 +0200
        Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-27 22:30 +0200
    Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-27 22:50 +0200
      Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-27 23:50 +0200
      Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-28 08:40 +0200
      Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Ingo Molnar <mingo@kernel.org> - 2016-03-29 10:50 +0200
        Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-30 11:40 +0200
          Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-30 12:00 +0200
            Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-30 14:50 +0200
              Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-30 14:50 +0200
                Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-30 15:20 +0200
          Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-30 12:00 +0200
          Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Boqun Feng <boqun.feng@gmail.com> - 2016-03-30 12:10 +0200
            Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-30 12:40 +0200
              Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-30 13:10 +0200
            Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-31 17:50 +0200
              Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Boqun Feng <boqun.feng@gmail.com> - 2016-03-31 18:00 +0200
              Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-04-02 08:30 +0200
          Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Peter Zijlstra <peterz@infradead.org> - 2016-03-30 16:10 +0200
            Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-30 17:30 +0200
              [PATCH] lockdep: print chain_key collision information Alfredo Alvarez Fernandez <alfredoalvarezfernandez@gmail.com> - 2016-03-30 19:10 +0200
                Re: [PATCH] lockdep: print chain_key collision information Peter Zijlstra <peterz@infradead.org> - 2016-03-30 19:20 +0200
                [tip:core/urgent] locking/lockdep: Print chain_key collision  information tip-bot for Alfredo Alvarez Fernandez <tipbot@zytor.com> - 2016-04-01 08:40 +0200
        Re: [Linux-v4.6-rc1] ext4: WARNING: CPU: 2 PID: 2692 at  kernel/locking/lockdep.c:2017 __lock_acquire+0x180e/0x2260 Sedat Dilek <sedat.dilek@gmail.com> - 2016-03-30 11:40 +0200

Page 2 of 2 — ← Prev page 1 [2]

#1369880

FromSedat Dilek <sedat.dilek@gmail.com>
Date2016-04-02 08:30 +0200
Message-ID<rjneh-88i-1@gated-at.bofh.it>
In reply to#1368409
On Thu, Mar 31, 2016 at 5:42 PM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Wed, Mar 30, 2016 at 05:59:54PM +0800, Boqun Feng wrote:
>> So we should use macro like current_hardirq_context() here? Or
>> considering the two helpers introduced in my RFC:
>>
>> http://lkml.kernel.org/g/1455602265-16490-2-git-send-email-boqun.feng@gmail.com
>>
>> if you don't think that overkills ;-)
>
> I changed it into the below; since I did significant edits, let me know
> if you disagree and / or want your name taken off.
>

Hi Peter,

is there a place where you collect all those lockdep patches?
I am a bit confused.

Thanks.

Regards,
- Sedat -

> ---
> Subject: lockdep: Add task_irq_context()
> From: Boqun Feng <boqun.feng@gmail.com>
> Date: Tue, 16 Feb 2016 13:57:40 +0800
>
> task_irq_context(): returns the encoded irq_context of the task, the
> return value is encoded in the same as ->irq_context of held_lock.
> Always return 0 if !(CONFIG_TRACE_IRQFLAGS && CONFIG_PROVE_LOCKING)
>
> Cc: Lai Jiangshan <jiangshanlai@gmail.com>
> Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Josh Triplett <josh@joshtriplett.org>
> Cc: sasha.levin@oracle.com
> Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> Signed-off-by: Boqun Feng <boqun.feng@gmail.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> Link: http://lkml.kernel.org/r/1455602265-16490-2-git-send-email-boqun.feng@gmail.com
> ---
>  kernel/locking/lockdep.c |   13 +++++++++++--
>  1 file changed, 11 insertions(+), 2 deletions(-)
>
> --- a/kernel/locking/lockdep.c
> +++ b/kernel/locking/lockdep.c
> @@ -2932,6 +2932,11 @@ static int mark_irqflags(struct task_str
>         return 1;
>  }
>
> +static inline unsigned int task_irq_context(struct task_struct *task)
> +{
> +       return 2 * !!task->hardirq_context + !!task->softirq_context;
> +}
> +
>  static int separate_irq_context(struct task_struct *curr,
>                 struct held_lock *hlock)
>  {
> @@ -2940,8 +2945,6 @@ static int separate_irq_context(struct t
>         /*
>          * Keep track of points where we cross into an interrupt context:
>          */
> -       hlock->irq_context = 2*(curr->hardirq_context ? 1 : 0) +
> -                               curr->softirq_context;
>         if (depth) {
>                 struct held_lock *prev_hlock;
>
> @@ -2973,6 +2976,11 @@ static inline int mark_irqflags(struct t
>         return 1;
>  }
>
> +static inline unsigned int task_irq_context(struct task_struct *task)
> +{
> +       return 0;
> +}
> +
>  static inline int separate_irq_context(struct task_struct *curr,
>                 struct held_lock *hlock)
>  {
> @@ -3241,6 +3249,7 @@ static int __lock_acquire(struct lockdep
>         hlock->acquire_ip = ip;
>         hlock->instance = lock;
>         hlock->nest_lock = nest_lock;
> +       hlock->irq_context = task_irq_context(curr);
>         hlock->trylock = trylock;
>         hlock->read = read;
>         hlock->check = check;

[toc] | [prev] | [next] | [standalone]

#1367234

FromPeter Zijlstra <peterz@infradead.org>
Date2016-03-30 16:10 +0200
Message-ID<rioYO-6wN-13@gated-at.bofh.it>
In reply to#1367039
On Wed, Mar 30, 2016 at 11:36:59AM +0200, Peter Zijlstra wrote:
> Furthermore, our hash function has definite room for improvement.

After a bit of reading, using a 'strong' PRNG as base for a hash
function seems generally suggested.

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

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 53ab2f85d77e..0f7dba4144d6 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -308,10 +308,21 @@ static struct hlist_head chainhash_table[CHAINHASH_SIZE];
  * It's a 64-bit hash, because it's important for the keys to be
  * unique.
  */
-#define iterate_chain_key(key1, key2) \
-	(((key1) << MAX_LOCKDEP_KEYS_BITS) ^ \
-	((key1) >> (64-MAX_LOCKDEP_KEYS_BITS)) ^ \
-	(key2))
+
+/* https://en.wikipedia.org/wiki/Xorshift#xorshift.2A */
+#define UINT64_C(x) x##ULL
+static inline u64 xorshift64star(u64 x)
+{
+	x ^= x >> 12; // a
+	x ^= x << 25; // b
+	x ^= x >> 27; // c
+	return x * UINT64_C(2685821657736338717);
+}
+
+static inline u64 iterate_chain_key(u64 hash, u64 class_idx)
+{
+	return xorshift64star(hash ^ class_idx);
+}
 
 void lockdep_off(void)
 {

[toc] | [prev] | [next] | [standalone]

#1367300

FromSedat Dilek <sedat.dilek@gmail.com>
Date2016-03-30 17:30 +0200
Message-ID<riqee-7pH-19@gated-at.bofh.it>
In reply to#1367234
On Wed, Mar 30, 2016 at 4:06 PM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Wed, Mar 30, 2016 at 11:36:59AM +0200, Peter Zijlstra wrote:
>> Furthermore, our hash function has definite room for improvement.
>
> After a bit of reading, using a 'strong' PRNG as base for a hash
> function seems generally suggested.
>

Is this patch in combination with the previous one?

- Sedat -

> ---
>  kernel/locking/lockdep.c | 19 +++++++++++++++----
>  1 file changed, 15 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> index 53ab2f85d77e..0f7dba4144d6 100644
> --- a/kernel/locking/lockdep.c
> +++ b/kernel/locking/lockdep.c
> @@ -308,10 +308,21 @@ static struct hlist_head chainhash_table[CHAINHASH_SIZE];
>   * It's a 64-bit hash, because it's important for the keys to be
>   * unique.
>   */
> -#define iterate_chain_key(key1, key2) \
> -       (((key1) << MAX_LOCKDEP_KEYS_BITS) ^ \
> -       ((key1) >> (64-MAX_LOCKDEP_KEYS_BITS)) ^ \
> -       (key2))
> +
> +/* https://en.wikipedia.org/wiki/Xorshift#xorshift.2A */
> +#define UINT64_C(x) x##ULL
> +static inline u64 xorshift64star(u64 x)
> +{
> +       x ^= x >> 12; // a
> +       x ^= x << 25; // b
> +       x ^= x >> 27; // c
> +       return x * UINT64_C(2685821657736338717);
> +}
> +
> +static inline u64 iterate_chain_key(u64 hash, u64 class_idx)
> +{
> +       return xorshift64star(hash ^ class_idx);
> +}
>
>  void lockdep_off(void)
>  {

[toc] | [prev] | [next] | [standalone]

#1367466 — [PATCH] lockdep: print chain_key collision information

FromAlfredo Alvarez Fernandez <alfredoalvarezfernandez@gmail.com>
Date2016-03-30 19:10 +0200
Subject[PATCH] lockdep: print chain_key collision information
Message-ID<rirN0-87-17@gated-at.bofh.it>
In reply to#1367300
A sequence of pairs [class_idx -> corresponding chain_key iteration]
is printed for both the current held_lock chain and the cached chain.
That exposes the two different class_idx sequences that led to that
particular hash value.

Signed-off-by: Alfredo Alvarez Fernandez <alfredoalvarezernandez@gmail.com>
---
 kernel/locking/lockdep.c | 81 ++++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 79 insertions(+), 2 deletions(-)

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 53ab2f8..5af260f 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -2000,6 +2000,79 @@ 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)
+{
+	u64 new_chain_key = iterate_chain_key(chain_key, class_idx);
+
+	printk(" class_idx:%d -> chain_key:%016Lx",
+		class_idx,
+		(unsigned long long)new_chain_key);
+	return new_chain_key;
+}
+
+static void print_chain_keys_held_locks(struct task_struct *curr,
+			struct held_lock *hlock_next)
+{
+	struct held_lock *hlock;
+	u64 chain_key = 0;
+	int depth = curr->lockdep_depth;
+	int i;
+
+	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);
+
+		print_lock(hlock);
+	}
+
+	print_chain_key_iteration(hlock_next->class_idx, chain_key);
+	print_lock(hlock_next);
+}
+
+static void print_chain_keys_chain(struct lock_chain *chain)
+{
+	int i;
+	u64 chain_key = 0;
+	int class_id;
+
+	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);
+
+		print_lock_name(lock_classes + class_id);
+		printk("\n");
+	}
+}
+
+static void print_collision(struct task_struct *curr,
+			struct held_lock *hlock_next,
+			struct lock_chain *chain)
+{
+	printk("\n");
+	printk("======================\n");
+	printk("[chain_key collision ]\n");
+	print_kernel_ident();
+	printk("----------------------\n");
+	printk("%s/%d: ", current->comm, task_pid_nr(current));
+	printk("Hash chain already cached but the contents don't match!\n");
+
+	printk("Held locks:");
+	print_chain_keys_held_locks(curr, hlock_next);
+
+	printk("Locks in cached chain:");
+	print_chain_keys_chain(chain);
+
+	printk("\nstack backtrace:\n");
+	dump_stack();
+}
+
+/*
  * Checks whether the chain and the current held locks are consistent
  * in depth and also in content. If they are not it most likely means
  * that there was a collision during the calculation of the chain_key.
@@ -2014,14 +2087,18 @@ 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)))
+	if (DEBUG_LOCKS_WARN_ON(chain->depth != curr->lockdep_depth - (i - 1))) {
+		print_collision(curr, hlock, chain);
 		return 0;
+	}
 
 	for (j = 0; j < chain->depth - 1; j++, i++) {
 		id = curr->held_locks[i].class_idx - 1;
 
-		if (DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id))
+		if (DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id)) {
+			print_collision(curr, hlock, chain);
 			return 0;
+		}
 	}
 #endif
 	return 1;
-- 
2.5.0

[toc] | [prev] | [next] | [standalone]

#1367477 — Re: [PATCH] lockdep: print chain_key collision information

FromPeter Zijlstra <peterz@infradead.org>
Date2016-03-30 19:20 +0200
SubjectRe: [PATCH] lockdep: print chain_key collision information
Message-ID<rirWG-by-17@gated-at.bofh.it>
In reply to#1367466
On Wed, Mar 30, 2016 at 07:03:36PM +0200, Alfredo Alvarez Fernandez wrote:
> A sequence of pairs [class_idx -> corresponding chain_key iteration]
> is printed for both the current held_lock chain and the cached chain.
> That exposes the two different class_idx sequences that led to that
> particular hash value.

Nice, thanks!

[toc] | [prev] | [next] | [standalone]

#1369018 — [tip:core/urgent] locking/lockdep: Print chain_key collision information

Fromtip-bot for Alfredo Alvarez Fernandez <tipbot@zytor.com>
Date2016-04-01 08:40 +0200
Subject[tip:core/urgent] locking/lockdep: Print chain_key collision information
Message-ID<rj0Uq-qW-5@gated-at.bofh.it>
In reply to#1367466
Commit-ID:  39e2e173fb1f900959d3a25c21c65fa88b06c6ee
Gitweb:     http://git.kernel.org/tip/39e2e173fb1f900959d3a25c21c65fa88b06c6ee
Author:     Alfredo Alvarez Fernandez <alfredoalvarezfernandez@gmail.com>
AuthorDate: Wed, 30 Mar 2016 19:03:36 +0200
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Thu, 31 Mar 2016 15:03:58 +0200

locking/lockdep: Print chain_key collision information

A sequence of pairs [class_idx -> corresponding chain_key iteration]
is printed for both the current held_lock chain and the cached chain.

That exposes the two different class_idx sequences that led to that
particular hash value.

This helps with debugging hash chain collision reports.

Signed-off-by: Alfredo Alvarez Fernandez <alfredoalvarezfernandez@gmail.com>
Acked-by: Peter Zijlstra (Intel) <peterz@infradead.org>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: linux-fsdevel@vger.kernel.org
Cc: sedat.dilek@gmail.com
Cc: tytso@mit.edu
Link: http://lkml.kernel.org/r/1459357416-19190-1-git-send-email-alfredoalvarezernandez@gmail.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/locking/lockdep.c | 79 ++++++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 77 insertions(+), 2 deletions(-)

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 53ab2f8..2324ba5 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -2000,6 +2000,77 @@ 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)
+{
+	u64 new_chain_key = iterate_chain_key(chain_key, class_idx);
+
+	printk(" class_idx:%d -> chain_key:%016Lx",
+		class_idx,
+		(unsigned long long)new_chain_key);
+	return new_chain_key;
+}
+
+static void
+print_chain_keys_held_locks(struct task_struct *curr, struct held_lock *hlock_next)
+{
+	struct held_lock *hlock;
+	u64 chain_key = 0;
+	int depth = curr->lockdep_depth;
+	int i;
+
+	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);
+
+		print_lock(hlock);
+	}
+
+	print_chain_key_iteration(hlock_next->class_idx, chain_key);
+	print_lock(hlock_next);
+}
+
+static void print_chain_keys_chain(struct lock_chain *chain)
+{
+	int i;
+	u64 chain_key = 0;
+	int class_id;
+
+	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);
+
+		print_lock_name(lock_classes + class_id);
+		printk("\n");
+	}
+}
+
+static void print_collision(struct task_struct *curr,
+			struct held_lock *hlock_next,
+			struct lock_chain *chain)
+{
+	printk("\n");
+	printk("======================\n");
+	printk("[chain_key collision ]\n");
+	print_kernel_ident();
+	printk("----------------------\n");
+	printk("%s/%d: ", current->comm, task_pid_nr(current));
+	printk("Hash chain already cached but the contents don't match!\n");
+
+	printk("Held locks:");
+	print_chain_keys_held_locks(curr, hlock_next);
+
+	printk("Locks in cached chain:");
+	print_chain_keys_chain(chain);
+
+	printk("\nstack backtrace:\n");
+	dump_stack();
+}
+
+/*
  * Checks whether the chain and the current held locks are consistent
  * in depth and also in content. If they are not it most likely means
  * that there was a collision during the calculation of the chain_key.
@@ -2014,14 +2085,18 @@ 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)))
+	if (DEBUG_LOCKS_WARN_ON(chain->depth != curr->lockdep_depth - (i - 1))) {
+		print_collision(curr, hlock, chain);
 		return 0;
+	}
 
 	for (j = 0; j < chain->depth - 1; j++, i++) {
 		id = curr->held_locks[i].class_idx - 1;
 
-		if (DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id))
+		if (DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id)) {
+			print_collision(curr, hlock, chain);
 			return 0;
+		}
 	}
 #endif
 	return 1;

[toc] | [prev] | [next] | [standalone]

#1367043

FromSedat Dilek <sedat.dilek@gmail.com>
Date2016-03-30 11:40 +0200
Message-ID<rikLx-3iV-15@gated-at.bofh.it>
In reply to#1366011
> [    0.000000] -------------------------------------------------------
> [    0.000000] Good, all 253 testcases passed! |
> [    0.000000] ---------------------------------
>
> And it's all good?
> ( On shutdown I saw an(other) issue - will investigate, might not be related. )
>

The initial reported issue is hard but reproducible.

Mar 30 08:26:52 fambox kernel: [  683.309212] ------------[ cut here
]------------
Mar 30 08:26:52 fambox kernel: [  683.309221] WARNING: CPU: 3 PID:
10090 at kernel/locking/lockdep.c:2023 __lock_acquire+0x147a/0x2260
Mar 30 08:26:52 fambox kernel: [  683.309223]
DEBUG_LOCKS_WARN_ON(chain_hlocks[chain->base + j] != id)
Mar 30 08:26:52 fambox kernel: [  683.309225] Modules linked in: btrfs
xor raid6_pq ntfs xfs libcrc32c ppp_deflate bsd_comp ppp_async
crc_ccitt option usb_wwan cdc_ether usbserial usbnet arc4 iwldvm
mac80211 bnep rfcomm i915 uvcvideo snd_hda_codec_hdmi
snd_hda_codec_realtek videobuf2_vmalloc kvm_intel
snd_hda_codec_generic videobuf2_memops videobuf2_v4l2 snd_hda_intel
videobuf2_core kvm snd_hda_codec joydev videodev usb_storage
parport_pc ppdev snd_hwdep btusb snd_hda_core btrtl i2c_algo_bit
snd_pcm irqbypass btbcm iwlwifi drm_kms_helper psmouse btintel
snd_seq_midi bluetooth syscopyarea snd_seq_midi_event sysfillrect
snd_rawmidi serio_raw samsung_laptop sysimgblt snd_seq fb_sys_fops
snd_timer cfg80211 drm snd_seq_device snd soundcore wmi mac_hid video
intel_rst lpc_ich lp parport binfmt_misc hid_generic usbhid hid r8169
mii
Mar 30 08:26:52 fambox kernel: [  683.309283] CPU: 3 PID: 10090 Comm:
mv Not tainted 4.6.0-rc1-4-iniza-small #1
Mar 30 08:26:52 fambox kernel: [  683.309285] Hardware name: SAMSUNG
ELECTRONICS CO., LTD. 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH,
BIOS 13XK 03/28/2013
Mar 30 08:26:52 fambox kernel: [  683.309287]  0000000000000000
ffff8800330af5d0 ffffffff81411c25 ffff8800330af620
Mar 30 08:26:52 fambox kernel: [  683.309290]  0000000000000000
ffff8800330af610 ffffffff81083db1 000007e7330af610
Mar 30 08:26:52 fambox kernel: [  683.309293]  ffff880109059300
0000000000000000 0000000000000004 31419e23b49ae8f8
Mar 30 08:26:52 fambox kernel: [  683.309296] Call Trace:
Mar 30 08:26:52 fambox kernel: [  683.309301]  [<ffffffff81411c25>]
dump_stack+0x85/0xc0
Mar 30 08:26:52 fambox kernel: [  683.309304]  [<ffffffff81083db1>]
__warn+0xd1/0xf0
Mar 30 08:26:52 fambox kernel: [  683.309307]  [<ffffffff81083e1f>]
warn_slowpath_fmt+0x4f/0x60
Mar 30 08:26:52 fambox kernel: [  683.309309]  [<ffffffff810dec8a>]
__lock_acquire+0x147a/0x2260
Mar 30 08:26:52 fambox kernel: [  683.309312]  [<ffffffff810e0709>]
lock_acquire+0x119/0x220
Mar 30 08:26:52 fambox kernel: [  683.309316]  [<ffffffff8131dc05>] ?
do_get_write_access+0x3a5/0x5d0
Mar 30 08:26:52 fambox kernel: [  683.309319]  [<ffffffff8180d188>]
_raw_spin_lock+0x38/0x50
Mar 30 08:26:52 fambox kernel: [  683.309322]  [<ffffffff8131dc05>] ?
do_get_write_access+0x3a5/0x5d0
Mar 30 08:26:52 fambox kernel: [  683.309324]  [<ffffffff8131dc05>]
do_get_write_access+0x3a5/0x5d0
Mar 30 08:26:52 fambox kernel: [  683.309327]  [<ffffffff8131de63>]
jbd2_journal_get_write_access+0x33/0x60
Mar 30 08:26:52 fambox kernel: [  683.309331]  [<ffffffff812ff25e>]
__ext4_journal_get_write_access+0x4e/0x90
Mar 30 08:26:52 fambox kernel: [  683.309334]  [<ffffffff8130665d>]
ext4_mb_mark_diskspace_used+0x6d/0x470
Mar 30 08:26:52 fambox kernel: [  683.309336]  [<ffffffff81307f68>]
ext4_mb_new_blocks+0x3e8/0x840
Mar 30 08:26:52 fambox kernel: [  683.309338]  [<ffffffff812f6807>] ?
ext4_find_extent+0x1b7/0x320
Mar 30 08:26:52 fambox kernel: [  683.309340]  [<ffffffff810db9c9>] ?
__lock_is_held+0x49/0x70
Mar 30 08:26:52 fambox kernel: [  683.309343]  [<ffffffff812fb1b5>]
ext4_ext_map_blocks+0xab5/0x2100
Mar 30 08:26:52 fambox kernel: [  683.309348]  [<ffffffff812ca45c>]
ext4_map_blocks+0x10c/0x510
Mar 30 08:26:52 fambox kernel: [  683.309350]  [<ffffffff810db9c9>] ?
__lock_is_held+0x49/0x70
Mar 30 08:26:52 fambox kernel: [  683.309353]  [<ffffffff812ce093>]
ext4_writepages+0x723/0x1010
Mar 30 08:26:52 fambox kernel: [  683.309356]  [<ffffffff8180d377>] ?
_raw_spin_unlock+0x27/0x40
Mar 30 08:26:52 fambox kernel: [  683.309359]  [<ffffffff811bb221>]
do_writepages+0x21/0x30
Mar 30 08:26:52 fambox kernel: [  683.309362]  [<ffffffff811abb5a>]
__filemap_fdatawrite_range+0xaa/0xf0
Mar 30 08:26:52 fambox kernel: [  683.309365]  [<ffffffff811abc4c>]
filemap_flush+0x1c/0x20
Mar 30 08:26:52 fambox kernel: [  683.309368]  [<ffffffff812cb4a3>]
ext4_alloc_da_blocks+0x43/0x130
Mar 30 08:26:52 fambox kernel: [  683.309370]  [<ffffffff812db0b1>]
ext4_rename+0x6a1/0x8f0
Mar 30 08:26:52 fambox kernel: [  683.309372]  [<ffffffff810dd24d>] ?
mark_held_locks+0x6d/0x90
Mar 30 08:26:52 fambox kernel: [  683.309374]  [<ffffffff8180981f>] ?
mutex_lock_nested+0x25f/0x3d0
Mar 30 08:26:52 fambox kernel: [  683.309377]  [<ffffffff812db31d>]
ext4_rename2+0x1d/0x30
Mar 30 08:26:52 fambox kernel: [  683.309379]  [<ffffffff812428e1>]
vfs_rename+0x601/0x900
Mar 30 08:26:52 fambox kernel: [  683.309383]  [<ffffffff81371500>] ?
security_path_rename+0x70/0xd0
Mar 30 08:26:52 fambox kernel: [  683.309386]  [<ffffffff81247c78>]
SyS_rename+0x398/0x3b0
Mar 30 08:26:52 fambox kernel: [  683.309389]  [<ffffffff8180dc00>]
entry_SYSCALL_64_fastpath+0x23/0xc1
Mar 30 08:26:52 fambox kernel: [  683.309391] ---[ end trace
7dacba969839f82f ]---

- Sedat -

[toc] | [prev] | [standalone]

Page 2 of 2 — ← Prev page 1 [2]

Back to top | Article view | linux.kernel

csiph-web