2013-04-23 16:34:35

by Dave Jones

[permalink] [raw]
Subject: Print out additional debugging advice when we hit lockdep BUGs

We occasionally get reports of these BUGs being hit, and the stack trace
doesn't necessarily always tell us what we need to know about why we are
hitting those limits.

If users start attaching /proc/lock_stats to reports we may have more of
a clue what's going on.

Signed-off-by: Dave Jones <[email protected]>

--
This could be factored out into a separate function as a follow-up patch
if this looks ok.

diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 7e755e7..e4c001f 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -411,6 +411,7 @@ static int save_trace(struct stack_trace *trace)

printk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();

return 0;
@@ -778,6 +779,7 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)

printk("BUG: MAX_LOCKDEP_KEYS too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();
return NULL;
}
@@ -849,6 +851,7 @@ static struct lock_list *alloc_list_entry(void)

printk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();
return NULL;
}
@@ -2063,6 +2066,7 @@ cache_hit:

printk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();
return 0;
}
@@ -3207,6 +3211,7 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
printk("BUG: MAX_LOCK_DEPTH too low, depth: %i max: %lu!\n",
curr->lockdep_depth, MAX_LOCK_DEPTH);
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");

lockdep_print_held_locks(current);
debug_show_all_locks();


2013-04-24 06:48:18

by Ingo Molnar

[permalink] [raw]
Subject: Re: Print out additional debugging advice when we hit lockdep BUGs


* Dave Jones <[email protected]> wrote:

> We occasionally get reports of these BUGs being hit, and the stack trace
> doesn't necessarily always tell us what we need to know about why we are
> hitting those limits.
>
> If users start attaching /proc/lock_stats to reports we may have more of
> a clue what's going on.

Good idea.

A detail:

> printk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
> printk("turning off the locking correctness validator.\n");
> + printk("Attach output of /proc/lock_stat to bug report\n");

> printk("BUG: MAX_LOCKDEP_KEYS too low!\n");
> printk("turning off the locking correctness validator.\n");
> + printk("Attach output of /proc/lock_stat to bug report\n");

> printk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
> printk("turning off the locking correctness validator.\n");
> + printk("Attach output of /proc/lock_stat to bug report\n");

> printk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
> printk("turning off the locking correctness validator.\n");
> + printk("Attach output of /proc/lock_stat to bug report\n");

> printk("BUG: MAX_LOCK_DEPTH too low, depth: %i max: %lu!\n",
> curr->lockdep_depth, MAX_LOCK_DEPTH);
> printk("turning off the locking correctness validator.\n");
> + printk("Attach output of /proc/lock_stat to bug report\n");

These patterns repeated in 4 places really call for a common helper
defined as print_lockdep_off(fmt...) or so?

(Can be a followup patch if that's easier for you.)

Thanks,

Ingo

2013-04-25 18:24:19

by Dave Jones

[permalink] [raw]
Subject: Re: Print out additional debugging advice when we hit lockdep BUGs

On Wed, Apr 24, 2013 at 08:48:13AM +0200, Ingo Molnar wrote:

> These patterns repeated in 4 places really call for a common helper
> defined as print_lockdep_off(fmt...) or so?
>
> (Can be a followup patch if that's easier for you.)

Given there was only one case which was really different, I opted not
to bother with varargs, and just pass the one string that changes
and add an extra printk for that special case (MAX_LOCK_DEPTH)

--

Consolidate the lockdep "too low" messages into one function.
Also add some missing printk levels.

Signed-off-by: Dave Jones <[email protected]>

diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index e4c001f..be52e6d 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -380,6 +380,13 @@ static int verbose(struct lock_class *class)
unsigned long nr_stack_trace_entries;
static unsigned long stack_trace[MAX_STACK_TRACE_ENTRIES];

+static void print_lockdep_off(const char *which)
+{
+ printk(KERN_DEBUG "BUG: %s too low!\n", which);
+ printk(KERN_DEBUG "turning off the locking correctness validator.\n");
+ printk(KERN_DEBUG "Attach output of /proc/lock_stat to bug report\n");
+}
+
static int save_trace(struct stack_trace *trace)
{
trace->nr_entries = 0;
@@ -409,9 +416,7 @@ static int save_trace(struct stack_trace *trace)
if (!debug_locks_off_graph_unlock())
return 0;

- printk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("MAX_STACK_TRACE_ENTRIES");
dump_stack();

return 0;
@@ -777,9 +782,7 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)
}
raw_local_irq_restore(flags);

- printk("BUG: MAX_LOCKDEP_KEYS too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("MAX_LOCKDEP_KEYS");
dump_stack();
return NULL;
}
@@ -849,9 +852,7 @@ static struct lock_list *alloc_list_entry(void)
if (!debug_locks_off_graph_unlock())
return NULL;

- printk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("MAX_LOCKDEP_ENTRIES");
dump_stack();
return NULL;
}
@@ -2064,9 +2065,7 @@ cache_hit:
if (!debug_locks_off_graph_unlock())
return 0;

- printk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("MAX_LOCKDEP_CHAINS");
dump_stack();
return 0;
}
@@ -3208,10 +3207,9 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
#endif
if (unlikely(curr->lockdep_depth >= MAX_LOCK_DEPTH)) {
debug_locks_off();
- printk("BUG: MAX_LOCK_DEPTH too low, depth: %i max: %lu!\n",
+ print_lockdep_off("MAX_LOCK_DEPTH");
+ printk(KERN_DEBUG "depth: %i max: %lu!\n",
curr->lockdep_depth, MAX_LOCK_DEPTH);
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");

lockdep_print_held_locks(current);
debug_show_all_locks();

2013-04-26 06:32:22

by Ingo Molnar

[permalink] [raw]
Subject: Re: Print out additional debugging advice when we hit lockdep BUGs


* Dave Jones <[email protected]> wrote:

> On Wed, Apr 24, 2013 at 08:48:13AM +0200, Ingo Molnar wrote:
>
> > These patterns repeated in 4 places really call for a common helper
> > defined as print_lockdep_off(fmt...) or so?
> >
> > (Can be a followup patch if that's easier for you.)
>
> Given there was only one case which was really different, I opted not to
> bother with varargs, and just pass the one string that changes and add
> an extra printk for that special case (MAX_LOCK_DEPTH)
>
> --
>
> Consolidate the lockdep "too low" messages into one function.
> Also add some missing printk levels.
>
> Signed-off-by: Dave Jones <[email protected]>
>
> diff --git a/kernel/lockdep.c b/kernel/lockdep.c
> index e4c001f..be52e6d 100644
> --- a/kernel/lockdep.c
> +++ b/kernel/lockdep.c
> @@ -380,6 +380,13 @@ static int verbose(struct lock_class *class)
> unsigned long nr_stack_trace_entries;
> static unsigned long stack_trace[MAX_STACK_TRACE_ENTRIES];
>
> +static void print_lockdep_off(const char *which)
> +{
> + printk(KERN_DEBUG "BUG: %s too low!\n", which);
> + printk(KERN_DEBUG "turning off the locking correctness validator.\n");
> + printk(KERN_DEBUG "Attach output of /proc/lock_stat to bug report\n");
> +}
> +

Yeah, that looks perfectly fine - thanks!

( I tweaked it a tiny bit to pass in a generic bug-string instead of
assuming that the warning is necessarily about some 'too low' value.
This makes actual usage sites of print_lockdep_off() easier to read and
closer to existing WARN() patterns. )

Thanks,

Ingo

Subject: [tip:core/locking] lockdep: Print out additional debugging advice when we hit lockdep BUGs

Commit-ID: 199e371f59d31c828345b0d959d27d752827b517
Gitweb: http://git.kernel.org/tip/199e371f59d31c828345b0d959d27d752827b517
Author: Dave Jones <[email protected]>
AuthorDate: Tue, 23 Apr 2013 12:34:03 -0400
Committer: Ingo Molnar <[email protected]>
CommitDate: Fri, 26 Apr 2013 08:36:33 +0200

lockdep: Print out additional debugging advice when we hit lockdep BUGs

We occasionally get reports of these BUGs being hit, and the
stack trace doesn't necessarily always tell us what we need to
know about why we are hitting those limits.

If users start attaching /proc/lock_stats to reports we may have
more of a clue what's going on.

Signed-off-by: Dave Jones <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/lockdep.c | 5 +++++
1 file changed, 5 insertions(+)

diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index e5dedda..c5d1e6b 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -411,6 +411,7 @@ static int save_trace(struct stack_trace *trace)

printk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();

return 0;
@@ -765,6 +766,7 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)

printk("BUG: MAX_LOCKDEP_KEYS too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();
return NULL;
}
@@ -836,6 +838,7 @@ static struct lock_list *alloc_list_entry(void)

printk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();
return NULL;
}
@@ -2050,6 +2053,7 @@ cache_hit:

printk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");
dump_stack();
return 0;
}
@@ -3191,6 +3195,7 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
printk("BUG: MAX_LOCK_DEPTH too low, depth: %i max: %lu!\n",
curr->lockdep_depth, MAX_LOCK_DEPTH);
printk("turning off the locking correctness validator.\n");
+ printk("Attach output of /proc/lock_stat to bug report\n");

lockdep_print_held_locks(current);
debug_show_all_locks();

Subject: [tip:core/locking] lockdep: Consolidate bug messages into a single print_lockdep_off() function

Commit-ID: 2c522836627c6e78660f8bd52cdb4cdcb75e3e3c
Gitweb: http://git.kernel.org/tip/2c522836627c6e78660f8bd52cdb4cdcb75e3e3c
Author: Dave Jones <[email protected]>
AuthorDate: Thu, 25 Apr 2013 13:40:02 -0400
Committer: Ingo Molnar <[email protected]>
CommitDate: Fri, 26 Apr 2013 08:37:22 +0200

lockdep: Consolidate bug messages into a single print_lockdep_off() function

Also add some missing printk levels.

Signed-off-by: Dave Jones <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
[ Tweaked the messages a bit. ]
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/lockdep.c | 28 +++++++++++++---------------
1 file changed, 13 insertions(+), 15 deletions(-)

diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index c5d1e6b..6a3bccb 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -380,6 +380,13 @@ static int verbose(struct lock_class *class)
unsigned long nr_stack_trace_entries;
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");
+}
+
static int save_trace(struct stack_trace *trace)
{
trace->nr_entries = 0;
@@ -409,9 +416,7 @@ static int save_trace(struct stack_trace *trace)
if (!debug_locks_off_graph_unlock())
return 0;

- printk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("BUG: MAX_STACK_TRACE_ENTRIES too low!");
dump_stack();

return 0;
@@ -764,9 +769,7 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)
}
raw_local_irq_restore(flags);

- printk("BUG: MAX_LOCKDEP_KEYS too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("BUG: MAX_LOCKDEP_KEYS too low!");
dump_stack();
return NULL;
}
@@ -836,9 +839,7 @@ static struct lock_list *alloc_list_entry(void)
if (!debug_locks_off_graph_unlock())
return NULL;

- printk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("BUG: MAX_LOCKDEP_ENTRIES too low!");
dump_stack();
return NULL;
}
@@ -2051,9 +2052,7 @@ cache_hit:
if (!debug_locks_off_graph_unlock())
return 0;

- printk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");
+ print_lockdep_off("BUG: MAX_LOCKDEP_CHAINS too low!");
dump_stack();
return 0;
}
@@ -3192,10 +3191,9 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
#endif
if (unlikely(curr->lockdep_depth >= MAX_LOCK_DEPTH)) {
debug_locks_off();
- printk("BUG: MAX_LOCK_DEPTH too low, depth: %i max: %lu!\n",
+ print_lockdep_off("BUG: MAX_LOCK_DEPTH too low!");
+ printk(KERN_DEBUG "depth: %i max: %lu!\n",
curr->lockdep_depth, MAX_LOCK_DEPTH);
- printk("turning off the locking correctness validator.\n");
- printk("Attach output of /proc/lock_stat to bug report\n");

lockdep_print_held_locks(current);
debug_show_all_locks();