[PATCH] xtensa: improve stack dumping

[PATCH] xtensa: improve stack dumping

[Max Filippov]

Collect whole stack dump lines in a buffer and print the whole buffer
when it's ready with pr_info instead of pr_cont. This makes stack dump
lines consistent in SMP case and relies less on pr_cont/printk
differences related to timestamps.
Make size of stack dump configurable.
Drop extra newline output in show_trace as its output format does not
depend on CONFIG_KALLSYMS.

Signed-off-by: Max Filippov <jcmvbkbc@gmail.com>
---
 arch/xtensa/Kconfig.debug  |  7 +++++++
 arch/xtensa/kernel/traps.c | 12 ++++++------
 2 files changed, 13 insertions(+), 6 deletions(-)

diff --git a/arch/xtensa/Kconfig.debug b/arch/xtensa/Kconfig.debug
index 39de98e20018..83cc8d12fa0e 100644
--- a/arch/xtensa/Kconfig.debug
+++ b/arch/xtensa/Kconfig.debug
@@ -31,3 +31,10 @@ config S32C1I_SELFTEST
 	  It is easy to make wrong hardware configuration, this test should catch it early.
 
 	  Say 'N' on stable hardware.
+
+config PRINT_STACK_DEPTH
+	int "Stack depth to print" if DEBUG_KERNEL
+	default 64
+	help
+	  This option allows you to set the stack depth that the kernel
+	  prints in stack traces.
diff --git a/arch/xtensa/kernel/traps.c b/arch/xtensa/kernel/traps.c
index 4a6c495ce9b6..b0c952652c73 100644
--- a/arch/xtensa/kernel/traps.c
+++ b/arch/xtensa/kernel/traps.c
@@ -491,17 +491,15 @@ void show_trace(struct task_struct *task, unsigned long *sp)
 
 	pr_info("Call Trace:\n");
 	walk_stackframe(sp, show_trace_cb, NULL);
-#ifndef CONFIG_KALLSYMS
-	pr_cont("\n");
-#endif
 }
 
-static int kstack_depth_to_print = 24;
+static int kstack_depth_to_print = CONFIG_PRINT_STACK_DEPTH;
 
 void show_stack(struct task_struct *task, unsigned long *sp)
 {
 	int i = 0;
 	unsigned long *stack;
+	char buf[9 * 8 + 1];
 
 	if (!sp)
 		sp = stack_pointer(task);
@@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
 	for (i = 0; i < kstack_depth_to_print; i++) {
 		if (kstack_end(sp))
 			break;
-		pr_cont(" %08lx", *sp++);
+		sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
 		if (i % 8 == 7)
-			pr_cont("\n");
+			pr_info("%s\n", buf);
 	}
+	if (i % 8)
+		pr_info("%s\n", buf);
 	show_trace(task, stack);
 }
 
-- 
2.20.1

Re: [PATCH] xtensa: improve stack dumping

[Dmitry Safonov]

Hi Max,

On 11/6/19 6:16 PM, Max Filippov wrote:
> Collect whole stack dump lines in a buffer and print the whole buffer
> when it's ready with pr_info instead of pr_cont. This makes stack dump
> lines consistent in SMP case and relies less on pr_cont/printk
> differences related to timestamps.
> Make size of stack dump configurable.
> Drop extra newline output in show_trace as its output format does not
> depend on CONFIG_KALLSYMS.
> 
> Signed-off-by: Max Filippov <jcmvbkbc@gmail.com>

[..]

>  void show_stack(struct task_struct *task, unsigned long *sp)
>  {
>  	int i = 0;
>  	unsigned long *stack;
> +	char buf[9 * 8 + 1];
>  
>  	if (!sp)
>  		sp = stack_pointer(task);
> @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
>  	for (i = 0; i < kstack_depth_to_print; i++) {
>  		if (kstack_end(sp))
>  			break;
> -		pr_cont(" %08lx", *sp++);
> +		sprintf(buf + (i % 8) * 9, " %08lx", *sp++);

buf is on the stack, does sprintf() put null-terminator for hex?

>  		if (i % 8 == 7)
> -			pr_cont("\n");
> +			pr_info("%s\n", buf);
>  	}
> +	if (i % 8)
> +		pr_info("%s\n", buf);

If the stack trace ends with (i % 8 == 7), you'll double-print the last
line?

Thanks,
          Dmitry

Re: [PATCH] xtensa: improve stack dumping

[Max Filippov]

On Wed, Nov 6, 2019 at 12:51 PM Dmitry Safonov <dima@arista.com> wrote:
> On 11/6/19 6:16 PM, Max Filippov wrote:
> > @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
> >       for (i = 0; i < kstack_depth_to_print; i++) {
> >               if (kstack_end(sp))
> >                       break;
> > -             pr_cont(" %08lx", *sp++);
> > +             sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
>
> buf is on the stack, does sprintf() put null-terminator for hex?

It should put null-terminator regardless of the format string.

> >               if (i % 8 == 7)
> > -                     pr_cont("\n");
> > +                     pr_info("%s\n", buf);
> >       }
> > +     if (i % 8)
> > +             pr_info("%s\n", buf);
>
> If the stack trace ends with (i % 8 == 7), you'll double-print the last
> line?

No, I don't think so. 'For' loop condition is checked after i++, so if
loop ends with i % 8 == 7 then its last iteration was done with
i % 8 == 6 and thus the buf haven't been printed.

-- 
Thanks.
-- Max

Re: [PATCH] xtensa: improve stack dumping

[Dmitry Safonov]

On 11/6/19 10:00 PM, Max Filippov wrote:
> On Wed, Nov 6, 2019 at 12:51 PM Dmitry Safonov <dima@arista.com> wrote:
>> On 11/6/19 6:16 PM, Max Filippov wrote:
>>> @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
>>>       for (i = 0; i < kstack_depth_to_print; i++) {
>>>               if (kstack_end(sp))
>>>                       break;
>>> -             pr_cont(" %08lx", *sp++);
>>> +             sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
>>
>> buf is on the stack, does sprintf() put null-terminator for hex?
> 
> It should put null-terminator regardless of the format string.

Always unsure what to expect from printf() :)

> 
>>>               if (i % 8 == 7)
>>> -                     pr_cont("\n");
>>> +                     pr_info("%s\n", buf);
>>>       }
>>> +     if (i % 8)
>>> +             pr_info("%s\n", buf);
>>
>> If the stack trace ends with (i % 8 == 7), you'll double-print the last
>> line?
> 
> No, I don't think so. 'For' loop condition is checked after i++, so if
> loop ends with i % 8 == 7 then its last iteration was done with
> i % 8 == 6 and thus the buf haven't been printed.

Ah, right - me being stupid.

Thanks,
          Dmitry

Re: [PATCH] xtensa: improve stack dumping

[Joe Perches]

On Wed, 2019-11-06 at 10:16 -0800, Max Filippov wrote:
> Collect whole stack dump lines in a buffer and print the whole buffer
> when it's ready with pr_info instead of pr_cont. This makes stack dump
> lines consistent in SMP case and relies less on pr_cont/printk
> differences related to timestamps.
> Make size of stack dump configurable.
> Drop extra newline output in show_trace as its output format does not
> depend on CONFIG_KALLSYMS.
[]
> diff --git a/arch/xtensa/kernel/traps.c b/arch/xtensa/kernel/traps.c
[]
> @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
>  	for (i = 0; i < kstack_depth_to_print; i++) {
>  		if (kstack_end(sp))
>  			break;
> -		pr_cont(" %08lx", *sp++);
> +		sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
>  		if (i % 8 == 7)
> -			pr_cont("\n");
> +			pr_info("%s\n", buf);
>  	}
> +	if (i % 8)
> +		pr_info("%s\n", buf);

Could this be done using hex_dump_to_buffer
by precalculating kstack_end ?

Re: [PATCH] xtensa: improve stack dumping

[Max Filippov]

On Wed, Nov 6, 2019 at 2:34 PM Joe Perches <joe@perches.com> wrote:
> > @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
> >       for (i = 0; i < kstack_depth_to_print; i++) {
> >               if (kstack_end(sp))
> >                       break;
> > -             pr_cont(" %08lx", *sp++);
> > +             sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
> >               if (i % 8 == 7)
> > -                     pr_cont("\n");
> > +                     pr_info("%s\n", buf);
> >       }
> > +     if (i % 8)
> > +             pr_info("%s\n", buf);
>
> Could this be done using hex_dump_to_buffer
> by precalculating kstack_end ?

I've got this, but it doesn't look very attractive to me:

void show_stack(struct task_struct *task, unsigned long *sp)
{
        unsigned long *stack;
        int len;

        if (!sp)
                sp = stack_pointer(task);
        stack = sp;

        len = min((-(unsigned long)stack) & (THREAD_SIZE - 4),
                  kstack_depth_to_print * 4ul);

        pr_info("Stack:\n");

        for (; len > 0; len -= 32) {
                char buf[9 * 8 + 1];

                hex_dump_to_buffer(sp, min(len, 32), 32, 4,
                                   buf, sizeof(buf), false);
                pr_info(" %08lx:  %s\n", (unsigned long)sp, buf);
                sp += 8;
        }
        show_trace(task, stack);
}

-- 
Thanks.
-- Max

Re: [PATCH] xtensa: improve stack dumping

[Petr Mladek]

On Wed 2019-11-06 16:21:51, Max Filippov wrote:
> On Wed, Nov 6, 2019 at 2:34 PM Joe Perches <joe@perches.com> wrote:
> > > @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
> > >       for (i = 0; i < kstack_depth_to_print; i++) {
> > >               if (kstack_end(sp))
> > >                       break;
> > > -             pr_cont(" %08lx", *sp++);
> > > +             sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
> > >               if (i % 8 == 7)
> > > -                     pr_cont("\n");
> > > +                     pr_info("%s\n", buf);
> > >       }
> > > +     if (i % 8)
> > > +             pr_info("%s\n", buf);
> >
> > Could this be done using hex_dump_to_buffer
> > by precalculating kstack_end ?
> 
> I've got this, but it doesn't look very attractive to me:
> 
> void show_stack(struct task_struct *task, unsigned long *sp)
> {
>         unsigned long *stack;
>         int len;
> 
>         if (!sp)
>                 sp = stack_pointer(task);
>         stack = sp;
> 
>         len = min((-(unsigned long)stack) & (THREAD_SIZE - 4),
>                   kstack_depth_to_print * 4ul);
> 
>         pr_info("Stack:\n");
> 
>         for (; len > 0; len -= 32) {
>                 char buf[9 * 8 + 1];
> 
>                 hex_dump_to_buffer(sp, min(len, 32), 32, 4,
>                                    buf, sizeof(buf), false);
>                 pr_info(" %08lx:  %s\n", (unsigned long)sp, buf);
>                 sp += 8;
>         }

I wonder if the cycle actually could get replaced by a single call:

	print_hex_dump(KERN_INFO, "", DUMP_PREFIX_OFFSET,
		       16, 1, sp, len, false);

print_hex_dump() currently does not allow to print 8 bytes per-line.
Either 16 is acceptable or hex_dump() function could be updated.

Best Regards,
Petr

Re: [PATCH] xtensa: improve stack dumping

[Joe Perches]

On Thu, 2019-11-07 at 15:38 +0100, Petr Mladek wrote:
> On Wed 2019-11-06 16:21:51, Max Filippov wrote:
> > On Wed, Nov 6, 2019 at 2:34 PM Joe Perches <joe@perches.com> wrote:
> > > > @@ -512,10 +510,12 @@ void show_stack(struct task_struct *task, unsigned long *sp)
> > > >       for (i = 0; i < kstack_depth_to_print; i++) {
> > > >               if (kstack_end(sp))
> > > >                       break;
> > > > -             pr_cont(" %08lx", *sp++);
> > > > +             sprintf(buf + (i % 8) * 9, " %08lx", *sp++);
> > > >               if (i % 8 == 7)
> > > > -                     pr_cont("\n");
> > > > +                     pr_info("%s\n", buf);
> > > >       }
> > > > +     if (i % 8)
> > > > +             pr_info("%s\n", buf);
> > > 
> > > Could this be done using hex_dump_to_buffer
> > > by precalculating kstack_end ?
> > 
> > I've got this, but it doesn't look very attractive to me:
> > 
> > void show_stack(struct task_struct *task, unsigned long *sp)
> > {
> >         unsigned long *stack;
> >         int len;
> > 
> >         if (!sp)
> >                 sp = stack_pointer(task);
> >         stack = sp;
> > 
> >         len = min((-(unsigned long)stack) & (THREAD_SIZE - 4),
> >                   kstack_depth_to_print * 4ul);
> > 
> >         pr_info("Stack:\n");
> > 
> >         for (; len > 0; len -= 32) {
> >                 char buf[9 * 8 + 1];
> > 
> >                 hex_dump_to_buffer(sp, min(len, 32), 32, 4,
> >                                    buf, sizeof(buf), false);
> >                 pr_info(" %08lx:  %s\n", (unsigned long)sp, buf);
> >                 sp += 8;
> >         }
> 
> I wonder if the cycle actually could get replaced by a single call:
> 
> 	print_hex_dump(KERN_INFO, "", DUMP_PREFIX_OFFSET,
> 		       16, 1, sp, len, false);

I think it could be using 4 and not 1 to keep the same output
of a u32 instead of spaces between bytes.