Re: [PATCH 1/2] sched/debug: fix per-task line continuation for console

[Peter Zijlstra]

On Mon, Mar 19, 2018 at 04:43:28PM -0400, Joe Lawrence wrote:
> On 03/19/2018 04:17 PM, Peter Zijlstra wrote:

> I don't have the commit offhand that changed the printk behavior, but
> from observation:

4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")

and thereabout I think.

> > Does pr_cont("\n") DTRT? it seems like something weird.
> > 
> 
> Yeah, pr_cont() is kind of a hack.  It will terminate a line if that's
> the first newline, but as demonstrated above, I don't think it likes
> extra newline chars.

Fair enough I suppose, just a bit weird.

> A better fix would be to marshal the text into temp buffer then dump it
> out.  Dunno if you prefer that kind of churn for these stats.

Yeah, not worth it, simple is better here.

Re: [PATCH 1/2] sched/debug: fix per-task line continuation for console

[Peter Zijlstra]

On Mon, Mar 19, 2018 at 04:43:28PM -0400, Joe Lawrence wrote:
> On 03/19/2018 04:17 PM, Peter Zijlstra wrote:

> I don't have the commit offhand that changed the printk behavior, but
> from observation:

4bcc595ccd80 ("printk: reinstate KERN_CONT for printing continuation lines")

and thereabout I think.

> > Does pr_cont("\n") DTRT? it seems like something weird.
> > 
> 
> Yeah, pr_cont() is kind of a hack.  It will terminate a line if that's
> the first newline, but as demonstrated above, I don't think it likes
> extra newline chars.

Fair enough I suppose, just a bit weird.

> A better fix would be to marshal the text into temp buffer then dump it
> out.  Dunno if you prefer that kind of churn for these stats.

Yeah, not worth it, simple is better here.

Re: [PATCH 1/2] sched/debug: fix per-task line continuation for console

[Joe Lawrence]

On 03/19/2018 04:17 PM, Peter Zijlstra wrote:
> On Mon, Mar 19, 2018 at 02:35:54PM -0400, Joe Lawrence wrote:
>> When the SEQ_printf() macro prints to the console, it runs a simple
>> printk() without KERN_CONT "continued" line printing.  The result of
>> this is oddly wrapped task info, for example:
>>
>>   % echo t > /proc/sysrq-trigger
>>   % dmesg
>>   ...
>>   runnable tasks:
>>   ...
>>   [   29.608611]  I
>>   [   29.608613]   rcu_sched 8  3252.013846  4087   120
>>   [   29.608614] 0.0029.090111 0.00
>>   [   29.608615]  0 0
>>   [   29.608616]  /
>>
>> Modify SEQ_printf to use pr_cont() for expected one-line results:
>>
>>   % echo t > /proc/sysrq-trigger
>>   % dmesg
>>   ...
>>   runnable tasks:
>>   ...
>>   [  106.716329]  Scpuhp/537  2006.31502614   120
>>  0.00 0.496893 0.00 0 0 /
>>
>> Signed-off-by: Joe Lawrence 
>> ---
>>  kernel/sched/debug.c | 2 +-
>>  1 file changed, 1 insertion(+), 1 deletion(-)
>>
>> diff --git a/kernel/sched/debug.c b/kernel/sched/debug.c
>> index 1ca0130ed4f9..50026aa2d81e 100644
>> --- a/kernel/sched/debug.c
>> +++ b/kernel/sched/debug.c
>> @@ -32,7 +32,7 @@
>>  if (m)  \
>>  seq_printf(m, x);   \
>>  else\
>> -printk(x);  \
>> +pr_cont(x); \
> 
> That used to work I think.. I think someone changed how printk() behaves
> somewhere along the lines.
> 

Hi Peter,

This code:

printk("printk one");
printk("printk two\n");

pr_cont("\n");
pr_cont("pr_cont one");
pr_cont("pr_cont two\n");

pr_cont("pr_cont first line\n");
pr_cont("\n");
pr_cont("\n");
pr_cont("pr_cont next line");

Creates this output:

%  uname -r
4.16.0-rc5+

% dmesg
[  575.221280] printk one
[  575.221281] printk two
[  575.221282] pr_cont onepr_cont two
[  575.221283] pr_cont first line

I don't have the commit offhand that changed the printk behavior, but
from observation:

  1 - printk implies a trailing newline:
  https://lwn.net/Articles/732420/

  2 - pr_cont seems to eat redundant newlines

> Does pr_cont("\n") DTRT? it seems like something weird.
> 

Yeah, pr_cont() is kind of a hack.  It will terminate a line if that's
the first newline, but as demonstrated above, I don't think it likes
extra newline chars.

A better fix would be to marshal the text into temp buffer then dump it
out.  Dunno if you prefer that kind of churn for these stats.

-- Joe

Re: [PATCH 1/2] sched/debug: fix per-task line continuation for console

[Joe Lawrence]

On 03/19/2018 04:17 PM, Peter Zijlstra wrote:
> On Mon, Mar 19, 2018 at 02:35:54PM -0400, Joe Lawrence wrote:
>> When the SEQ_printf() macro prints to the console, it runs a simple
>> printk() without KERN_CONT "continued" line printing.  The result of
>> this is oddly wrapped task info, for example:
>>
>>   % echo t > /proc/sysrq-trigger
>>   % dmesg
>>   ...
>>   runnable tasks:
>>   ...
>>   [   29.608611]  I
>>   [   29.608613]   rcu_sched 8  3252.013846  4087   120
>>   [   29.608614] 0.0029.090111 0.00
>>   [   29.608615]  0 0
>>   [   29.608616]  /
>>
>> Modify SEQ_printf to use pr_cont() for expected one-line results:
>>
>>   % echo t > /proc/sysrq-trigger
>>   % dmesg
>>   ...
>>   runnable tasks:
>>   ...
>>   [  106.716329]  Scpuhp/537  2006.31502614   120
>>  0.00 0.496893 0.00 0 0 /
>>
>> Signed-off-by: Joe Lawrence 
>> ---
>>  kernel/sched/debug.c | 2 +-
>>  1 file changed, 1 insertion(+), 1 deletion(-)
>>
>> diff --git a/kernel/sched/debug.c b/kernel/sched/debug.c
>> index 1ca0130ed4f9..50026aa2d81e 100644
>> --- a/kernel/sched/debug.c
>> +++ b/kernel/sched/debug.c
>> @@ -32,7 +32,7 @@
>>  if (m)  \
>>  seq_printf(m, x);   \
>>  else\
>> -printk(x);  \
>> +pr_cont(x); \
> 
> That used to work I think.. I think someone changed how printk() behaves
> somewhere along the lines.
> 

Hi Peter,

This code:

printk("printk one");
printk("printk two\n");

pr_cont("\n");
pr_cont("pr_cont one");
pr_cont("pr_cont two\n");

pr_cont("pr_cont first line\n");
pr_cont("\n");
pr_cont("\n");
pr_cont("pr_cont next line");

Creates this output:

%  uname -r
4.16.0-rc5+

% dmesg
[  575.221280] printk one
[  575.221281] printk two
[  575.221282] pr_cont onepr_cont two
[  575.221283] pr_cont first line

I don't have the commit offhand that changed the printk behavior, but
from observation:

  1 - printk implies a trailing newline:
  https://lwn.net/Articles/732420/

  2 - pr_cont seems to eat redundant newlines

> Does pr_cont("\n") DTRT? it seems like something weird.
> 

Yeah, pr_cont() is kind of a hack.  It will terminate a line if that's
the first newline, but as demonstrated above, I don't think it likes
extra newline chars.

A better fix would be to marshal the text into temp buffer then dump it
out.  Dunno if you prefer that kind of churn for these stats.

-- Joe

Re: [PATCH 1/2] sched/debug: fix per-task line continuation for console

[Peter Zijlstra]

On Mon, Mar 19, 2018 at 02:35:54PM -0400, Joe Lawrence wrote:
> When the SEQ_printf() macro prints to the console, it runs a simple
> printk() without KERN_CONT "continued" line printing.  The result of
> this is oddly wrapped task info, for example:
> 
>   % echo t > /proc/sysrq-trigger
>   % dmesg
>   ...
>   runnable tasks:
>   ...
>   [   29.608611]  I
>   [   29.608613]   rcu_sched 8  3252.013846  4087   120
>   [   29.608614] 0.0029.090111 0.00
>   [   29.608615]  0 0
>   [   29.608616]  /
> 
> Modify SEQ_printf to use pr_cont() for expected one-line results:
> 
>   % echo t > /proc/sysrq-trigger
>   % dmesg
>   ...
>   runnable tasks:
>   ...
>   [  106.716329]  Scpuhp/537  2006.31502614   120 
> 0.00 0.496893 0.00 0 0 /
> 
> Signed-off-by: Joe Lawrence 
> ---
>  kernel/sched/debug.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/sched/debug.c b/kernel/sched/debug.c
> index 1ca0130ed4f9..50026aa2d81e 100644
> --- a/kernel/sched/debug.c
> +++ b/kernel/sched/debug.c
> @@ -32,7 +32,7 @@
>   if (m)  \
>   seq_printf(m, x);   \
>   else\
> - printk(x);  \
> + pr_cont(x); \

That used to work I think.. I think someone changed how printk() behaves
somewhere along the lines.

Does pr_cont("\n") DTRT? it seems like something weird.

Re: [PATCH 1/2] sched/debug: fix per-task line continuation for console

[Peter Zijlstra]

On Mon, Mar 19, 2018 at 02:35:54PM -0400, Joe Lawrence wrote:
> When the SEQ_printf() macro prints to the console, it runs a simple
> printk() without KERN_CONT "continued" line printing.  The result of
> this is oddly wrapped task info, for example:
> 
>   % echo t > /proc/sysrq-trigger
>   % dmesg
>   ...
>   runnable tasks:
>   ...
>   [   29.608611]  I
>   [   29.608613]   rcu_sched 8  3252.013846  4087   120
>   [   29.608614] 0.0029.090111 0.00
>   [   29.608615]  0 0
>   [   29.608616]  /
> 
> Modify SEQ_printf to use pr_cont() for expected one-line results:
> 
>   % echo t > /proc/sysrq-trigger
>   % dmesg
>   ...
>   runnable tasks:
>   ...
>   [  106.716329]  Scpuhp/537  2006.31502614   120 
> 0.00 0.496893 0.00 0 0 /
> 
> Signed-off-by: Joe Lawrence 
> ---
>  kernel/sched/debug.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/sched/debug.c b/kernel/sched/debug.c
> index 1ca0130ed4f9..50026aa2d81e 100644
> --- a/kernel/sched/debug.c
> +++ b/kernel/sched/debug.c
> @@ -32,7 +32,7 @@
>   if (m)  \
>   seq_printf(m, x);   \
>   else\
> - printk(x);  \
> + pr_cont(x); \

That used to work I think.. I think someone changed how printk() behaves
somewhere along the lines.

Does pr_cont("\n") DTRT? it seems like something weird.