Currently, the log-level of show_stack() depends on a platform
realization. It creates situations where the headers are printed with
lower log level or higher than the stacktrace (depending on
a platform or user).
Furthermore, it forces the logic decision from user to an architecture
side. In result, some users as sysrq/kdb/etc are doing tricks with
temporary rising console_loglevel while printing their messages.
And in result it not only may print unwanted messages from other CPUs,
but also omit printing at all in the unlucky case where the printk()
was deferred.
Introducing log-level parameter and KERN_UNSUPPRESSED [1] seems
an easier approach than introducing more printk buffers.
Also, it will consolidate printings with headers.
Introduce show_stack_loglvl(), that eventually will substitute
show_stack().
Cc: Chris Zankel <[email protected]>
Cc: Max Filippov <[email protected]>
Cc: [email protected]
[1]: https://lore.kernel.org/lkml/[email protected]/T/#u
Signed-off-by: Dmitry Safonov <[email protected]>
---
arch/xtensa/kernel/traps.c | 16 +++++++++++-----
1 file changed, 11 insertions(+), 5 deletions(-)
diff --git a/arch/xtensa/kernel/traps.c b/arch/xtensa/kernel/traps.c
index cbc0d673f542..ba6c150095c6 100644
--- a/arch/xtensa/kernel/traps.c
+++ b/arch/xtensa/kernel/traps.c
@@ -502,7 +502,8 @@ static void show_trace(struct task_struct *task, unsigned long *sp,
static int kstack_depth_to_print = 24;
-void show_stack(struct task_struct *task, unsigned long *sp)
+void show_stack_loglvl(struct task_struct *task, unsigned long *sp,
+ const char *loglvl)
{
int i = 0;
unsigned long *stack;
@@ -511,16 +512,21 @@ void show_stack(struct task_struct *task, unsigned long *sp)
sp = stack_pointer(task);
stack = sp;
- pr_info("Stack:\n");
+ printk("%sStack:\n", loglvl);
for (i = 0; i < kstack_depth_to_print; i++) {
if (kstack_end(sp))
break;
- pr_cont(" %08lx", *sp++);
+ printk("%s %08lx", loglvl, *sp++);
if (i % 8 == 7)
- pr_cont("\n");
+ printk("%s\n", loglvl);
}
- show_trace(task, stack, KERN_INFO);
+ show_trace(task, stack, loglvl);
+}
+
+void show_stack(struct task_struct *task, unsigned long *sp)
+{
+ show_stack_loglvl(task, sp, KERN_INFO);
}
DEFINE_SPINLOCK(die_lock);
--
2.23.0
Hi Dmitry,
On Tue, Nov 5, 2019 at 7:08 PM Dmitry Safonov <[email protected]> wrote:
>
> Currently, the log-level of show_stack() depends on a platform
> realization. It creates situations where the headers are printed with
> lower log level or higher than the stacktrace (depending on
> a platform or user).
>
> Furthermore, it forces the logic decision from user to an architecture
> side. In result, some users as sysrq/kdb/etc are doing tricks with
> temporary rising console_loglevel while printing their messages.
> And in result it not only may print unwanted messages from other CPUs,
> but also omit printing at all in the unlucky case where the printk()
> was deferred.
>
> Introducing log-level parameter and KERN_UNSUPPRESSED [1] seems
> an easier approach than introducing more printk buffers.
> Also, it will consolidate printings with headers.
>
> Introduce show_stack_loglvl(), that eventually will substitute
> show_stack().
>
> Cc: Chris Zankel <[email protected]>
> Cc: Max Filippov <[email protected]>
> Cc: [email protected]
> [1]: https://lore.kernel.org/lkml/[email protected]/T/#u
> Signed-off-by: Dmitry Safonov <[email protected]>
> ---
> arch/xtensa/kernel/traps.c | 16 +++++++++++-----
> 1 file changed, 11 insertions(+), 5 deletions(-)
>
> diff --git a/arch/xtensa/kernel/traps.c b/arch/xtensa/kernel/traps.c
> index cbc0d673f542..ba6c150095c6 100644
> --- a/arch/xtensa/kernel/traps.c
> +++ b/arch/xtensa/kernel/traps.c
> @@ -502,7 +502,8 @@ static void show_trace(struct task_struct *task, unsigned long *sp,
>
> static int kstack_depth_to_print = 24;
>
> -void show_stack(struct task_struct *task, unsigned long *sp)
> +void show_stack_loglvl(struct task_struct *task, unsigned long *sp,
> + const char *loglvl)
> {
> int i = 0;
> unsigned long *stack;
> @@ -511,16 +512,21 @@ void show_stack(struct task_struct *task, unsigned long *sp)
> sp = stack_pointer(task);
> stack = sp;
>
> - pr_info("Stack:\n");
> + printk("%sStack:\n", loglvl);
>
> for (i = 0; i < kstack_depth_to_print; i++) {
> if (kstack_end(sp))
> break;
> - pr_cont(" %08lx", *sp++);
> + printk("%s %08lx", loglvl, *sp++);
> if (i % 8 == 7)
> - pr_cont("\n");
> + printk("%s\n", loglvl);
> }
> - show_trace(task, stack, KERN_INFO);
> + show_trace(task, stack, loglvl);
> +}
> +
> +void show_stack(struct task_struct *task, unsigned long *sp)
> +{
> + show_stack_loglvl(task, sp, KERN_INFO);
> }
>
> DEFINE_SPINLOCK(die_lock);
> --
> 2.23.0
This change doesn't work well with printk timestamps, it changes
the following output on xtensa architecture
[ 3.404675] Stack:
[ 3.404861] a05773e2 00000018 bb03dc34 bb03dc30 a0008640 bb03dc70
ba9ba410 37c3f000
[ 3.405414] 37c3f000 d7c3f000 00000800 bb03dc50 a02b97ed bb03dc90
ba9ba400 ba9ba410
[ 3.405969] a05fc1bc bbff28dc 00000000 bb03dc70 a02b7fb9 bb03dce0
ba9ba410 a0579044
into this:
[ 3.056825] Stack:
[ 3.056963] a04ebb20
[ 3.056995] bb03dc10
[ 3.057138] 00000001
[ 3.057277] bb03dc10
[ 3.057815] a00083ca
[ 3.057965] bb03dc50
[ 3.058107] ba9ba410
[ 3.058247] 37c3f000
[ 3.058387]
[ 3.058584] a05773e2
[ 3.058614] 00000001
[ 3.058755] a05ca0bc
[ 3.058896] bb03dc30
[ 3.059035] a000865c
[ 3.059180] bb03dc70
[ 3.059319] ba9ba410
[ 3.059459] 37c3f000
[ 3.059598]
[ 3.059795] 37c3f000
[ 3.059824] d7c3f000
[ 3.059964] 00000800
[ 3.060103] bb03dc50
[ 3.060241] a02b9809
[ 3.060379] bb03dc90
[ 3.060519] ba9ba400
[ 3.060658] ba9ba410
[ 3.060796]
--
Thanks.
-- Max
On Tue 2019-11-05 20:13:22, Max Filippov wrote:
> Hi Dmitry,
>
> On Tue, Nov 5, 2019 at 7:08 PM Dmitry Safonov <[email protected]> wrote:
> >
> > Currently, the log-level of show_stack() depends on a platform
> > realization. It creates situations where the headers are printed with
> > lower log level or higher than the stacktrace (depending on
> > a platform or user).
> >
> > Furthermore, it forces the logic decision from user to an architecture
> > side. In result, some users as sysrq/kdb/etc are doing tricks with
> > temporary rising console_loglevel while printing their messages.
> > And in result it not only may print unwanted messages from other CPUs,
> > but also omit printing at all in the unlucky case where the printk()
> > was deferred.
> >
> > Introducing log-level parameter and KERN_UNSUPPRESSED [1] seems
> > an easier approach than introducing more printk buffers.
> > Also, it will consolidate printings with headers.
> >
> > Introduce show_stack_loglvl(), that eventually will substitute
> > show_stack().
> >
> > Cc: Chris Zankel <[email protected]>
> > Cc: Max Filippov <[email protected]>
> > Cc: [email protected]
> > [1]: https://lore.kernel.org/lkml/[email protected]/T/#u
> > Signed-off-by: Dmitry Safonov <[email protected]>
> > ---
> > arch/xtensa/kernel/traps.c | 16 +++++++++++-----
> > 1 file changed, 11 insertions(+), 5 deletions(-)
> >
> > diff --git a/arch/xtensa/kernel/traps.c b/arch/xtensa/kernel/traps.c
> > index cbc0d673f542..ba6c150095c6 100644
> > --- a/arch/xtensa/kernel/traps.c
> > +++ b/arch/xtensa/kernel/traps.c
> > @@ -502,7 +502,8 @@ static void show_trace(struct task_struct *task, unsigned long *sp,
> >
> > static int kstack_depth_to_print = 24;
> >
> > -void show_stack(struct task_struct *task, unsigned long *sp)
> > +void show_stack_loglvl(struct task_struct *task, unsigned long *sp,
> > + const char *loglvl)
> > {
> > int i = 0;
> > unsigned long *stack;
> > @@ -511,16 +512,21 @@ void show_stack(struct task_struct *task, unsigned long *sp)
> > sp = stack_pointer(task);
> > stack = sp;
> >
> > - pr_info("Stack:\n");
> > + printk("%sStack:\n", loglvl);
> >
> > for (i = 0; i < kstack_depth_to_print; i++) {
> > if (kstack_end(sp))
> > break;
> > - pr_cont(" %08lx", *sp++);
> > + printk("%s %08lx", loglvl, *sp++);
KERN_CONT can be combined with any other loglevel.
So you could keep using pr_cont() together with explicit loglevel:
pr_cont("%s %08lx", loglvl, *sp++);
It should fix the problems reported below.
Well, the preferred solution would be to snprintf() the continuous
line into a temporary buffer. And printk() it when it is complete.
pr_cont() is not reliable when more CPUs print at the same time.
Best Regards,
Petr
> This change doesn't work well with printk timestamps, it changes
> the following output on xtensa architecture
>
> [ 3.404675] Stack:
> [ 3.404861] a05773e2 00000018 bb03dc34 bb03dc30 a0008640 bb03dc70
> ba9ba410 37c3f000
> [ 3.405414] 37c3f000 d7c3f000 00000800 bb03dc50 a02b97ed bb03dc90
> ba9ba400 ba9ba410
> [ 3.405969] a05fc1bc bbff28dc 00000000 bb03dc70 a02b7fb9 bb03dce0
> ba9ba410 a0579044
>
> into this:
> [ 3.056825] Stack:
> [ 3.056963] a04ebb20
> [ 3.056995] bb03dc10
> [ 3.057138] 00000001
> [ 3.057277] bb03dc10
> [ 3.057815] a00083ca
> [ 3.057965] bb03dc50
> [ 3.058107] ba9ba410
> [ 3.058247] 37c3f000
> [ 3.058387]
> [ 3.058584] a05773e2
> [ 3.058614] 00000001
> [ 3.058755] a05ca0bc
> [ 3.058896] bb03dc30
> [ 3.059035] a000865c
> [ 3.059180] bb03dc70
> [ 3.059319] ba9ba410
> [ 3.059459] 37c3f000
> [ 3.059598]
> [ 3.059795] 37c3f000
> [ 3.059824] d7c3f000
> [ 3.059964] 00000800
> [ 3.060103] bb03dc50
> [ 3.060241] a02b9809
> [ 3.060379] bb03dc90
> [ 3.060519] ba9ba400
> [ 3.060658] ba9ba410
> [ 3.060796]
>
> --
> Thanks.
> -- Max
On 11/6/19 8:15 AM, Petr Mladek wrote:
> On Tue 2019-11-05 20:13:22, Max Filippov wrote:
[..]
>>> @@ -511,16 +512,21 @@ void show_stack(struct task_struct *task, unsigned long *sp)
>>> sp = stack_pointer(task);
>>> stack = sp;
>>>
>>> - pr_info("Stack:\n");
>>> + printk("%sStack:\n", loglvl);
>>>
>>> for (i = 0; i < kstack_depth_to_print; i++) {
>>> if (kstack_end(sp))
>>> break;
>>> - pr_cont(" %08lx", *sp++);
>>> + printk("%s %08lx", loglvl, *sp++);
>
> KERN_CONT can be combined with any other loglevel.
> So you could keep using pr_cont() together with explicit loglevel:
>
> pr_cont("%s %08lx", loglvl, *sp++);
Yes, that's what I had, but than misread the printk() code and thought
that it doesn't add '\n' to messages.. Will fix.
> It should fix the problems reported below.
>
> Well, the preferred solution would be to snprintf() the continuous
> line into a temporary buffer. And printk() it when it is complete.
> pr_cont() is not reliable when more CPUs print at the same time.
Yep. Not sure if doing it now in those per-arch patches or keep the
changes to minimum.
>
>> This change doesn't work well with printk timestamps, it changes
>> the following output on xtensa architecture
>>
>> [ 3.404675] Stack:
>> [ 3.404861] a05773e2 00000018 bb03dc34 bb03dc30 a0008640 bb03dc70
>> ba9ba410 37c3f000
>> [ 3.405414] 37c3f000 d7c3f000 00000800 bb03dc50 a02b97ed bb03dc90
>> ba9ba400 ba9ba410
>> [ 3.405969] a05fc1bc bbff28dc 00000000 bb03dc70 a02b7fb9 bb03dce0
>> ba9ba410 a0579044
>>
>> into this:
>> [ 3.056825] Stack:
>> [ 3.056963] a04ebb20
>> [ 3.056995] bb03dc10
>> [ 3.057138] 00000001
>> [ 3.057277] bb03dc10
>> [ 3.057815] a00083ca
>> [ 3.057965] bb03dc50
>> [ 3.058107] ba9ba410
>> [ 3.058247] 37c3f000
>> [ 3.058387]
>> [ 3.058584] a05773e2
>> [ 3.058614] 00000001
>> [ 3.058755] a05ca0bc
>> [ 3.058896] bb03dc30
>> [ 3.059035] a000865c
>> [ 3.059180] bb03dc70
>> [ 3.059319] ba9ba410
>> [ 3.059459] 37c3f000
>> [ 3.059598]
>> [ 3.059795] 37c3f000
>> [ 3.059824] d7c3f000
>> [ 3.059964] 00000800
>> [ 3.060103] bb03dc50
>> [ 3.060241] a02b9809
>> [ 3.060379] bb03dc90
>> [ 3.060519] ba9ba400
>> [ 3.060658] ba9ba410
>> [ 3.060796]
Hey Max,
thanks for the testing and the report - will fix it in v2.
Thanks,
Dmitry
On Wed, Nov 6, 2019 at 12:15 AM Petr Mladek <[email protected]> wrote:
> > > for (i = 0; i < kstack_depth_to_print; i++) {
> > > if (kstack_end(sp))
> > > break;
> > > - pr_cont(" %08lx", *sp++);
> > > + printk("%s %08lx", loglvl, *sp++);
>
> KERN_CONT can be combined with any other loglevel.
> So you could keep using pr_cont() together with explicit loglevel:
>
> pr_cont("%s %08lx", loglvl, *sp++);
>
> It should fix the problems reported below.
>
> Well, the preferred solution would be to snprintf() the continuous
> line into a temporary buffer. And printk() it when it is complete.
> pr_cont() is not reliable when more CPUs print at the same time.
Good point. Let me do this cleanup.
--
Thanks.
-- Max