Printk mulitple line message support

Printk mulitple line message support

[Huang Ying]

Hi,

In most cases, printk only guarantees messages from different printk
calling will not be interleaved between each other.  But many printk
users uses multiple line to form a complete message and call printk
for each line.  So the following situation is possible for two printk
users running on two CPUs.

line 1 of message from printk user1
line 1 of message from printk user2
line 2 of message from printk user1
line 2 of message from printk user2

This makes kernel log hard to read.  One possible solution to this
issue is to give a sequence number (or ID) to each complete message.
So the above lines will be:

{1}line 1 of message from printk user1
{2}line 1 of message from printk user2
{1}line 2 of message from printk user1
{2}line 2 of message from printk user2

Then some simple script can be used to group lines together according
to sequence number in lines.

What do you think about that?

A simple patch to implement this is followed.

Best Regards,
Huang Ying

---
 include/linux/printk.h |   24 ++++++++++++++++++++++++
 kernel/printk.c        |    7 +++++++
 2 files changed, 31 insertions(+)

--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -149,6 +149,7 @@ static char *log_buf = __log_buf;
 static int log_buf_len = __LOG_BUF_LEN;
 static unsigned logged_chars; /* Number of chars produced since last read+clear operation */
 static int saved_console_loglevel = -1;
+static atomic_t printk_seqno;
 
 #ifdef CONFIG_KEXEC
 /*
@@ -970,6 +971,12 @@ out_restore_irqs:
 EXPORT_SYMBOL(printk);
 EXPORT_SYMBOL(vprintk);
 
+unsigned int printk_ml_seqno(void)
+{
+	return atomic_inc_return(&printk_seqno);
+}
+EXPORT_SYMBOL_GPL(printk_ml_seqno);
+
 #else
 
 static void call_console_drivers(unsigned start, unsigned end)
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -116,6 +116,7 @@ extern int kptr_restrict;
 
 void log_buf_kexec_setup(void);
 void __init setup_log_buf(int early);
+unsigned int printk_ml_seqno(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -144,6 +145,11 @@ static inline void log_buf_kexec_setup(v
 static inline void setup_log_buf(int early)
 {
 }
+
+static unsigned int printk_ml_seqno(void)
+{
+	return 0;
+}
 #endif
 
 extern void dump_stack(void) __cold;
@@ -192,6 +198,24 @@ extern void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+#define PR_ML_FMT	"{%u}"
+
+#define pr_emerg_ml(seqno, fmt, ...)					\
+	printk(KERN_EMERG PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+#define pr_alert_ml(seqno, fmt, ...)					\
+	printk(KERN_ALERT PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+#define pr_crit_ml(seqno, fmt, ...)					\
+	printk(KERN_CRIT PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+#define pr_err_ml(seqno, fmt, ...)					\
+	printk(KERN_ERR PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+#define pr_warning_ml(seqno, fmt, ...)					\
+	printk(KERN_WARNING PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+#define pr_warn_ml pr_warning_ml
+#define pr_notice_ml(seqno, fmt, ...)					\
+	printk(KERN_NOTICE PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+#define pr_info_ml(seqno, fmt, ...)					\
+	printk(KERN_INFO PR_ML_FMT pr_fmt(fmt), seqno, ##__VA_ARGS__)
+
 /*
  * Print a one-time message (analogous to WARN_ONCE() et al):
  */

Re: Printk mulitple line message support

[Joe Perches]

On Mon, 2011-11-14 at 14:58 +0800, Huang Ying wrote:
> Hi,
> 
> In most cases, printk only guarantees messages from different printk
> calling will not be interleaved between each other.  But many printk
> users uses multiple line to form a complete message and call printk
> for each line.  So the following situation is possible for two printk
> users running on two CPUs.
> 
> line 1 of message from printk user1
> line 1 of message from printk user2
> line 2 of message from printk user1
> line 2 of message from printk user2
> 
> This makes kernel log hard to read.  One possible solution to this
> issue is to give a sequence number (or ID) to each complete message.
> So the above lines will be:
> 
> {1}line 1 of message from printk user1
> {2}line 1 of message from printk user2
> {1}line 2 of message from printk user1
> {2}line 2 of message from printk user2
> 
> Then some simple script can be used to group lines together according
> to sequence number in lines.
> 
> What do you think about that?

This makes the typical multi-part but non-interleaved
output difficult to read.

How about determining if there is interleaving and
emitting sequence # only in those cases?

Perhaps test the atomic for the last sequence #.

Re: Printk mulitple line message support

[Bruno Prémont]

On Mon, 14 November 2011 Joe Perches <joe@perches.com> wrote:

> On Mon, 2011-11-14 at 14:58 +0800, Huang Ying wrote:
> > Hi,
> > 
> > In most cases, printk only guarantees messages from different printk
> > calling will not be interleaved between each other.  But many printk
> > users uses multiple line to form a complete message and call printk
> > for each line.  So the following situation is possible for two printk
> > users running on two CPUs.
> > 
> > line 1 of message from printk user1
> > line 1 of message from printk user2
> > line 2 of message from printk user1
> > line 2 of message from printk user2
> > 
> > This makes kernel log hard to read.  One possible solution to this
> > issue is to give a sequence number (or ID) to each complete message.
> > So the above lines will be:
> > 
> > {1}line 1 of message from printk user1
> > {2}line 1 of message from printk user2
> > {1}line 2 of message from printk user1
> > {2}line 2 of message from printk user2
> > 
> > Then some simple script can be used to group lines together according
> > to sequence number in lines.
> > 
> > What do you think about that?
> 
> This makes the typical multi-part but non-interleaved
> output difficult to read.
> 
> How about determining if there is interleaving and
> emitting sequence # only in those cases?
> 
> Perhaps test the atomic for the last sequence #.

Wouldn't another option be to let printk() handle '\n' in messages
so the multi-line messages could be done with a single call to printk.

Those messages could contain optional severity information after the
linefeed (if none given, the one of previous line would be repeated
internally by printk).

This way consumers of printk (and all variations of it like dev_err)
would all benefit without need to redefine them for multi-line use.

Bruno

Re: Printk mulitple line message support

[Joe Perches]

On Mon, 2011-11-14 at 19:20 +0100, Bruno Prémont wrote:
> Wouldn't another option be to let printk() handle '\n' in messages
> so the multi-line messages could be done with a single call to printk.

That already happens.

Re: Printk mulitple line message support

[Huang Ying]

On Mon, 2011-11-14 at 22:40 +0800, Joe Perches wrote:
> On Mon, 2011-11-14 at 14:58 +0800, Huang Ying wrote:
> > Hi,
> > 
> > In most cases, printk only guarantees messages from different printk
> > calling will not be interleaved between each other.  But many printk
> > users uses multiple line to form a complete message and call printk
> > for each line.  So the following situation is possible for two printk
> > users running on two CPUs.
> > 
> > line 1 of message from printk user1
> > line 1 of message from printk user2
> > line 2 of message from printk user1
> > line 2 of message from printk user2
> > 
> > This makes kernel log hard to read.  One possible solution to this
> > issue is to give a sequence number (or ID) to each complete message.
> > So the above lines will be:
> > 
> > {1}line 1 of message from printk user1
> > {2}line 1 of message from printk user2
> > {1}line 2 of message from printk user1
> > {2}line 2 of message from printk user2
> > 
> > Then some simple script can be used to group lines together according
> > to sequence number in lines.
> > 
> > What do you think about that?
> 
> This makes the typical multi-part but non-interleaved
> output difficult to read.

With a simple script, we can strip out the sequence # easily.

> How about determining if there is interleaving and
> emitting sequence # only in those cases?
> 
> Perhaps test the atomic for the last sequence #.

So we will have no sequence # prefix for printk user1's lines if printk
user 2 comes in the middle?  Something as follow?

line 1 of message from printk user1
{2}line 1 of message from printk user2
line 2 of message from printk user1
{2}line 2 of message from printk user2

This will make it hard for a script to sort the lines.  Where should it
insert lines from printk user2 in the sort result?

Best Regards,
Huang Ying

Re: Printk mulitple line message support

[Huang Ying]

On Tue, 2011-11-15 at 02:20 +0800, Bruno Prémont wrote:
> On Mon, 14 November 2011 Joe Perches <joe@perches.com> wrote:
> 
> > On Mon, 2011-11-14 at 14:58 +0800, Huang Ying wrote:
> > > Hi,
> > > 
> > > In most cases, printk only guarantees messages from different printk
> > > calling will not be interleaved between each other.  But many printk
> > > users uses multiple line to form a complete message and call printk
> > > for each line.  So the following situation is possible for two printk
> > > users running on two CPUs.
> > > 
> > > line 1 of message from printk user1
> > > line 1 of message from printk user2
> > > line 2 of message from printk user1
> > > line 2 of message from printk user2
> > > 
> > > This makes kernel log hard to read.  One possible solution to this
> > > issue is to give a sequence number (or ID) to each complete message.
> > > So the above lines will be:
> > > 
> > > {1}line 1 of message from printk user1
> > > {2}line 1 of message from printk user2
> > > {1}line 2 of message from printk user1
> > > {2}line 2 of message from printk user2
> > > 
> > > Then some simple script can be used to group lines together according
> > > to sequence number in lines.
> > > 
> > > What do you think about that?
> > 
> > This makes the typical multi-part but non-interleaved
> > output difficult to read.
> > 
> > How about determining if there is interleaving and
> > emitting sequence # only in those cases?
> > 
> > Perhaps test the atomic for the last sequence #.
> 
> Wouldn't another option be to let printk() handle '\n' in messages
> so the multi-line messages could be done with a single call to printk.
> 
> Those messages could contain optional severity information after the
> linefeed (if none given, the one of previous line would be repeated
> internally by printk).
> 
> This way consumers of printk (and all variations of it like dev_err)
> would all benefit without need to redefine them for multi-line use.

Yes.  That is another solution.  But sometimes, it is just not so
convenient to do that.  The printk users may have to allocate a big
buffer to hold all these lines.  The solution here is for those users.

Best Regards,
Huang Ying

Re: Printk mulitple line message support

[Joe Perches]

On Tue, 2011-11-15 at 08:50 +0800, Huang Ying wrote:
> On Mon, 2011-11-14 at 22:40 +0800, Joe Perches wrote:
> > On Mon, 2011-11-14 at 14:58 +0800, Huang Ying wrote:
> > > Hi,
> > > 
> > > In most cases, printk only guarantees messages from different printk
> > > calling will not be interleaved between each other.  But many printk
> > > users uses multiple line to form a complete message and call printk
> > > for each line.  So the following situation is possible for two printk
> > > users running on two CPUs.
> > > 
> > > line 1 of message from printk user1
> > > line 1 of message from printk user2
> > > line 2 of message from printk user1
> > > line 2 of message from printk user2
> > > 
> > > This makes kernel log hard to read.  One possible solution to this
> > > issue is to give a sequence number (or ID) to each complete message.
> > > So the above lines will be:
> > > 
> > > {1}line 1 of message from printk user1
> > > {2}line 1 of message from printk user2
> > > {1}line 2 of message from printk user1
> > > {2}line 2 of message from printk user2
> > > 
> > > Then some simple script can be used to group lines together according
> > > to sequence number in lines.
> > > 
> > > What do you think about that?
> > 
> > This makes the typical multi-part but non-interleaved
> > output difficult to read.
> 
> With a simple script, we can strip out the sequence # easily.
> 
> > How about determining if there is interleaving and
> > emitting sequence # only in those cases?
> > 
> > Perhaps test the atomic for the last sequence #.
> 
> So we will have no sequence # prefix for printk user1's lines if printk
> user 2 comes in the middle?  Something as follow?
> 
> line 1 of message from printk user1
> {2}line 1 of message from printk user2
> line 2 of message from printk user1
> {2}line 2 of message from printk user2
> 
> This will make it hard for a script to sort the lines.  Where should it
> insert lines from printk user2 in the sort result?

90+% it's the previous line.

I believe you are not solving any real problem
with pr_<level>_ml.

Most all interleaved complete line uses have some
pr_fmt prefix that distinguishes between the sources.

A perhaps larger problem is interleaved partial
lines with pr_cont.

I believe that an initiator/terminator is necessary
for reassembly.  Something that could be used
with pr_<level>, dev_<level>, netdev_<level>, et al.

mp_start(&cookie)
pr_<level>(fmt, ...);
pr_mp_cont(&cookie, fmt, ...);
pr_mp_cont(&cookie, fmt "\n", ...);
mp_end(&cookie);

Re: Printk mulitple line message support

[Huang Ying]

On Tue, 2011-11-15 at 09:18 +0800, Joe Perches wrote:
> On Tue, 2011-11-15 at 08:50 +0800, Huang Ying wrote:
> > On Mon, 2011-11-14 at 22:40 +0800, Joe Perches wrote:
> > > On Mon, 2011-11-14 at 14:58 +0800, Huang Ying wrote:
> > > > Hi,
> > > > 
> > > > In most cases, printk only guarantees messages from different printk
> > > > calling will not be interleaved between each other.  But many printk
> > > > users uses multiple line to form a complete message and call printk
> > > > for each line.  So the following situation is possible for two printk
> > > > users running on two CPUs.
> > > > 
> > > > line 1 of message from printk user1
> > > > line 1 of message from printk user2
> > > > line 2 of message from printk user1
> > > > line 2 of message from printk user2
> > > > 
> > > > This makes kernel log hard to read.  One possible solution to this
> > > > issue is to give a sequence number (or ID) to each complete message.
> > > > So the above lines will be:
> > > > 
> > > > {1}line 1 of message from printk user1
> > > > {2}line 1 of message from printk user2
> > > > {1}line 2 of message from printk user1
> > > > {2}line 2 of message from printk user2
> > > > 
> > > > Then some simple script can be used to group lines together according
> > > > to sequence number in lines.
> > > > 
> > > > What do you think about that?
> > > 
> > > This makes the typical multi-part but non-interleaved
> > > output difficult to read.
> > 
> > With a simple script, we can strip out the sequence # easily.
> > 
> > > How about determining if there is interleaving and
> > > emitting sequence # only in those cases?
> > > 
> > > Perhaps test the atomic for the last sequence #.
> > 
> > So we will have no sequence # prefix for printk user1's lines if printk
> > user 2 comes in the middle?  Something as follow?
> > 
> > line 1 of message from printk user1
> > {2}line 1 of message from printk user2
> > line 2 of message from printk user1
> > {2}line 2 of message from printk user2
> > 
> > This will make it hard for a script to sort the lines.  Where should it
> > insert lines from printk user2 in the sort result?
> 
> 90+% it's the previous line.
> 
> I believe you are not solving any real problem
> with pr_<level>_ml.
> 
> Most all interleaved complete line uses have some
> pr_fmt prefix that distinguishes between the sources.

Except dev_<level> and netdev_<level>, it appears that many general
pr_<level> do not have the prefix.

> A perhaps larger problem is interleaved partial
> lines with pr_cont.

In an interleaved situation, how to determine <level> for pr_cont?
Maybe we should avoid use it if we care about interleaving?

> I believe that an initiator/terminator is necessary
> for reassembly.  Something that could be used
> with pr_<level>, dev_<level>, netdev_<level>, et al.
> 
> mp_start(&cookie)
> pr_<level>(fmt, ...);

Do not need cookie here?

> pr_mp_cont(&cookie, fmt, ...);
> pr_mp_cont(&cookie, fmt "\n", ...);
> mp_end(&cookie);

With initiator/terminator the kernel log will be more structural, but
that will make kernel log a little harder to read too.

Best Regards,
Huang Ying

Re: Printk mulitple line message support

[Joe Perches]

On Tue, 2011-11-15 at 09:52 +0800, Huang Ying wrote:
> On Tue, 2011-11-15 at 09:18 +0800, Joe Perches wrote:
> > I believe you are not solving any real problem
> > with pr_<level>_ml.
> > Most all interleaved complete line uses have some
> > pr_fmt prefix that distinguishes between the sources.
> Except dev_<level> and netdev_<level>, it appears that many general
> pr_<level> do not have the prefix.

I'm working on that.
There are a lot of them and it's a slog.

> > A perhaps larger problem is interleaved partial
> > lines with pr_cont.
> In an interleaved situation, how to determine <level> for pr_cont?

pr_cont has its own KERN_CONT level, it's "<c>", which
is stripped from output by printk.  It's used to continue
the previous printks output on a single line.
 
> > I believe that an initiator/terminator is necessary
> > for reassembly.  Something that could be used
> > with pr_<level>, dev_<level>, netdev_<level>, et al.
> > 
> > mp_start(&cookie)
> > pr_<level>(fmt, ...);
> 
> Do not need cookie here?

Ideally not.

> > pr_mp_cont(&cookie, fmt, ...);
> > pr_mp_cont(&cookie, fmt "\n", ...);
> > mp_end(&cookie);
> 
> With initiator/terminator the kernel log will be more structural, but
> that will make kernel log a little harder to read too.

Initiator/terminator would not be part of printk output
but could exist simply to set/track the atomic/cookie #
and have printk output the appropriate cookie id when
more than 1 cookie is active.

Re: Printk mulitple line message support

[Huang Ying]

On Tue, 2011-11-15 at 10:30 +0800, Joe Perches wrote:
> On Tue, 2011-11-15 at 09:52 +0800, Huang Ying wrote:
> > On Tue, 2011-11-15 at 09:18 +0800, Joe Perches wrote:
> > > I believe you are not solving any real problem
> > > with pr_<level>_ml.
> > > Most all interleaved complete line uses have some
> > > pr_fmt prefix that distinguishes between the sources.
> > Except dev_<level> and netdev_<level>, it appears that many general
> > pr_<level> do not have the prefix.
> 
> I'm working on that.
> There are a lot of them and it's a slog.

Em...  so you think we do not need a general solution?  Just use various
prefix for these pr_<level>?

The down side of this solution is that it is hard to use a simple script
to distinguish interleaved message easily.

> > > A perhaps larger problem is interleaved partial
> > > lines with pr_cont.
> > In an interleaved situation, how to determine <level> for pr_cont?
> 
> pr_cont has its own KERN_CONT level, it's "<c>", which
> is stripped from output by printk.  It's used to continue
> the previous printks output on a single line.

Sorry.  Had some misunderstanding about pr_cont.
 
> > > I believe that an initiator/terminator is necessary
> > > for reassembly.  Something that could be used
> > > with pr_<level>, dev_<level>, netdev_<level>, et al.
> > > 
> > > mp_start(&cookie)
> > > pr_<level>(fmt, ...);
> > 
> > Do not need cookie here?
> 
> Ideally not.
> 
> > > pr_mp_cont(&cookie, fmt, ...);
> > > pr_mp_cont(&cookie, fmt "\n", ...);
> > > mp_end(&cookie);
> > 
> > With initiator/terminator the kernel log will be more structural, but
> > that will make kernel log a little harder to read too.
> 
> Initiator/terminator would not be part of printk output
> but could exist simply to set/track the atomic/cookie #
> and have printk output the appropriate cookie id when
> more than 1 cookie is active.

Oh.  I see.

For multiple part in one line.  I think the better solution may be to
assemble them in a line buffer before real output to console to avoid
interleaving.  Do you think so?

Best Regards,
Huang Ying

Re: Printk mulitple line message support

[Joe Perches]

On Tue, 2011-11-15 at 10:59 +0800, Huang Ying wrote:
> For multiple part in one line.  I think the better solution may be to
> assemble them in a line buffer before real output to console to avoid
> interleaving.  Do you think so?

Hard to say yes for sure.  Immediacy has some value.

There are some downsides to preassembly in memory
constrained systems.

On the other hand, most uses of pr_cont don't create
very long lines.

Re: Printk mulitple line message support

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 254 bytes --]

On Mon, 14 Nov 2011 17:18:03 PST, Joe Perches said:

> mp_start(&cookie)
> pr_<level>(fmt, ...);
> pr_mp_cont(&cookie, fmt, ...);
> pr_mp_cont(&cookie, fmt "\n", ...);
> mp_end(&cookie);

What should happen if buggy code returns before calling mp_end()?

[-- Attachment #2: Type: application/pgp-signature, Size: 227 bytes --]

Re: Printk mulitple line message support

[Joe Perches]

On Tue, 2011-11-15 at 19:29 -0500, Valdis.Kletnieks@vt.edu wrote:
> On Mon, 14 Nov 2011 17:18:03 PST, Joe Perches said:
> 
> > mp_start(&cookie)
> > pr_<level>(fmt, ...);
> > pr_mp_cont(&cookie, fmt, ...);
> > pr_mp_cont(&cookie, fmt "\n", ...);
> > mp_end(&cookie);
> 
> What should happen if buggy code returns before calling mp_end()?

Every pr_cont use gets emitted with a cookie id
which is annoying enough to get the code fixed
rather quickly no? 

Re: Printk mulitple line message support

[Huang Ying]

On Tue, 2011-11-15 at 11:41 +0800, Joe Perches wrote:
> On Tue, 2011-11-15 at 10:59 +0800, Huang Ying wrote:
> > For multiple part in one line.  I think the better solution may be to
> > assemble them in a line buffer before real output to console to avoid
> > interleaving.  Do you think so?
> 
> Hard to say yes for sure.  Immediacy has some value.
> 
> There are some downsides to preassembly in memory
> constrained systems.
> 
> On the other hand, most uses of pr_cont don't create
> very long lines.

Yes.  And I think too long line is bad and should be warned.

Best Regards,
Huang Ying

Re: Printk mulitple line message support

[Huang Ying]

On Tue, 2011-11-15 at 10:30 +0800, Joe Perches wrote:
> On Tue, 2011-11-15 at 09:52 +0800, Huang Ying wrote:
> > On Tue, 2011-11-15 at 09:18 +0800, Joe Perches wrote:
> > > I believe you are not solving any real problem
> > > with pr_<level>_ml.
> > > Most all interleaved complete line uses have some
> > > pr_fmt prefix that distinguishes between the sources.
> > Except dev_<level> and netdev_<level>, it appears that many general
> > pr_<level> do not have the prefix.
> 
> I'm working on that.
> There are a lot of them and it's a slog.

What's your solution here?  Fix multiline pr_<level> one by one with
various prefix?  How about lines with same prefix comes from different
CPU?

Best Regards,
Huang Ying

Re: Printk mulitple line message support

[Joe Perches]

On Wed, 2011-11-16 at 08:45 +0800, Huang Ying wrote:
> On Tue, 2011-11-15 at 10:30 +0800, Joe Perches wrote:
> > On Tue, 2011-11-15 at 09:52 +0800, Huang Ying wrote:
> > > On Tue, 2011-11-15 at 09:18 +0800, Joe Perches wrote:
> > > > I believe you are not solving any real problem
> > > > with pr_<level>_ml.
> > > > Most all interleaved complete line uses have some
> > > > pr_fmt prefix that distinguishes between the sources.
> > > Except dev_<level> and netdev_<level>, it appears that many general
> > > pr_<level> do not have the prefix.
> > I'm working on that.
> > There are a lot of them and it's a slog.
> What's your solution here?

Coalesce the multiple printks to a single printk
without KERN_CONT use at all.

For example: commit 94f05b0f60de32

> Fix multiline pr_<level> one by one with
> various prefix?

Yes, though I believe multiline_pr_<level>
isn't particularly valuable.

> How about lines with same prefix comes from different
> CPU?

Generally, emitting complete lines even from the same
module via multiple threads from a single or multiple
cpus can be intelligibly interleaved without issue.

I believe it's the printks that use KERN_CONT and the
printks without terminating newlines that are the
problems that need to be resolved somehow.

cheers, Joe