[PATCH] stacktrace: fix spaces and annoying extra newlines

[PATCH] stacktrace: fix spaces and annoying extra newlines

[Omar Sandoval]

From: Omar Sandoval <osandov@fb.com>

Since KERN_CONT became meaningful again, lockdep stack traces have
looked like this:

[    5.561122] -> #1 (B){+.+...}:
[    5.561528]
[    5.561532] [<ffffffff810d8873>] lock_acquire+0xc3/0x210
[    5.562178]
[    5.562181] [<ffffffff816f6414>] mutex_lock_nested+0x74/0x6d0
[    5.562861]
[    5.562880] [<ffffffffa01aa3c3>] init_btrfs_fs+0x21/0x196 [btrfs]
[    5.563717]
[    5.563721] [<ffffffff81000472>] do_one_initcall+0x52/0x1b0
[    5.564554]
[    5.564559] [<ffffffff811a3af6>] do_init_module+0x5f/0x209
[    5.565357]
[    5.565361] [<ffffffff81122f4d>] load_module+0x218d/0x2b80
[    5.566020]
[    5.566021] [<ffffffff81123beb>] SyS_finit_module+0xeb/0x120
[    5.566694]
[    5.566696] [<ffffffff816fd241>] entry_SYSCALL_64_fastpath+0x1f/0xc2

That's happening because each printk() call now gets printed on its own
line, and we do a separate call to print the spaces before the symbol.

This is what it should look like:

[    6.650322] -> #1 (B){+.+...}:
[    6.651053]        [<ffffffff810d8873>] lock_acquire+0xc3/0x210
[    6.652000]        [<ffffffff816f6414>] mutex_lock_nested+0x74/0x6d0
[    6.652664]        [<ffffffffa01b43c3>] init_btrfs_fs+0x21/0x196 [btrfs]
[    6.653288]        [<ffffffff81000472>] do_one_initcall+0x52/0x1b0
[    6.653858]        [<ffffffff811a3ae6>] do_init_module+0x5f/0x209
[    6.654426]        [<ffffffff81122f3d>] load_module+0x218d/0x2b80
[    6.654992]        [<ffffffff81123bdb>] SyS_finit_module+0xeb/0x120
[    6.655591]        [<ffffffff816fd241>] entry_SYSCALL_64_fastpath+0x1f/0xc2

Fix it by doing the printk() directly instead of using the
print_ip_sym() helper.

Fixes: 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Omar Sandoval <osandov@fb.com>
---
Patch is based on v4.10-rc7. That print_ip_sym() helper isn't all that
complicated and it probably causes more problems than it solves with
KERN_CONT and all. I'm not entirely sure who should take this, but it's
somewhat lockdep related, so it can probably go through tip for 4.11?

 kernel/stacktrace.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/kernel/stacktrace.c b/kernel/stacktrace.c
index b6e4c16377c7..625573af2a3c 100644
--- a/kernel/stacktrace.c
+++ b/kernel/stacktrace.c
@@ -14,13 +14,14 @@
 void print_stack_trace(struct stack_trace *trace, int spaces)
 {
 	int i;
+	void *ip;
 
 	if (WARN_ON(!trace->entries))
 		return;
 
 	for (i = 0; i < trace->nr_entries; i++) {
-		printk("%*c", 1 + spaces, ' ');
-		print_ip_sym(trace->entries[i]);
+		ip = (void *)trace->entries[i];
+		printk("%*c[<%p>] %pS\n", 1 + spaces, ' ', ip, ip);
 	}
 }
 EXPORT_SYMBOL_GPL(print_stack_trace);
-- 
2.11.1

Re: [PATCH] stacktrace: fix spaces and annoying extra newlines

[Linus Torvalds]

Hmm.

Looks ok, except I think we migth want to go even further:

On Tue, Feb 7, 2017 at 2:44 PM, Omar Sandoval <osandov@osandov.com> wrote:
>
> Since KERN_CONT became meaningful again, lockdep stack traces have
> looked like this:

[ removed really ugly trace ]

> This is what it should look like:
>
> [    6.650322] -> #1 (B){+.+...}:
> [    6.651053]        [<ffffffff810d8873>] lock_acquire+0xc3/0x210
> [    6.652000]        [<ffffffff816f6414>] mutex_lock_nested+0x74/0x6d0
> [    6.652664]        [<ffffffffa01b43c3>] init_btrfs_fs+0x21/0x196 [btrfs]
> [    6.653288]        [<ffffffff81000472>] do_one_initcall+0x52/0x1b0
> [    6.653858]        [<ffffffff811a3ae6>] do_init_module+0x5f/0x209
> [    6.654426]        [<ffffffff81122f3d>] load_module+0x218d/0x2b80
> [    6.654992]        [<ffffffff81123bdb>] SyS_finit_module+0xeb/0x120
> [    6.655591]        [<ffffffff816fd241>] entry_SYSCALL_64_fastpath+0x1f/0xc2

That's still pretty ugly.

Actually, let's just remove those hex numbers too, which buy you nothing at all.

> -               printk("%*c", 1 + spaces, ' ');
> -               print_ip_sym(trace->entries[i]);
> +               ip = (void *)trace->entries[i];
> +               printk("%*c[<%p>] %pS\n", 1 + spaces, ' ', ip, ip);

So how does it look if we make that just be

        printk("%*c%pS\n", 1 + spaces, ' ', (void *)trace->entries[i]);

which also avoids the extra variable because the thing is only used
once anyway. We've removed the hex numbers from other printouts, and
they really are completely useless with modules and kernel randomized
addresses.

Would you mind testing such a thing and re-submitting?

               Linus

[PATCH v2] stacktrace: fix address, newline ugliness

[Omar Sandoval]

From: Omar Sandoval <osandov@fb.com>

Since KERN_CONT became meaningful again, lockdep stack traces have had
annoying extra newlines, like this:

[    5.561122] -> #1 (B){+.+...}:
[    5.561528]
[    5.561532] [<ffffffff810d8873>] lock_acquire+0xc3/0x210
[    5.562178]
[    5.562181] [<ffffffff816f6414>] mutex_lock_nested+0x74/0x6d0
[    5.562861]
[    5.562880] [<ffffffffa01aa3c3>] init_btrfs_fs+0x21/0x196 [btrfs]
[    5.563717]
[    5.563721] [<ffffffff81000472>] do_one_initcall+0x52/0x1b0
[    5.564554]
[    5.564559] [<ffffffff811a3af6>] do_init_module+0x5f/0x209
[    5.565357]
[    5.565361] [<ffffffff81122f4d>] load_module+0x218d/0x2b80
[    5.566020]
[    5.566021] [<ffffffff81123beb>] SyS_finit_module+0xeb/0x120
[    5.566694]
[    5.566696] [<ffffffff816fd241>] entry_SYSCALL_64_fastpath+0x1f/0xc2

That's happening because each printk() call now gets printed on its own
line, and we do a separate call to print the spaces before the symbol.
Fix it by doing the printk() directly instead of using the
print_ip_sym() helper.

Additionally, the symbol address isn't very helpful, so let's get rid of
that, too. The final result looks like this:

[    5.194518] -> #1 (B){+.+...}:
[    5.195002]        lock_acquire+0xc3/0x210
[    5.195439]        mutex_lock_nested+0x74/0x6d0
[    5.195976]        init_btrfs_fs+0x21/0x196 [btrfs]
[    5.196491]        do_one_initcall+0x52/0x1b0
[    5.196939]        do_init_module+0x5f/0x209
[    5.197355]        load_module+0x218d/0x2b80
[    5.197792]        SyS_finit_module+0xeb/0x120
[    5.198251]        entry_SYSCALL_64_fastpath+0x1f/0xc2

Fixes: 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Omar Sandoval <osandov@fb.com>
---
 kernel/stacktrace.c | 12 ++++--------
 1 file changed, 4 insertions(+), 8 deletions(-)

diff --git a/kernel/stacktrace.c b/kernel/stacktrace.c
index b6e4c16377c7..9c15a9124e83 100644
--- a/kernel/stacktrace.c
+++ b/kernel/stacktrace.c
@@ -18,10 +18,8 @@ void print_stack_trace(struct stack_trace *trace, int spaces)
 	if (WARN_ON(!trace->entries))
 		return;
 
-	for (i = 0; i < trace->nr_entries; i++) {
-		printk("%*c", 1 + spaces, ' ');
-		print_ip_sym(trace->entries[i]);
-	}
+	for (i = 0; i < trace->nr_entries; i++)
+		printk("%*c%pS\n", 1 + spaces, ' ', (void *)trace->entries[i]);
 }
 EXPORT_SYMBOL_GPL(print_stack_trace);
 
@@ -29,7 +27,6 @@ int snprint_stack_trace(char *buf, size_t size,
 			struct stack_trace *trace, int spaces)
 {
 	int i;
-	unsigned long ip;
 	int generated;
 	int total = 0;
 
@@ -37,9 +34,8 @@ int snprint_stack_trace(char *buf, size_t size,
 		return 0;
 
 	for (i = 0; i < trace->nr_entries; i++) {
-		ip = trace->entries[i];
-		generated = snprintf(buf, size, "%*c[<%p>] %pS\n",
-				1 + spaces, ' ', (void *) ip, (void *) ip);
+		generated = snprintf(buf, size, "%*c%pS\n", 1 + spaces, ' ',
+				     (void *)trace->entries[i]);
 
 		total += generated;
 
-- 
2.11.1

[tip:locking/urgent] stacktrace, lockdep: Fix address, newline ugliness

[tip-bot for Omar Sandoval]

Commit-ID:  bfeda41d06d85ad9d52f2413cfc2b77be5022f75
Gitweb:     http://git.kernel.org/tip/bfeda41d06d85ad9d52f2413cfc2b77be5022f75
Author:     Omar Sandoval <osandov@fb.com>
AuthorDate: Tue, 7 Feb 2017 15:33:20 -0800
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Wed, 8 Feb 2017 08:21:31 +0100

stacktrace, lockdep: Fix address, newline ugliness

Since KERN_CONT became meaningful again, lockdep stack traces have had
annoying extra newlines, like this:

[    5.561122] -> #1 (B){+.+...}:
[    5.561528]
[    5.561532] [<ffffffff810d8873>] lock_acquire+0xc3/0x210
[    5.562178]
[    5.562181] [<ffffffff816f6414>] mutex_lock_nested+0x74/0x6d0
[    5.562861]
[    5.562880] [<ffffffffa01aa3c3>] init_btrfs_fs+0x21/0x196 [btrfs]
[    5.563717]
[    5.563721] [<ffffffff81000472>] do_one_initcall+0x52/0x1b0
[    5.564554]
[    5.564559] [<ffffffff811a3af6>] do_init_module+0x5f/0x209
[    5.565357]
[    5.565361] [<ffffffff81122f4d>] load_module+0x218d/0x2b80
[    5.566020]
[    5.566021] [<ffffffff81123beb>] SyS_finit_module+0xeb/0x120
[    5.566694]
[    5.566696] [<ffffffff816fd241>] entry_SYSCALL_64_fastpath+0x1f/0xc2

That's happening because each printk() call now gets printed on its own
line, and we do a separate call to print the spaces before the symbol.
Fix it by doing the printk() directly instead of using the
print_ip_sym() helper.

Additionally, the symbol address isn't very helpful, so let's get rid of
that, too. The final result looks like this:

[    5.194518] -> #1 (B){+.+...}:
[    5.195002]        lock_acquire+0xc3/0x210
[    5.195439]        mutex_lock_nested+0x74/0x6d0
[    5.196491]        do_one_initcall+0x52/0x1b0
[    5.196939]        do_init_module+0x5f/0x209
[    5.197355]        load_module+0x218d/0x2b80
[    5.197792]        SyS_finit_module+0xeb/0x120
[    5.198251]        entry_SYSCALL_64_fastpath+0x1f/0xc2

Suggested-by: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Omar Sandoval <osandov@fb.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: kernel-team@fb.com
Fixes: 4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")
Link: http://lkml.kernel.org/r/43b4e114724b2bdb0308fa86cb33aa07d3d67fad.1486510315.git.osandov@fb.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/stacktrace.c | 12 ++++--------
 1 file changed, 4 insertions(+), 8 deletions(-)

diff --git a/kernel/stacktrace.c b/kernel/stacktrace.c
index b6e4c16..9c15a91 100644
--- a/kernel/stacktrace.c
+++ b/kernel/stacktrace.c
@@ -18,10 +18,8 @@ void print_stack_trace(struct stack_trace *trace, int spaces)
 	if (WARN_ON(!trace->entries))
 		return;
 
-	for (i = 0; i < trace->nr_entries; i++) {
-		printk("%*c", 1 + spaces, ' ');
-		print_ip_sym(trace->entries[i]);
-	}
+	for (i = 0; i < trace->nr_entries; i++)
+		printk("%*c%pS\n", 1 + spaces, ' ', (void *)trace->entries[i]);
 }
 EXPORT_SYMBOL_GPL(print_stack_trace);
 
@@ -29,7 +27,6 @@ int snprint_stack_trace(char *buf, size_t size,
 			struct stack_trace *trace, int spaces)
 {
 	int i;
-	unsigned long ip;
 	int generated;
 	int total = 0;
 
@@ -37,9 +34,8 @@ int snprint_stack_trace(char *buf, size_t size,
 		return 0;
 
 	for (i = 0; i < trace->nr_entries; i++) {
-		ip = trace->entries[i];
-		generated = snprintf(buf, size, "%*c[<%p>] %pS\n",
-				1 + spaces, ' ', (void *) ip, (void *) ip);
+		generated = snprintf(buf, size, "%*c%pS\n", 1 + spaces, ' ',
+				     (void *)trace->entries[i]);
 
 		total += generated;