[PATCH] printk(): add KERN_CONT where needed

[PATCH] printk(): add KERN_CONT where needed

[Kay Sievers]

From: Kay Sievers <kay@vrfy.org>
Subject: printk(): add KERN_CONT where needed

A prototype for kmsg records instead of a byte-stream buffer revealed
a couple of missing printk(KERN_CONT ...) uses. Subsequent calls produce
one record per printk() call, while all should have ended up in a single
record.

Instead of:
  ACPI: (supports S0 S5)
  ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
  hpet0: at MMIO 0xfed00000, IRQs 2 , 8 , 0

It prints:
  ACPI: (supports S0
   S5
  )
  ACPI: PCI Interrupt Link [LNKA] (IRQs
   5
   *10
   11
  )
  hpet0: at MMIO 0xfed00000, IRQs
   2
  , 8
  , 0

Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Len Brown <lenb@kernel.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Signed-off-by: Kay Sievers <kay@vrfy.org>
---
 drivers/acpi/pci_link.c |   12 ++++++------
 drivers/acpi/sleep.c    |    8 ++++----
 drivers/char/hpet.c     |    4 ++--
 drivers/tty/vt/vt.c     |    3 +--
 mm/page_alloc.c         |    6 +++---
 5 files changed, 16 insertions(+), 17 deletions(-)

--- a/drivers/acpi/pci_link.c
+++ b/drivers/acpi/pci_link.c
@@ -720,21 +720,21 @@ static int acpi_pci_link_add(struct acpi
 	       acpi_device_bid(device));
 	for (i = 0; i < link->irq.possible_count; i++) {
 		if (link->irq.active == link->irq.possible[i]) {
-			printk(" *%d", link->irq.possible[i]);
+			printk(KERN_CONT " *%d", link->irq.possible[i]);
 			found = 1;
 		} else
-			printk(" %d", link->irq.possible[i]);
+			printk(KERN_CONT " %d", link->irq.possible[i]);
 	}
 
-	printk(")");
+	printk(KERN_CONT ")");
 
 	if (!found)
-		printk(" *%d", link->irq.active);
+		printk(KERN_CONT " *%d", link->irq.active);
 
 	if (!link->device->status.enabled)
-		printk(", disabled.");
+		printk(KERN_CONT ", disabled.");
 
-	printk("\n");
+	printk(KERN_CONT "\n");
 
 	list_add_tail(&link->list, &acpi_link_list);
 
--- a/drivers/acpi/sleep.c
+++ b/drivers/acpi/sleep.c
@@ -883,7 +883,7 @@ int __init acpi_sleep_init(void)
 		status = acpi_get_sleep_type_data(i, &type_a, &type_b);
 		if (ACPI_SUCCESS(status)) {
 			sleep_states[i] = 1;
-			printk(" S%d", i);
+			printk(KERN_CONT " S%d", i);
 		}
 	}
 
@@ -897,7 +897,7 @@ int __init acpi_sleep_init(void)
 		hibernation_set_ops(old_suspend_ordering ?
 			&acpi_hibernation_ops_old : &acpi_hibernation_ops);
 		sleep_states[ACPI_STATE_S4] = 1;
-		printk(" S4");
+		printk(KERN_CONT " S4");
 		if (!nosigcheck) {
 			acpi_get_table(ACPI_SIG_FACS, 1,
 				(struct acpi_table_header **)&facs);
@@ -910,11 +910,11 @@ int __init acpi_sleep_init(void)
 	status = acpi_get_sleep_type_data(ACPI_STATE_S5, &type_a, &type_b);
 	if (ACPI_SUCCESS(status)) {
 		sleep_states[ACPI_STATE_S5] = 1;
-		printk(" S5");
+		printk(KERN_CONT " S5");
 		pm_power_off_prepare = acpi_power_off_prepare;
 		pm_power_off = acpi_power_off;
 	}
-	printk(")\n");
+	printk(KERN_CONT ")\n");
 	/*
 	 * Register the tts_notifier to reboot notifier list so that the _TTS
 	 * object can also be evaluated when the system enters S5.
--- a/drivers/char/hpet.c
+++ b/drivers/char/hpet.c
@@ -906,8 +906,8 @@ int hpet_alloc(struct hpet_data *hdp)
 		hpetp->hp_which, hdp->hd_phys_address,
 		hpetp->hp_ntimer > 1 ? "s" : "");
 	for (i = 0; i < hpetp->hp_ntimer; i++)
-		printk("%s %d", i > 0 ? "," : "", hdp->hd_irq[i]);
-	printk("\n");
+		printk(KERN_CONT "%s %d", i > 0 ? "," : "", hdp->hd_irq[i]);
+	printk(KERN_CONT "\n");
 
 	temp = hpetp->hp_tick_freq;
 	remainder = do_div(temp, 1000000);
--- a/drivers/tty/vt/vt.c
+++ b/drivers/tty/vt/vt.c
@@ -2932,11 +2932,10 @@ static int __init con_init(void)
 	gotoxy(vc, vc->vc_x, vc->vc_y);
 	csi_J(vc, 0);
 	update_screen(vc);
-	pr_info("Console: %s %s %dx%d",
+	pr_info("Console: %s %s %dx%d\n",
 		vc->vc_can_do_color ? "colour" : "mono",
 		display_desc, vc->vc_cols, vc->vc_rows);
 	printable = 1;
-	printk("\n");
 
 	console_unlock();
 
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -4763,12 +4763,12 @@ void __init free_area_init_nodes(unsigne
 	for (i = 0; i < MAX_NR_ZONES; i++) {
 		if (i == ZONE_MOVABLE)
 			continue;
-		printk("  %-8s ", zone_names[i]);
+		printk(KERN_CONT "  %-8s ", zone_names[i]);
 		if (arch_zone_lowest_possible_pfn[i] ==
 				arch_zone_highest_possible_pfn[i])
-			printk("empty\n");
+			printk(KERN_CONT "empty\n");
 		else
-			printk("%0#10lx -> %0#10lx\n",
+			printk(KERN_CONT "%0#10lx -> %0#10lx\n",
 				arch_zone_lowest_possible_pfn[i],
 				arch_zone_highest_possible_pfn[i]);
 	}

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 03:18 +0200, Kay Sievers wrote:
> From: Kay Sievers <kay@vrfy.org>
> Subject: printk(): add KERN_CONT where needed
> 
> A prototype for kmsg records instead of a byte-stream buffer revealed
> a couple of missing printk(KERN_CONT ...) uses. Subsequent calls produce
> one record per printk() call, while all should have ended up in a single
> record.
> 
> Instead of:
>   ACPI: (supports S0 S5)
>   ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
>   hpet0: at MMIO 0xfed00000, IRQs 2 , 8 , 0
> 
> It prints:
>   ACPI: (supports S0
>    S5
>   )
>   ACPI: PCI Interrupt Link [LNKA] (IRQs
>    5
>    *10
>    11
>   )
>   hpet0: at MMIO 0xfed00000, IRQs
>    2
>   , 8
>   , 0


You are going to find many, many _hundreds_ of these.

Maybe it'd be better to aggregate content rather like
printk does.  Aggregate until you get a newline or a
new KERN_<LEVEL>

A couple of other trivial comments:

It's better to try to coalesce multiple printks(KERN_CONT
(perhaps it's better to use pr_cont instead too)

Branches with the same printks should be hoisted where
possible.

> --- a/drivers/acpi/pci_link.c
> @@ -720,21 +720,21 @@ static int acpi_pci_link_add(struct acpi
>  	       acpi_device_bid(device));
>  	for (i = 0; i < link->irq.possible_count; i++) {
>  		if (link->irq.active == link->irq.possible[i]) {
> -			printk(" *%d", link->irq.possible[i]);
> +			printk(KERN_CONT " *%d", link->irq.possible[i]);
>  			found = 1;
>  		} else
> -			printk(" %d", link->irq.possible[i]);
> +			printk(KERN_CONT " %d", link->irq.possible[i]);
>  	}

Hoisting gives:

	for (i = 0; ...) {
		pr_cont(" %d", link->irq.possible[i]);
		if (link->irq.active == link->irq.possible[i])
 			found = 1;
	}

>  	if (!found)
> -		printk(" *%d", link->irq.active);
> +		printk(KERN_CONT " *%d", link->irq.active);
>  
>  	if (!link->device->status.enabled)
> -		printk(", disabled.");
> +		printk(KERN_CONT ", disabled.");
>  
> -	printk("\n");
> +	printk(KERN_CONT "\n");

Coalesced this is:

	if (!found)
		pr_cont(") *%d%s\n",
			link->irq.active,
			!link->device->status.enabled ? ", disabled" : "");
	else
		pr_cont("}%s\n",
			!link->device->status.enabled ? ", disabled" : "")

Re: [PATCH] printk(): add KERN_CONT where needed

[Kay Sievers]

On Tue, Apr 3, 2012 at 04:36, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-04-03 at 03:18 +0200, Kay Sievers wrote:

>>   hpet0: at MMIO 0xfed00000, IRQs
>>    2
>>   , 8
>>   , 0

> You are going to find many, many _hundreds_ of these.

Yeah, and they should all be fixed over time. It's 2012 and time to
make kernel log messages readable for machines, not for humans to
puzzle them together. :)

> Maybe it'd be better to aggregate content rather like
> printk does.  Aggregate until you get a newline or a
> new KERN_<LEVEL>

The continuation printk() can can always go wrong when multiple
threads do that in parallel. We can try to make it better with a
per-cpu buffer, but I guess there will always be a situation where
this can happen.

I'm confident, that only callers who are willing to take that 'risk'
of interleaved messages should be exposed to the problem, and never
ones who print proper single lines.

In other words, we should guarantee that there is no garbage left from
any earlier printk() for someone who does not want to play this
continuation print() game.

> A couple of other trivial comments:
>
> It's better to try to coalesce multiple printks(KERN_CONT
> (perhaps it's better to use pr_cont instead too)
>
> Branches with the same printks should be hoisted where
> possible.

Sure, please send patches for anything that is more appropriate to use here.

I did not want to change any logic which needs to be tested. I just
trivially added the obviously missing prefix, which solved the
problem, and which could be applied right away.

Kay

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 05:00 +0200, Kay Sievers wrote:
> I just
> trivially added the obviously missing prefix, which solved the
> problem, and which could be applied right away.

Actually, you didn't solve any problem.  You just made
it less likely to be interleaved against any other
bare printk.  But there are still _thousands_ of bare
printks.

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 05:00 +0200, Kay Sievers wrote:
> On Tue, Apr 3, 2012 at 04:36, Joe Perches <joe@perches.com> wrote:
> > A couple of other trivial comments:
> > It's better to try to coalesce multiple printks(KERN_CONT
> > (perhaps it's better to use pr_cont instead too)
> > Branches with the same printks should be hoisted where
> > possible.
> Sure, please send patches for anything that is more appropriate to use here.
> I did not want to change any logic which needs to be tested. I just
> trivially added the obviously missing prefix, which solved the
> problem, and which could be applied right away.

I think you should do it "right" rather than add
trivial markers.

Re: [PATCH] printk(): add KERN_CONT where needed

[Kay Sievers]

On Tue, Apr 3, 2012 at 05:47, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-04-03 at 05:00 +0200, Kay Sievers wrote:
>> On Tue, Apr 3, 2012 at 04:36, Joe Perches <joe@perches.com> wrote:
>> > A couple of other trivial comments:
>> > It's better to try to coalesce multiple printks(KERN_CONT
>> > (perhaps it's better to use pr_cont instead too)
>> > Branches with the same printks should be hoisted where
>> > possible.
>> Sure, please send patches for anything that is more appropriate to use here.
>> I did not want to change any logic which needs to be tested. I just
>> trivially added the obviously missing prefix, which solved the
>> problem, and which could be applied right away.
>
> I think you should do it "right" rather than add
> trivial markers.

The trivial markers _are_ correct. And they really fix things as soon
as we start storing machine-readable records with printk(), instead of
blindly glueing bytes together with each printk() call, for humans to
puzzle with them if things go wrong.

The stuff you propose is a pretty different story. I see your point,
but it's more 'cosmetics' in code than not simple correctness fixes.

Kay

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 12:30 +0200, Kay Sievers wrote:
> On Tue, Apr 3, 2012 at 05:47, Joe Perches <joe@perches.com> wrote:
> > I think you should do it "right" rather than add
> > trivial markers.
> 
> The trivial markers _are_ correct. And they really fix things as soon
> as we start storing machine-readable records with printk(), instead of
> blindly glueing bytes together with each printk() call, for humans to
> puzzle with them if things go wrong.

These KERN_CONT changes don't _fix_ things,
they just make it less likely to cause problems.

Imagine two threads with printks extended with
KERN_CONT

Thread 1:                                 Thread 2:
printk(KERN_INFO "info message: ");
                                          printk(KERN_ERR "err message: ");
printk(KERN_CONT "online\n");
                                          printk(KERN_CONT "offline\n");

Instead of a guarantee of "info message: online" and
"err message: offline", buffering could still join
the messages to "err message: online".

I believe the only _guaranteed_ way to correctly
assemble these messages is to use a initiator with
a cookie and pass that cookie to assembling printks.

Something like:

	cookie = multi_printk_start()
	multi_printk(cookie, level fmt, ...);
	...
	multi_printk_end(cookie);

Though get_current() might be a reasonable cookie
so perhaps the multi_ variants aren't needed.

git.kernel.org isn't responding right now.  I
can't read the link you sent me privately to
check if you are using get_current() or some
other current_thread_info() constuct.

Re: [PATCH] printk(): add KERN_CONT where needed

[Kay Sievers]

On Tue, Apr 3, 2012 at 16:32, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-04-03 at 12:30 +0200, Kay Sievers wrote:
>> On Tue, Apr 3, 2012 at 05:47, Joe Perches <joe@perches.com> wrote:
>> > I think you should do it "right" rather than add
>> > trivial markers.
>>
>> The trivial markers _are_ correct. And they really fix things as soon
>> as we start storing machine-readable records with printk(), instead of
>> blindly glueing bytes together with each printk() call, for humans to
>> puzzle with them if things go wrong.
>
> These KERN_CONT changes don't _fix_ things,
> they just make it less likely to cause problems.

They sure changes things, as you can see in the first message in this
thread. This is a real paste of output, not made up stuff.

It will matter as soon as we do not allow the next printk() to get
appended to 'left-over garbage' of the last printk() without a
trailing '\n'. We should not allow that, and the 'risk' of
interleaving and garbled messages should be limited to threads which
_both_ do continuation at the same time. The likeliness of that will
get pretty low.

We should make absolutely sure, it will never affect the thread which
does a proper single and complete line.

> Imagine two threads with printks extended with
> KERN_CONT
>
> Thread 1:                                 Thread 2:
> printk(KERN_INFO "info message: ");
>                                          printk(KERN_ERR "err message: ");
> printk(KERN_CONT "online\n");
>                                          printk(KERN_CONT "offline\n");
>
> Instead of a guarantee of "info message: online" and
> "err message: offline", buffering could still join
> the messages to "err message: online".

Yes, both threads play racy games with continuation, and that makes
them both vulnerable to interleaving. But we must make sure, that
single and complete lines are never affected by that.

I did not claim to address the problem of concurrent continuation line
writers, and this patch has absolutely nothing to do with that
problem. It _does_ fix encountered problems, and it is correct as it
is. Please do not mix other issues you bring up here into it, they
should go into a separate thread, unrelated to this patch.

> I believe the only _guaranteed_ way to correctly
> assemble these messages is to use a initiator with
> a cookie and pass that cookie to assembling printks.
>
> Something like:
>
>        cookie = multi_printk_start()
>        multi_printk(cookie, level fmt, ...);
>        ...
>        multi_printk_end(cookie);
>
> Though get_current() might be a reasonable cookie
> so perhaps the multi_ variants aren't needed.

Apart from *possibly* switching to per-cpu buffers for printk() core,
I think the callers should probably just do that on their own, maybe
just on the stack, if the message is small enough.

> git.kernel.org isn't responding right now.  I
> can't read the link you sent me privately to
> check if you are using get_current() or some
> other current_thread_info() constuct.

No, it does not change any current behaviour or gets any knowledge
about threads, it just makes sure that full and single line always
ends up in its own record instead of accepting unterminated left-overs
from earlier printk()s.

Thanks,
Kay

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 17:50 +0200, Kay Sievers wrote:
> I did not claim to address the problem of concurrent continuation line
> writers, and this patch has absolutely nothing to do with that
> problem. It _does_ fix encountered problems,

No it doesn't.  It fixes problems _you_ encounter
with an unpublished modification of the printk
subsystem.

Re: [PATCH] printk(): add KERN_CONT where needed

[Kay Sievers]

On Tue, Apr 3, 2012 at 18:05, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-04-03 at 17:50 +0200, Kay Sievers wrote:
>> I did not claim to address the problem of concurrent continuation line
>> writers, and this patch has absolutely nothing to do with that
>> problem. It _does_ fix encountered problems,
>
> No it doesn't.  It fixes problems _you_ encounter
> with an unpublished modification of the printk
> subsystem.

Exactly. And that is what is written in the changelog of the patch.
But all that does not matter, the change results in more correct code
than the current one is; and that is all that matters.

Sure, I see your point, and support your effort, but I don't think
your arguments are related to this patch and you are hijacking
something unrelated, which should be discussed in a separate mail
thread, that's all.

Thanks,
Kay

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 18:11 +0200, Kay Sievers wrote:
> On Tue, Apr 3, 2012 at 18:05, Joe Perches <joe@perches.com> wrote:
> > On Tue, 2012-04-03 at 17:50 +0200, Kay Sievers wrote:
> >> I did not claim to address the problem of concurrent continuation line
> >> writers, and this patch has absolutely nothing to do with that
> >> problem. It _does_ fix encountered problems,
> >
> > No it doesn't.  It fixes problems _you_ encounter
> > with an unpublished modification of the printk
> > subsystem.
> 
> Exactly. And that is what is written in the changelog of the patch.
> But all that does not matter, the change results in more correct code
> than the current one is; and that is all that matters.
> 
> Sure, I see your point, and support your effort, but I don't think
> your arguments are related to this patch and you are hijacking
> something unrelated, which should be discussed in a separate mail
> thread, that's all.

Conversations happen all over the place and making
separate discussions isn't that valuable nor are
they really controllable.

Just write the change log to simply state "add KERN_CONT"
without mentioning your unpublished stuff.

cheers, Joe

Re: [PATCH] printk(): add KERN_CONT where needed

[Kay Sievers]

On Tue, Apr 3, 2012 at 18:16, Joe Perches <joe@perches.com> wrote:
> Conversations happen all over the place and making
> separate discussions isn't that valuable nor are
> they really controllable.

Sure, but this is not a conversation in that sense, you reply to a
patch that something is not correct, but what's not correct is not a
subject of the patch. And that I need to correct.

> Just write the change log to simply state "add KERN_CONT"
> without mentioning your unpublished stuff.

The changelog says:

"A prototype for kmsg records instead of a byte-stream buffer revealed
a couple of missing printk(KERN_CONT ...) uses. Subsequent calls produce
one record per printk() call, while all should have ended up in a single
record."

What else do you need?

Kay

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Tue, 2012-04-03 at 18:20 +0200, Kay Sievers wrote:
> On Tue, Apr 3, 2012 at 18:16, Joe Perches <joe@perches.com> wrote:
> > Conversations happen all over the place and making
> > separate discussions isn't that valuable nor are
> > they really controllable.
> 
> Sure, but this is not a conversation in that sense, you reply to a
> patch that something is not correct, but what's not correct is not a
> subject of the patch. And that I need to correct.
> 
> > Just write the change log to simply state "add KERN_CONT"
> > without mentioning your unpublished stuff.
> 
> The changelog says:
> 
> "A prototype for kmsg records instead of a byte-stream buffer revealed
> a couple of missing printk(KERN_CONT ...) uses. Subsequent calls produce
> one record per printk() call, while all should have ended up in a single
> record."
> 
> What else do you need?

You need less.

This has nothing to do with the current printk subsystem,
it has only to do with using KERN_CONT.

Maybe:

trivial: add some KERN_CONT markers to continuation lines

or something like:

commit 66d0ae4d6ffa45b8e6d8bdbf85f8f1b285c8152d
Author: Jiri Slaby <jirislaby@gmail.com>
Date:   Sun Dec 6 16:16:24 2009 +0100

    PM / Hibernate: Swap, use KERN_CONT
    
    Use KERN_CONT in save_image() for printks, so that anybody won't
    try to add a loglevel.
    
    Signed-off-by: Jiri Slaby <jirislaby@gmail.com>
    Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>

Re: [PATCH] printk(): add KERN_CONT where needed

[Andrew Morton]

On Tue, 3 Apr 2012 05:00:10 +0200
Kay Sievers <kay@vrfy.org> wrote:

> > Maybe it'd be better to aggregate content rather like
> > printk does. __Aggregate until you get a newline or a
> > new KERN_<LEVEL>
> 
> The continuation printk() can can always go wrong when multiple
> threads do that in parallel. We can try to make it better with a
> per-cpu buffer, but I guess there will always be a situation where
> this can happen.

Maybe we can be a bit smarter.  For example, if `current' is unchanged
and __builtin_return_address(0) is unchanged, keep on buffering.

It's all a bit hacky, but weeding out all those thousands of printks
which never get printed anyway doesn't sound much fun either.

> -	printk(")");
> +	printk(KERN_CONT ")");

And I do think we should avoid doing it that way, if only because it
consumes 10 display columns and makes a mess.  Maybe use pr_cont()? 
But that implies that the affected code is using the pr_foo()
facilities, and a lot of it doesn't.  So maybe a new macro.

All a bit of a pain.

Re: [PATCH] printk(): add KERN_CONT where needed

[Joe Perches]

On Mon, 2012-04-09 at 16:08 -0700, Andrew Morton wrote:
> On Tue, 3 Apr 2012 05:00:10 +0200
> Kay Sievers <kay@vrfy.org> wrote:
> 
> > > Maybe it'd be better to aggregate content rather like
> > > printk does. __Aggregate until you get a newline or a
> > > new KERN_<LEVEL>
> > 
> > The continuation printk() can can always go wrong when multiple
> > threads do that in parallel. We can try to make it better with a
> > per-cpu buffer, but I guess there will always be a situation where
> > this can happen.
> 
> Maybe we can be a bit smarter.  For example, if `current' is unchanged
> and __builtin_return_address(0) is unchanged, keep on buffering.

There are dozens to hundreds of existing sequences
like:

void some_func(...)
{
	printk("some additional data");
}

...

void some_device_init(...)
{
	...
	printk([KERN_LEVEL or not] "some initiator")
	some_func();
	printk("\n");
}

> It's all a bit hacky, but weeding out all those thousands of printks
> which never get printed anyway doesn't sound much fun either.

Nope.  That isn't any fun.

So given the example above, maybe check if the
initial printk's __builtin_return_address(0) exists
in some level of the stack say up to 3 deep for each
subsequent printk.

I don't remember any threads spun off to emit printk
continuation lines so maybe that'd work reasonably
well.

> All a bit of a pain.

Too true.