* [PATCH] lockdep: fix report formatting
@ 2016-11-28 14:24 Dmitry Vyukov
2016-11-29 7:50 ` Andrew Donnellan
` (2 more replies)
0 siblings, 3 replies; 4+ messages in thread
From: Dmitry Vyukov @ 2016-11-28 14:24 UTC (permalink / raw)
To: peterz, mingo
Cc: Dmitry Vyukov, aryabinin, andreyknvl, joe, linux-kernel,
syzkaller
Since commit 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing
continuation lines") printk() requires KERN_CONT to continue log
messages. Lots of printk() in lockdep.c and print_ip_sym() don't
have it. As the result lockdep reports are completely messed.
Add missing KERN_CONT and inline print_ip_sym() where necessary.
Without this patch all scripts that parse kernel bug reports
are broken. So it makes sense to get this into 4.9.
Cc: aryabinin@virtuozzo.com
Cc: andreyknvl@google.com
Cc: joe@perches.com
Cc: peterz@infradead.org
Cc: mingo@redhat.com
Cc: linux-kernel@vger.kernel.org
Cc: syzkaller@googlegroups.com
---
Any better suggestions on how to fix this systematically
rather than sprinkle KERN_CONT here and there?
Most likely I got it wrong somewhere. Output tests would be nice...
Example of a messed report:
[ 332.843850] [ INFO: possible circular locking dependency detected ]
[ 332.850253] 4.9.0-rc5+ #41 Not tainted
[ 332.854153] -------------------------------------------------------
[ 332.860558] syz-executor0/5036 is trying to acquire lock:
[ 332.860565] (
[ 332.860568] rtnl_mutex
[ 332.860569] ){+.+.+.}
[ 332.860586] , at:
[ 332.860587] [<ffffffff86b3d6ac>] rtnl_lock+0x1c/0x20
[ 332.860589]
[ 332.860589] but task is already holding lock:
[ 332.860593] (
[ 332.860596] &net->packet.sklist_lock
[ 332.860598] ){+.+...}
[ 332.860610] , at:
[ 332.860611] [<ffffffff873541a6>] packet_diag_dump+0x1a6/0x1920
[ 332.860613]
[ 332.860613] which lock already depends on the new lock.
[ 332.860613]
[ 332.860615]
[ 332.860615] the existing dependency chain (in reverse order) is:
[ 332.860619]
[ 332.860619] -> #3
[ 332.860622] (
[ 332.860624] &net->packet.sklist_lock
[ 332.860626] ){+.+...}
[ 332.860626] :
[ 332.860638]
[ 332.860639] [<ffffffff81569446>] __lock_acquire+0x2156/0x3380
[ 332.860647]
[ 332.860648] [<ffffffff8156b542>] lock_acquire+0x2a2/0x790
[ 332.860659]
[ 332.860660] [<ffffffff8813754f>] mutex_lock_nested+0x23f/0xf20
[ 332.860670]
[ 332.860670] [<ffffffff873541a6>] packet_diag_dump+0x1a6/0x1920
[ 332.860681]
[ 332.860682] [<ffffffff86ca8096>] netlink_dump+0x576/0xd70
[ 332.860691]
[ 332.860691] [<ffffffff86cac85a>] __netlink_dump_start+0x4ea/0x760
[ 332.860701]
[ 332.860702] [<ffffffff87353f37>] packet_diag_handler_dump+0x247/0x310
[ 332.860712]
[ 332.860713] [<ffffffff86b6f163>] sock_diag_rcv_msg+0x313/0x390
[ 332.860723]
[ 332.860723] [<ffffffff86cb5020>] netlink_rcv_skb+0x2b0/0x390
[ 332.860733]
[ 332.860733] [<ffffffff86b6e66f>] sock_diag_rcv+0x2f/0x40
[ 332.860743]
[ 332.860744] [<ffffffff86cb3854>] netlink_unicast+0x514/0x730
[ 332.860754]
[ 332.860754] [<ffffffff86cb4514>] netlink_sendmsg+0xaa4/0xe50
[ 332.860765]
[ 332.860766] [<ffffffff86a6da7f>] sock_sendmsg+0xcf/0x110
[ 332.860776]
[ 332.860776] [<ffffffff86a6ddeb>] sock_write_iter+0x32b/0x620
[ 332.860787]
[ 332.860787] [<ffffffff81a6e5b3>] do_iter_readv_writev+0x363/0x670
[ 332.860797]
[ 332.860797] [<ffffffff81a71001>] do_readv_writev+0x431/0x9b0
[ 332.860806]
[ 332.860807] [<ffffffff81a71b3c>] vfs_writev+0x8c/0xc0
[ 332.860815]
[ 332.860816] [<ffffffff81a71c85>] do_writev+0x115/0x2d0
[ 332.860825]
[ 332.860826] [<ffffffff81a7543c>] SyS_writev+0x2c/0x40
[ 332.860837]
[ 332.860837] [<ffffffff88147845>] entry_SYSCALL_64_fastpath+0x23/0xc6
[ 332.860841]
[ 332.860841] -> #2
[ 332.860844] (
[ 332.860846] nlk->cb_mutex
[ 332.860848] ){+.+.+.}
[ 332.860849] :
[ 332.860858]
[ 332.860859] [<ffffffff81569446>] __lock_acquire+0x2156/0x3380
[ 332.860866]
[ 332.860866] [<ffffffff8156b542>] lock_acquire+0x2a2/0x790
[ 332.860875]
[ 332.860875] [<ffffffff8813754f>] mutex_lock_nested+0x23f/0xf20
[ 332.860884]
[ 332.860885] [<ffffffff86cac469>] __netlink_dump_start+0xf9/0x760
[ 332.860894]
[ 332.860895] [<ffffffff86cfbb9f>] ctnetlink_get_ct_unconfirmed+0x17f/0x220
[ 332.860904]
[ 332.860904] [<ffffffff86cc7a1e>] nfnetlink_rcv_msg+0x9be/0xd60
[ 332.860919]
[ 332.860920] [<ffffffff86cb5020>] netlink_rcv_skb+0x2b0/0x390
[ 332.860926]
[ 332.860927] [<ffffffff86cc644c>] nfnetlink_rcv+0x7cc/0x10c0
[ 332.860935]
[ 332.860935] [<ffffffff86cb3854>] netlink_unicast+0x514/0x730
[ 332.860951]
[ 332.860951] [<ffffffff86cb4514>] netlink_sendmsg+0xaa4/0xe50
[ 332.860961]
[ 332.860961] [<ffffffff86a6da7f>] sock_sendmsg+0xcf/0x110
[ 332.860970]
[ 332.860971] [<ffffffff86a6ddeb>] sock_write_iter+0x32b/0x620
[ 332.860979]
[ 332.860980] [<ffffffff81a6e5b3>] do_iter_readv_writev+0x363/0x670
[ 332.860988]
[ 332.860989] [<ffffffff81a71001>] do_readv_writev+0x431/0x9b0
[ 332.860997]
[ 332.860997] [<ffffffff81a71b3c>] vfs_writev+0x8c/0xc0
[ 332.861005]
[ 332.861006] [<ffffffff81a71c85>] do_writev+0x115/0x2d0
[ 332.861014]
[ 332.861014] [<ffffffff81a7543c>] SyS_writev+0x2c/0x40
---
kernel/locking/lockdep.c | 111 ++++++++++++++++++++++++-----------------------
1 file changed, 57 insertions(+), 54 deletions(-)
diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 589d763..4d7ffc0 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -506,13 +506,13 @@ static void __print_lock_name(struct lock_class *class)
name = class->name;
if (!name) {
name = __get_key_name(class->key, str);
- printk("%s", name);
+ printk(KERN_CONT "%s", name);
} else {
- printk("%s", name);
+ printk(KERN_CONT "%s", name);
if (class->name_version > 1)
- printk("#%d", class->name_version);
+ printk(KERN_CONT "#%d", class->name_version);
if (class->subclass)
- printk("/%d", class->subclass);
+ printk(KERN_CONT "/%d", class->subclass);
}
}
@@ -522,9 +522,9 @@ static void print_lock_name(struct lock_class *class)
get_usage_chars(class, usage);
- printk(" (");
+ printk(KERN_CONT " (");
__print_lock_name(class);
- printk("){%s}", usage);
+ printk(KERN_CONT "){%s}", usage);
}
static void print_lockdep_cache(struct lockdep_map *lock)
@@ -536,7 +536,7 @@ static void print_lockdep_cache(struct lockdep_map *lock)
if (!name)
name = __get_key_name(lock->key->subkeys, str);
- printk("%s", name);
+ printk(KERN_CONT "%s", name);
}
static void print_lock(struct held_lock *hlock)
@@ -551,13 +551,13 @@ static void print_lock(struct held_lock *hlock)
barrier();
if (!class_idx || (class_idx - 1) >= MAX_LOCKDEP_KEYS) {
- printk("<RELEASED>\n");
+ printk(KERN_CONT "<RELEASED>\n");
return;
}
print_lock_name(lock_classes + class_idx - 1);
- printk(", at: ");
- print_ip_sym(hlock->acquire_ip);
+ printk(KERN_CONT ", at: [<%p>] %pS\n",
+ (void *)hlock->acquire_ip, (void *)hlock->acquire_ip);
}
static void lockdep_print_held_locks(struct task_struct *curr)
@@ -792,8 +792,8 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)
printk("\nnew class %p: %s", class->key, class->name);
if (class->name_version > 1)
- printk("#%d", class->name_version);
- printk("\n");
+ printk(KERN_CONT "#%d", class->name_version);
+ printk(KERN_CONT "\n");
dump_stack();
if (!graph_lock()) {
@@ -1071,7 +1071,7 @@ print_circular_bug_entry(struct lock_list *target, int depth)
return 0;
printk("\n-> #%u", depth);
print_lock_name(target->class);
- printk(":\n");
+ printk(KERN_CONT ":\n");
print_stack_trace(&target->trace, 6);
return 0;
@@ -1102,11 +1102,11 @@ print_circular_lock_scenario(struct held_lock *src,
if (parent != source) {
printk("Chain exists of:\n ");
__print_lock_name(source);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(parent);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(target);
- printk("\n\n");
+ printk(KERN_CONT "\n\n");
}
printk(" Possible unsafe locking scenario:\n\n");
@@ -1114,16 +1114,16 @@ print_circular_lock_scenario(struct held_lock *src,
printk(" ---- ----\n");
printk(" lock(");
__print_lock_name(target);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(parent);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(target);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(source);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
}
@@ -1359,22 +1359,22 @@ static void print_lock_class_header(struct lock_class *class, int depth)
printk("%*s->", depth, "");
print_lock_name(class);
- printk(" ops: %lu", class->ops);
- printk(" {\n");
+ printk(KERN_CONT " ops: %lu", class->ops);
+ printk(KERN_CONT " {\n");
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");
+ len += printk(KERN_CONT " at:\n");
print_stack_trace(class->usage_traces + bit, len);
}
}
printk("%*s }\n", depth, "");
- printk("%*s ... key at: ",depth,"");
- print_ip_sym((unsigned long)class->key);
+ printk("%*s ... key at: [<%p>] %pS\n",
+ depth, "", class->key, class->key);
}
/*
@@ -1437,11 +1437,11 @@ print_irq_lock_scenario(struct lock_list *safe_entry,
if (middle_class != unsafe_class) {
printk("Chain exists of:\n ");
__print_lock_name(safe_class);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(middle_class);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(unsafe_class);
- printk("\n\n");
+ printk(KERN_CONT "\n\n");
}
printk(" Possible interrupt unsafe locking scenario:\n\n");
@@ -1449,18 +1449,18 @@ print_irq_lock_scenario(struct lock_list *safe_entry,
printk(" ---- ----\n");
printk(" lock(");
__print_lock_name(unsafe_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" local_irq_disable();\n");
printk(" lock(");
__print_lock_name(safe_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(middle_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" <Interrupt>\n");
printk(" lock(");
__print_lock_name(safe_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
}
@@ -1497,9 +1497,9 @@ print_bad_irq_dependency(struct task_struct *curr,
print_lock(prev);
printk("which would create a new lock dependency:\n");
print_lock_name(hlock_class(prev));
- printk(" ->");
+ printk(KERN_CONT " ->");
print_lock_name(hlock_class(next));
- printk("\n");
+ printk(KERN_CONT "\n");
printk("\nbut this new dependency connects a %s-irq-safe lock:\n",
irqclass);
@@ -1521,8 +1521,7 @@ print_bad_irq_dependency(struct task_struct *curr,
lockdep_print_held_locks(curr);
- printk("\nthe dependencies between %s-irq-safe lock", irqclass);
- printk(" and the holding lock:\n");
+ printk("\nthe dependencies between %s-irq-safe lock and the holding lock:\n", irqclass);
if (!save_trace(&prev_root->trace))
return 0;
print_shortest_lock_dependencies(backwards_entry, prev_root);
@@ -1694,10 +1693,10 @@ print_deadlock_scenario(struct held_lock *nxt,
printk(" ----\n");
printk(" lock(");
__print_lock_name(prev);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(next);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
printk(" May be due to missing lock nesting notation\n\n");
}
@@ -1891,9 +1890,9 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev,
graph_unlock();
printk("\n new dependency: ");
print_lock_name(hlock_class(prev));
- printk(" => ");
+ printk(KERN_CONT " => ");
print_lock_name(hlock_class(next));
- printk("\n");
+ printk(KERN_CONT "\n");
dump_stack();
return graph_lock();
}
@@ -2343,11 +2342,11 @@ print_usage_bug_scenario(struct held_lock *lock)
printk(" ----\n");
printk(" lock(");
__print_lock_name(class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" <Interrupt>\n");
printk(" lock(");
__print_lock_name(class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
}
@@ -2522,14 +2521,18 @@ 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);
+ printk("hardirqs last enabled at (%u): [<%p>] %pS\n",
+ curr->hardirq_enable_event, (void *)curr->hardirq_enable_ip,
+ (void *)curr->hardirq_enable_ip);
+ printk("hardirqs last disabled at (%u): [<%p>] %pS\n",
+ curr->hardirq_disable_event, (void *)curr->hardirq_disable_ip,
+ (void *)curr->hardirq_disable_ip);
+ printk("softirqs last enabled at (%u): [<%p>] %pS\n",
+ curr->softirq_enable_event, (void *)curr->softirq_enable_ip,
+ (void *)curr->softirq_enable_ip);
+ printk("softirqs last disabled at (%u): [<%p>] %pS\n",
+ curr->softirq_disable_event, (void *)curr->softirq_disable_ip,
+ (void *)curr->softirq_disable_ip);
}
static int HARDIRQ_verbose(struct lock_class *class)
@@ -3235,8 +3238,8 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
if (very_verbose(class)) {
printk("\nacquire class [%p] %s", class->key, class->name);
if (class->name_version > 1)
- printk("#%d", class->name_version);
- printk("\n");
+ printk(KERN_CONT "#%d", class->name_version);
+ printk(KERN_CONT "\n");
dump_stack();
}
@@ -3378,7 +3381,7 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock,
printk("%s/%d is trying to release lock (",
curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock);
- printk(") at:\n");
+ printk(KERN_CONT ") 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");
@@ -3871,7 +3874,7 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock,
printk("%s/%d is trying to contend lock (",
curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock);
- printk(") at:\n");
+ printk(KERN_CONT ") at:\n");
print_ip_sym(ip);
printk("but there are no locks held!\n");
printk("\nother info that might help us debug this:\n");
--
2.8.0.rc3.226.g39d4020
^ permalink raw reply related [flat|nested] 4+ messages in thread* Re: [PATCH] lockdep: fix report formatting
2016-11-28 14:24 [PATCH] lockdep: fix report formatting Dmitry Vyukov
@ 2016-11-29 7:50 ` Andrew Donnellan
2016-12-06 9:41 ` Ingo Molnar
2016-12-06 10:13 ` [tip:locking/urgent] lockdep: Fix " tip-bot for Dmitry Vyukov
2 siblings, 0 replies; 4+ messages in thread
From: Andrew Donnellan @ 2016-11-29 7:50 UTC (permalink / raw)
To: Dmitry Vyukov, peterz, mingo
Cc: aryabinin, andreyknvl, joe, linux-kernel, syzkaller
On 29/11/16 01:24, Dmitry Vyukov wrote:
> Since commit 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing
> continuation lines") printk() requires KERN_CONT to continue log
> messages. Lots of printk() in lockdep.c and print_ip_sym() don't
> have it. As the result lockdep reports are completely messed.
>
> Add missing KERN_CONT and inline print_ip_sym() where necessary.
>
> Without this patch all scripts that parse kernel bug reports
> are broken. So it makes sense to get this into 4.9.
I'm glad someone else is looking at this, I started working on a similar
patch but haven't quite finished it :)
>
> Cc: aryabinin@virtuozzo.com
> Cc: andreyknvl@google.com
> Cc: joe@perches.com
> Cc: peterz@infradead.org
> Cc: mingo@redhat.com
> Cc: linux-kernel@vger.kernel.org
> Cc: syzkaller@googlegroups.com
Missing Signed-off-by.
FWIW I think the pr_cont() macro looks nicer than printk(KERN_CONT ...).
--
Andrew Donnellan OzLabs, ADL Canberra
andrew.donnellan@au1.ibm.com IBM Australia Limited
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: [PATCH] lockdep: fix report formatting
2016-11-28 14:24 [PATCH] lockdep: fix report formatting Dmitry Vyukov
2016-11-29 7:50 ` Andrew Donnellan
@ 2016-12-06 9:41 ` Ingo Molnar
2016-12-06 10:13 ` [tip:locking/urgent] lockdep: Fix " tip-bot for Dmitry Vyukov
2 siblings, 0 replies; 4+ messages in thread
From: Ingo Molnar @ 2016-12-06 9:41 UTC (permalink / raw)
To: Dmitry Vyukov
Cc: peterz, mingo, aryabinin, andreyknvl, joe, linux-kernel,
syzkaller
* Dmitry Vyukov <dvyukov@google.com> wrote:
> Since commit 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing
> continuation lines") printk() requires KERN_CONT to continue log
> messages. Lots of printk() in lockdep.c and print_ip_sym() don't
> have it. As the result lockdep reports are completely messed.
>
> Add missing KERN_CONT and inline print_ip_sym() where necessary.
>
> Without this patch all scripts that parse kernel bug reports
> are broken. So it makes sense to get this into 4.9.
>
> Cc: aryabinin@virtuozzo.com
> Cc: andreyknvl@google.com
> Cc: joe@perches.com
> Cc: peterz@infradead.org
> Cc: mingo@redhat.com
> Cc: linux-kernel@vger.kernel.org
> Cc: syzkaller@googlegroups.com
JFYI, I've added your Signed-off-by to this fix.
Thanks,
Ingo
^ permalink raw reply [flat|nested] 4+ messages in thread* [tip:locking/urgent] lockdep: Fix report formatting
2016-11-28 14:24 [PATCH] lockdep: fix report formatting Dmitry Vyukov
2016-11-29 7:50 ` Andrew Donnellan
2016-12-06 9:41 ` Ingo Molnar
@ 2016-12-06 10:13 ` tip-bot for Dmitry Vyukov
2 siblings, 0 replies; 4+ messages in thread
From: tip-bot for Dmitry Vyukov @ 2016-12-06 10:13 UTC (permalink / raw)
To: linux-tip-commits
Cc: tglx, dvyukov, hpa, linux-kernel, peterz, torvalds, mingo
Commit-ID: f943fe0faf27991d256e10b5a85f175385c64cdc
Gitweb: http://git.kernel.org/tip/f943fe0faf27991d256e10b5a85f175385c64cdc
Author: Dmitry Vyukov <dvyukov@google.com>
AuthorDate: Mon, 28 Nov 2016 15:24:43 +0100
Committer: Ingo Molnar <mingo@kernel.org>
CommitDate: Tue, 6 Dec 2016 10:40:08 +0100
lockdep: Fix report formatting
Since commit:
4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")
printk() requires KERN_CONT to continue log messages. Lots of printk()
in lockdep.c and print_ip_sym() don't have it. As the result lockdep
reports are completely messed up.
Add missing KERN_CONT and inline print_ip_sym() where necessary.
Example of a messed up report:
0-rc5+ #41 Not tainted
-------------------------------------------------------
syz-executor0/5036 is trying to acquire lock:
(
rtnl_mutex
){+.+.+.}
, at:
[<ffffffff86b3d6ac>] rtnl_lock+0x1c/0x20
but task is already holding lock:
(
&net->packet.sklist_lock
){+.+...}
, at:
[<ffffffff873541a6>] packet_diag_dump+0x1a6/0x1920
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #3
(
&net->packet.sklist_lock
+.+...}
...
Without this patch all scripts that parse kernel bug reports are broken.
Signed-off-by: Dmitry Vyukov <dvyukov@google.com>
Signed-off-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: andreyknvl@google.com
Cc: aryabinin@virtuozzo.com
Cc: joe@perches.com
Cc: syzkaller@googlegroups.com
Link: http://lkml.kernel.org/r/1480343083-48731-1-git-send-email-dvyukov@google.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
kernel/locking/lockdep.c | 111 ++++++++++++++++++++++++-----------------------
1 file changed, 57 insertions(+), 54 deletions(-)
diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 589d763..4d7ffc0 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -506,13 +506,13 @@ static void __print_lock_name(struct lock_class *class)
name = class->name;
if (!name) {
name = __get_key_name(class->key, str);
- printk("%s", name);
+ printk(KERN_CONT "%s", name);
} else {
- printk("%s", name);
+ printk(KERN_CONT "%s", name);
if (class->name_version > 1)
- printk("#%d", class->name_version);
+ printk(KERN_CONT "#%d", class->name_version);
if (class->subclass)
- printk("/%d", class->subclass);
+ printk(KERN_CONT "/%d", class->subclass);
}
}
@@ -522,9 +522,9 @@ static void print_lock_name(struct lock_class *class)
get_usage_chars(class, usage);
- printk(" (");
+ printk(KERN_CONT " (");
__print_lock_name(class);
- printk("){%s}", usage);
+ printk(KERN_CONT "){%s}", usage);
}
static void print_lockdep_cache(struct lockdep_map *lock)
@@ -536,7 +536,7 @@ static void print_lockdep_cache(struct lockdep_map *lock)
if (!name)
name = __get_key_name(lock->key->subkeys, str);
- printk("%s", name);
+ printk(KERN_CONT "%s", name);
}
static void print_lock(struct held_lock *hlock)
@@ -551,13 +551,13 @@ static void print_lock(struct held_lock *hlock)
barrier();
if (!class_idx || (class_idx - 1) >= MAX_LOCKDEP_KEYS) {
- printk("<RELEASED>\n");
+ printk(KERN_CONT "<RELEASED>\n");
return;
}
print_lock_name(lock_classes + class_idx - 1);
- printk(", at: ");
- print_ip_sym(hlock->acquire_ip);
+ printk(KERN_CONT ", at: [<%p>] %pS\n",
+ (void *)hlock->acquire_ip, (void *)hlock->acquire_ip);
}
static void lockdep_print_held_locks(struct task_struct *curr)
@@ -792,8 +792,8 @@ register_lock_class(struct lockdep_map *lock, unsigned int subclass, int force)
printk("\nnew class %p: %s", class->key, class->name);
if (class->name_version > 1)
- printk("#%d", class->name_version);
- printk("\n");
+ printk(KERN_CONT "#%d", class->name_version);
+ printk(KERN_CONT "\n");
dump_stack();
if (!graph_lock()) {
@@ -1071,7 +1071,7 @@ print_circular_bug_entry(struct lock_list *target, int depth)
return 0;
printk("\n-> #%u", depth);
print_lock_name(target->class);
- printk(":\n");
+ printk(KERN_CONT ":\n");
print_stack_trace(&target->trace, 6);
return 0;
@@ -1102,11 +1102,11 @@ print_circular_lock_scenario(struct held_lock *src,
if (parent != source) {
printk("Chain exists of:\n ");
__print_lock_name(source);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(parent);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(target);
- printk("\n\n");
+ printk(KERN_CONT "\n\n");
}
printk(" Possible unsafe locking scenario:\n\n");
@@ -1114,16 +1114,16 @@ print_circular_lock_scenario(struct held_lock *src,
printk(" ---- ----\n");
printk(" lock(");
__print_lock_name(target);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(parent);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(target);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(source);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
}
@@ -1359,22 +1359,22 @@ static void print_lock_class_header(struct lock_class *class, int depth)
printk("%*s->", depth, "");
print_lock_name(class);
- printk(" ops: %lu", class->ops);
- printk(" {\n");
+ printk(KERN_CONT " ops: %lu", class->ops);
+ printk(KERN_CONT " {\n");
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");
+ len += printk(KERN_CONT " at:\n");
print_stack_trace(class->usage_traces + bit, len);
}
}
printk("%*s }\n", depth, "");
- printk("%*s ... key at: ",depth,"");
- print_ip_sym((unsigned long)class->key);
+ printk("%*s ... key at: [<%p>] %pS\n",
+ depth, "", class->key, class->key);
}
/*
@@ -1437,11 +1437,11 @@ print_irq_lock_scenario(struct lock_list *safe_entry,
if (middle_class != unsafe_class) {
printk("Chain exists of:\n ");
__print_lock_name(safe_class);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(middle_class);
- printk(" --> ");
+ printk(KERN_CONT " --> ");
__print_lock_name(unsafe_class);
- printk("\n\n");
+ printk(KERN_CONT "\n\n");
}
printk(" Possible interrupt unsafe locking scenario:\n\n");
@@ -1449,18 +1449,18 @@ print_irq_lock_scenario(struct lock_list *safe_entry,
printk(" ---- ----\n");
printk(" lock(");
__print_lock_name(unsafe_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" local_irq_disable();\n");
printk(" lock(");
__print_lock_name(safe_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(middle_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" <Interrupt>\n");
printk(" lock(");
__print_lock_name(safe_class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
}
@@ -1497,9 +1497,9 @@ print_bad_irq_dependency(struct task_struct *curr,
print_lock(prev);
printk("which would create a new lock dependency:\n");
print_lock_name(hlock_class(prev));
- printk(" ->");
+ printk(KERN_CONT " ->");
print_lock_name(hlock_class(next));
- printk("\n");
+ printk(KERN_CONT "\n");
printk("\nbut this new dependency connects a %s-irq-safe lock:\n",
irqclass);
@@ -1521,8 +1521,7 @@ print_bad_irq_dependency(struct task_struct *curr,
lockdep_print_held_locks(curr);
- printk("\nthe dependencies between %s-irq-safe lock", irqclass);
- printk(" and the holding lock:\n");
+ printk("\nthe dependencies between %s-irq-safe lock and the holding lock:\n", irqclass);
if (!save_trace(&prev_root->trace))
return 0;
print_shortest_lock_dependencies(backwards_entry, prev_root);
@@ -1694,10 +1693,10 @@ print_deadlock_scenario(struct held_lock *nxt,
printk(" ----\n");
printk(" lock(");
__print_lock_name(prev);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" lock(");
__print_lock_name(next);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
printk(" May be due to missing lock nesting notation\n\n");
}
@@ -1891,9 +1890,9 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev,
graph_unlock();
printk("\n new dependency: ");
print_lock_name(hlock_class(prev));
- printk(" => ");
+ printk(KERN_CONT " => ");
print_lock_name(hlock_class(next));
- printk("\n");
+ printk(KERN_CONT "\n");
dump_stack();
return graph_lock();
}
@@ -2343,11 +2342,11 @@ print_usage_bug_scenario(struct held_lock *lock)
printk(" ----\n");
printk(" lock(");
__print_lock_name(class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk(" <Interrupt>\n");
printk(" lock(");
__print_lock_name(class);
- printk(");\n");
+ printk(KERN_CONT ");\n");
printk("\n *** DEADLOCK ***\n\n");
}
@@ -2522,14 +2521,18 @@ 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);
+ printk("hardirqs last enabled at (%u): [<%p>] %pS\n",
+ curr->hardirq_enable_event, (void *)curr->hardirq_enable_ip,
+ (void *)curr->hardirq_enable_ip);
+ printk("hardirqs last disabled at (%u): [<%p>] %pS\n",
+ curr->hardirq_disable_event, (void *)curr->hardirq_disable_ip,
+ (void *)curr->hardirq_disable_ip);
+ printk("softirqs last enabled at (%u): [<%p>] %pS\n",
+ curr->softirq_enable_event, (void *)curr->softirq_enable_ip,
+ (void *)curr->softirq_enable_ip);
+ printk("softirqs last disabled at (%u): [<%p>] %pS\n",
+ curr->softirq_disable_event, (void *)curr->softirq_disable_ip,
+ (void *)curr->softirq_disable_ip);
}
static int HARDIRQ_verbose(struct lock_class *class)
@@ -3235,8 +3238,8 @@ static int __lock_acquire(struct lockdep_map *lock, unsigned int subclass,
if (very_verbose(class)) {
printk("\nacquire class [%p] %s", class->key, class->name);
if (class->name_version > 1)
- printk("#%d", class->name_version);
- printk("\n");
+ printk(KERN_CONT "#%d", class->name_version);
+ printk(KERN_CONT "\n");
dump_stack();
}
@@ -3378,7 +3381,7 @@ print_unlock_imbalance_bug(struct task_struct *curr, struct lockdep_map *lock,
printk("%s/%d is trying to release lock (",
curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock);
- printk(") at:\n");
+ printk(KERN_CONT ") 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");
@@ -3871,7 +3874,7 @@ print_lock_contention_bug(struct task_struct *curr, struct lockdep_map *lock,
printk("%s/%d is trying to contend lock (",
curr->comm, task_pid_nr(curr));
print_lockdep_cache(lock);
- printk(") at:\n");
+ printk(KERN_CONT ") at:\n");
print_ip_sym(ip);
printk("but there are no locks held!\n");
printk("\nother info that might help us debug this:\n");
^ permalink raw reply related [flat|nested] 4+ messages in thread
end of thread, other threads:[~2016-12-06 10:14 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2016-11-28 14:24 [PATCH] lockdep: fix report formatting Dmitry Vyukov
2016-11-29 7:50 ` Andrew Donnellan
2016-12-06 9:41 ` Ingo Molnar
2016-12-06 10:13 ` [tip:locking/urgent] lockdep: Fix " tip-bot for Dmitry Vyukov
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.