A customer noticed some misalignment issues in the scheduler debug stats
caused by line break/continuations. While the kernel isn't responsible
for log rendering, these trivial changes can help clean up the stats
display with default settings for dmesg/rsyslog/etc.
Note that /proc/sched_debug didn't suffer from these issues and its
output remains unchanged by this patchset.
Joe Lawrence (2):
sched/debug: fix per-task line continuation for console
sched/debug: adjust newlines for better alignment
kernel/sched/debug.c | 29 +++++++++++++++++------------
1 file changed, 17 insertions(+), 12 deletions(-)
--
1.8.3.1
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.000000 29.090111 0.000000
[ 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] S cpuhp/5 37 2006.315026 14 120 0.000000 0.496893 0.000000 0 0 /
Signed-off-by: Joe Lawrence <[email protected]>
---
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); \
} while (0)
/*
--
1.8.3.1
Scheduler debug stats include newlines that display out of alignment
when prefixed by timestamps. For example, the dmesg utility:
% echo t > /proc/sysrq-trigger
% dmesg
...
[ 83.124251]
runnable tasks:
S task PID tree-key switches prio wait-time
sum-exec sum-sleep
-----------------------------------------------------------------------------------------------------------
At the same time, some syslog utilities (like rsyslog by default) don't
like the additional newlines control characters, saving lines like this
to /var/log/messages:
Mar 16 16:02:29 localhost kernel: #012runnable tasks:#012 S task PID tree-key ...
^^^^ ^^^^
Clean these up by moving newline characters to their own SEQ_printf
invocation. This leaves the /proc/sched_debug unchanged, but brings the
entire output into alignment when prefixed:
% echo t > /proc/sysrq-trigger
% dmesg
...
[ 62.410368] runnable tasks:
[ 62.410368] S task PID tree-key switches prio wait-time sum-exec sum-sleep
[ 62.410369] -----------------------------------------------------------------------------------------------------------
[ 62.410369] I kworker/u12:0 5 1932.215593 332 120 0.000000 3.621252 0.000000 0 0 /
and no escaped control characters from rsyslog in /var/log/messages:
Mar 16 16:15:06 localhost kernel: runnable tasks:
Mar 16 16:15:06 localhost kernel: S task PID tree-key ...
Signed-off-by: Joe Lawrence <[email protected]>
---
kernel/sched/debug.c | 27 ++++++++++++++++-----------
1 file changed, 16 insertions(+), 11 deletions(-)
diff --git a/kernel/sched/debug.c b/kernel/sched/debug.c
index 50026aa2d81e..72c401b3b15c 100644
--- a/kernel/sched/debug.c
+++ b/kernel/sched/debug.c
@@ -501,12 +501,12 @@ static void print_rq(struct seq_file *m, struct rq *rq, int rq_cpu)
{
struct task_struct *g, *p;
- SEQ_printf(m,
- "\nrunnable tasks:\n"
- " S task PID tree-key switches prio"
- " wait-time sum-exec sum-sleep\n"
- "-------------------------------------------------------"
- "----------------------------------------------------\n");
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "runnable tasks:\n");
+ SEQ_printf(m, " S task PID tree-key switches prio"
+ " wait-time sum-exec sum-sleep\n");
+ SEQ_printf(m, "-------------------------------------------------------"
+ "----------------------------------------------------\n");
rcu_read_lock();
for_each_process_thread(g, p) {
@@ -527,9 +527,11 @@ void print_cfs_rq(struct seq_file *m, int cpu, struct cfs_rq *cfs_rq)
unsigned long flags;
#ifdef CONFIG_FAIR_GROUP_SCHED
- SEQ_printf(m, "\ncfs_rq[%d]:%s\n", cpu, task_group_path(cfs_rq->tg));
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "cfs_rq[%d]:%s\n", cpu, task_group_path(cfs_rq->tg));
#else
- SEQ_printf(m, "\ncfs_rq[%d]:\n", cpu);
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "cfs_rq[%d]:\n", cpu);
#endif
SEQ_printf(m, " .%-30s: %Ld.%06ld\n", "exec_clock",
SPLIT_NS(cfs_rq->exec_clock));
@@ -595,9 +597,11 @@ void print_cfs_rq(struct seq_file *m, int cpu, struct cfs_rq *cfs_rq)
void print_rt_rq(struct seq_file *m, int cpu, struct rt_rq *rt_rq)
{
#ifdef CONFIG_RT_GROUP_SCHED
- SEQ_printf(m, "\nrt_rq[%d]:%s\n", cpu, task_group_path(rt_rq->tg));
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "rt_rq[%d]:%s\n", cpu, task_group_path(rt_rq->tg));
#else
- SEQ_printf(m, "\nrt_rq[%d]:\n", cpu);
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "rt_rq[%d]:\n", cpu);
#endif
#define P(x) \
@@ -624,7 +628,8 @@ void print_dl_rq(struct seq_file *m, int cpu, struct dl_rq *dl_rq)
{
struct dl_bw *dl_bw;
- SEQ_printf(m, "\ndl_rq[%d]:\n", cpu);
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "dl_rq[%d]:\n", cpu);
#define PU(x) \
SEQ_printf(m, " .%-30s: %lu\n", #x, (unsigned long)(dl_rq->x))
--
1.8.3.1
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.000000 29.090111 0.000000
> [ 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] S cpuhp/5 37 2006.315026 14 120 0.000000 0.496893 0.000000 0 0 /
>
> Signed-off-by: Joe Lawrence <[email protected]>
> ---
> 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.
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.000000 29.090111 0.000000
>> [ 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] S cpuhp/5 37 2006.315026 14 120 0.000000 0.496893 0.000000 0 0 /
>>
>> Signed-off-by: Joe Lawrence <[email protected]>
>> ---
>> 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
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.
Commit-ID: a8c024cd9b9683d25ae1f459525dd2c6bec75e79
Gitweb: https://git.kernel.org/tip/a8c024cd9b9683d25ae1f459525dd2c6bec75e79
Author: Joe Lawrence <[email protected]>
AuthorDate: Mon, 19 Mar 2018 14:35:54 -0400
Committer: Ingo Molnar <[email protected]>
CommitDate: Tue, 20 Mar 2018 09:30:09 +0100
sched/debug: Fix per-task line continuation for console output
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.000000 29.090111 0.000000
[ 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] S cpuhp/5 37 2006.315026 14 120 0.000000 0.496893 0.000000 0 0 /
Signed-off-by: Joe Lawrence <[email protected]>
Acked-by: Peter Zijlstra <[email protected]>
Cc: Linus Torvalds <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
---
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 @@ static DEFINE_SPINLOCK(sched_debug_lock);
if (m) \
seq_printf(m, x); \
else \
- printk(x); \
+ pr_cont(x); \
} while (0)
/*
Commit-ID: e9ca267096674eadd1fd479279bcb58df1486049
Gitweb: https://git.kernel.org/tip/e9ca267096674eadd1fd479279bcb58df1486049
Author: Joe Lawrence <[email protected]>
AuthorDate: Mon, 19 Mar 2018 14:35:55 -0400
Committer: Ingo Molnar <[email protected]>
CommitDate: Tue, 20 Mar 2018 09:30:09 +0100
sched/debug: Adjust newlines for better alignment
Scheduler debug stats include newlines that display out of alignment
when prefixed by timestamps. For example, the dmesg utility:
% echo t > /proc/sysrq-trigger
% dmesg
...
[ 83.124251]
runnable tasks:
S task PID tree-key switches prio wait-time
sum-exec sum-sleep
-----------------------------------------------------------------------------------------------------------
At the same time, some syslog utilities (like rsyslog by default) don't
like the additional newlines control characters, saving lines like this
to /var/log/messages:
Mar 16 16:02:29 localhost kernel: #012runnable tasks:#012 S task PID tree-key ...
^^^^ ^^^^
Clean these up by moving newline characters to their own SEQ_printf
invocation. This leaves the /proc/sched_debug unchanged, but brings the
entire output into alignment when prefixed:
% echo t > /proc/sysrq-trigger
% dmesg
...
[ 62.410368] runnable tasks:
[ 62.410368] S task PID tree-key switches prio wait-time sum-exec sum-sleep
[ 62.410369] -----------------------------------------------------------------------------------------------------------
[ 62.410369] I kworker/u12:0 5 1932.215593 332 120 0.000000 3.621252 0.000000 0 0 /
and no escaped control characters from rsyslog in /var/log/messages:
Mar 16 16:15:06 localhost kernel: runnable tasks:
Mar 16 16:15:06 localhost kernel: S task PID tree-key ...
Signed-off-by: Joe Lawrence <[email protected]>
Acked-by: Peter Zijlstra <[email protected]>
Cc: Linus Torvalds <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
---
kernel/sched/debug.c | 27 ++++++++++++++++-----------
1 file changed, 16 insertions(+), 11 deletions(-)
diff --git a/kernel/sched/debug.c b/kernel/sched/debug.c
index 50026aa2d81e..72c401b3b15c 100644
--- a/kernel/sched/debug.c
+++ b/kernel/sched/debug.c
@@ -501,12 +501,12 @@ static void print_rq(struct seq_file *m, struct rq *rq, int rq_cpu)
{
struct task_struct *g, *p;
- SEQ_printf(m,
- "\nrunnable tasks:\n"
- " S task PID tree-key switches prio"
- " wait-time sum-exec sum-sleep\n"
- "-------------------------------------------------------"
- "----------------------------------------------------\n");
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "runnable tasks:\n");
+ SEQ_printf(m, " S task PID tree-key switches prio"
+ " wait-time sum-exec sum-sleep\n");
+ SEQ_printf(m, "-------------------------------------------------------"
+ "----------------------------------------------------\n");
rcu_read_lock();
for_each_process_thread(g, p) {
@@ -527,9 +527,11 @@ void print_cfs_rq(struct seq_file *m, int cpu, struct cfs_rq *cfs_rq)
unsigned long flags;
#ifdef CONFIG_FAIR_GROUP_SCHED
- SEQ_printf(m, "\ncfs_rq[%d]:%s\n", cpu, task_group_path(cfs_rq->tg));
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "cfs_rq[%d]:%s\n", cpu, task_group_path(cfs_rq->tg));
#else
- SEQ_printf(m, "\ncfs_rq[%d]:\n", cpu);
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "cfs_rq[%d]:\n", cpu);
#endif
SEQ_printf(m, " .%-30s: %Ld.%06ld\n", "exec_clock",
SPLIT_NS(cfs_rq->exec_clock));
@@ -595,9 +597,11 @@ void print_cfs_rq(struct seq_file *m, int cpu, struct cfs_rq *cfs_rq)
void print_rt_rq(struct seq_file *m, int cpu, struct rt_rq *rt_rq)
{
#ifdef CONFIG_RT_GROUP_SCHED
- SEQ_printf(m, "\nrt_rq[%d]:%s\n", cpu, task_group_path(rt_rq->tg));
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "rt_rq[%d]:%s\n", cpu, task_group_path(rt_rq->tg));
#else
- SEQ_printf(m, "\nrt_rq[%d]:\n", cpu);
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "rt_rq[%d]:\n", cpu);
#endif
#define P(x) \
@@ -624,7 +628,8 @@ void print_dl_rq(struct seq_file *m, int cpu, struct dl_rq *dl_rq)
{
struct dl_bw *dl_bw;
- SEQ_printf(m, "\ndl_rq[%d]:\n", cpu);
+ SEQ_printf(m, "\n");
+ SEQ_printf(m, "dl_rq[%d]:\n", cpu);
#define PU(x) \
SEQ_printf(m, " .%-30s: %lu\n", #x, (unsigned long)(dl_rq->x))