Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1499698 > unrolled thread

linux.git: printk() problem

Back to article view | Back to linux.kernel

Contents

  linux.git: printk() problem Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2016-10-12 15:40 +0200
    Re: linux.git: printk() problem Michal Hocko <mhocko@kernel.org> - 2016-10-12 17:00 +0200
      Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-12 18:10 +0200
        Re: linux.git: printk() problem Michal Hocko <mhocko@kernel.org> - 2016-10-13 08:30 +0200
          Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-13 11:40 +0200
            Re: linux.git: printk() problem Michal Hocko <mhocko@kernel.org> - 2016-10-13 12:10 +0200
              Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-13 12:30 +0200
                Re: linux.git: printk() problem Michal Hocko <mhocko@kernel.org> - 2016-10-13 13:10 +0200
    Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-12 17:50 +0200
      Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-12 18:20 +0200
        Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-12 19:00 +0200
          [PATCH] acpi_os_vprintf: Use printk_get_level() to avoid unnecessary KERN_CONT Joe Perches <joe@perches.com> - 2016-10-12 21:00 +0200
            Re: [PATCH] acpi_os_vprintf: Use printk_get_level() to avoid unnecessary KERN_CONT "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2016-10-14 00:10 +0200
      Re: linux.git: printk() problem Geert Uytterhoeven <geert@linux-m68k.org> - 2016-10-23 11:30 +0200
        Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-23 20:20 +0200
          Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-23 21:10 +0200
            Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-23 21:40 +0200
              Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-23 21:50 +0200
                Re: linux.git: printk() problem Geert Uytterhoeven <geert@linux-m68k.org> - 2016-10-24 13:20 +0200
                Re: linux.git: printk() problem Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-10-24 16:20 +0200
                  Re: linux.git: printk() problem Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-10-24 16:30 +0200
                  Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-24 20:00 +0200
                    Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-24 20:00 +0200
                      Re: linux.git: printk() problem Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-25 04:00 +0200
                        Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-25 04:10 +0200
                          Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-25 04:30 +0200
                            Re: linux.git: printk() problem Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-25 06:10 +0200
                              Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-25 06:20 +0200
                              Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-25 06:30 +0200
                                Re: linux.git: printk() problem Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-25 06:50 +0200
                            Re: linux.git: printk() problem Petr Mladek <pmladek@suse.com> - 2016-10-25 16:50 +0200
                        Re: linux.git: printk() problem Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-25 04:30 +0200
              Re: linux.git: printk() problem Joe Perches <joe@perches.com> - 2016-10-23 22:40 +0200
                Re: linux.git: printk() problem Linus Torvalds <torvalds@linux-foundation.org> - 2016-10-23 23:20 +0200
          Re: linux.git: printk() problem Steven Rostedt <rostedt@goodmis.org> - 2016-10-25 16:50 +0200

Page 1 of 2  [1] 2  Next page →

#1499698 — linux.git: printk() problem

Hello.

I noticed that current linux.git generates hardly readable console output
due to KERN_CONT changes. Are you suggesting developers that output like
this be fixed?

[   93.723582] Mem-Info:
[   93.725919] active_anon:380970 inactive_anon:2098 isolated_anon:0
[   93.725919]  active_file:242 inactive_file:275 isolated_file:0
[   93.725919]  unevictable:0 dirty:0 writeback:65 unstable:0
[   93.725919]  slab_reclaimable:3825 slab_unreclaimable:12527
[   93.725919]  mapped:760 shmem:2164 pagetables:9297 bounce:0
[   93.725919]  free:14046 free_pcp:74 free_cma:0
[   93.735626] Node 0 active_anon:1523880kB inactive_anon:8392kB active_file:968kB inactive_file:1100kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:3040kB dirty:0kB writeback:244kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 1056768kB anon_thp: 8656kB writeback_tmp:0kB unstable:0kB pages_scanned:0 all_unreclaimable? no
[   93.742894] Node 0 [   93.743319] DMA free:7156kB min:408kB low:508kB high:608kB active_anon:8672kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15904kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:40kB kernel_stack:0kB pagetables:36kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[   93.750951] lowmem_reserve[]:[   93.751597]  0
 1699[   93.752678]  1699
 1699[   93.753910] 
[   93.754822] Node 0 [   93.755216] DMA32 free:49028kB min:44644kB low:55804kB high:66964kB active_anon:1515208kB inactive_anon:8392kB active_file:968kB inactive_file:960kB unevictable:0kB writepending:232kB present:2080640kB managed:1760736kB mlocked:0kB slab_reclaimable:15300kB slab_unreclaimable:50068kB kernel_stack:20320kB pagetables:37152kB bounce:0kB free_pcp:436kB local_pcp:240kB free_cma:0kB
[   93.763709] lowmem_reserve[]:[   93.764235]  0
 0[   93.765630]  0
 0[   93.767544] 
[   93.768676] Node 0 [   93.769135] DMA: 
1*4kB [   93.770932] (U) 
0*8kB [   93.772192] 1*16kB 
(U) [   93.773438] 1*32kB 
(M) [   93.774574] 1*64kB 
(U) [   93.775997] 1*128kB 
(U) [   93.777665] 1*256kB 
(U) [   93.778861] 1*512kB 
(M) [   93.780004] 2*1024kB 
(UM) [   93.781225] 0*2048kB 
1*4096kB [   93.782422] (M) 
[   93.783423] = 7156kB
[   93.784445] Node 0 [   93.784844] DMA32: 
1265*4kB [   93.786204] (UMEH) 
790*8kB [   93.787412] (UMEH) 
335*16kB [   93.788634] (UEH) 
265*32kB [   93.790037] (UE) 
89*64kB [   93.791254] (UEH) 
23*128kB [   93.792541] (UME) 
9*256kB [   93.793787] (ME) 
13*512kB [   93.794956] (UME) 
6*1024kB [   93.796094] (UME) 
0*2048kB [   93.797435] 0*4096kB 
[   93.798413] = 48964kB
[   93.799357] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[   93.802221] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[   93.804476] 2700 total pagecache pages
[   93.805949] 0 pages in swap cache
[   93.807557] Swap cache stats: add 0, delete 0, find 0/0
[   93.809417] Free swap  = 0kB
[   93.810573] Total swap = 0kB
[   93.811788] 524157 pages RAM
[   93.812903] 0 pages HighMem/MovableOnly
[   93.814216] 79997 pages reserved
[   93.815292] 0 pages hwpoisoned

[  185.497015] Showing all locks held in the system:
[  185.500009] 1 lock held by systemd/1:
[  185.501377]  #0: [  185.501717]  (
&(&ip->i_mmaplock)->mr_lock[  185.503347] ){++++++}
, at: [  185.504566] [<ffffffff812a1600>] xfs_ilock+0xd0/0xe0
[  185.506157] 2 locks held by khungtaskd/46:
[  185.507553]  #0: [  185.507896]  (
rcu_read_lock[  185.509091] ){......}
, at: [  185.510277] [<ffffffff8112054e>] watchdog+0x9e/0x480
[  185.512072]  #1: [  185.512413]  (
tasklist_lock[  185.513602] ){.+.+..}
, at: [  185.514802] [<ffffffff810b5adf>] debug_show_all_locks+0x3f/0x1b0

[toc] | [next] | [standalone]

#1499747

On Wed 12-10-16 22:30:03, Tetsuo Handa wrote:
> Hello.
> 
> I noticed that current linux.git generates hardly readable console output
> due to KERN_CONT changes. Are you suggesting developers that output like
> this be fixed?

Joe has already posted a patch
http://lkml.kernel.org/r/c7df37c8665134654a17aaeb8b9f6ace1d6db58b.1476239034.git.joe@perches.com

And in general I think that adding those KERN_CONT is a good thing to
do.
-- 
Michal Hocko
SUSE Labs

[toc] | [prev] | [next] | [standalone]

#1499796

On Wed, 2016-10-12 at 16:35 +0200, Michal Hocko wrote:
> On Wed 12-10-16 22:30:03, Tetsuo Handa wrote:
> > Hello.
> > 
> > I noticed that current linux.git generates hardly readable console output
> > due to KERN_CONT changes. Are you suggesting developers that output like
> > this be fixed?
> 
> 
> Joe has already posted a patch
> http://lkml.kernel.org/r/c7df37c8665134654a17aaeb8b9f6ace1d6db58b.1476239034.git.joe@perches.com
> 
> And in general I think that adding those KERN_CONT is a good thing to
> do.

As do I, but there are about a quarter _million_ uses of
printk/logging messages in the kernel tree with newlines.

Maybe 100 or so of the existing messages lack terminating
newlines.

There are about 1800 uses of KERN_CONT/pr_cont today.

There are multiple thousands of uses of bare printks used as
printk line continuations that would need updating.

Most of those multiple thousands are in drivers of ancient and
out of manufacture devices or are subsystems that are old, crufty
and effectively unmaintained.  These might not need to be updated.

Still, there are probably hundreds to low thousands of actively
used device drivers that will need KERN?CONT or pr_cont update to
avoid logging output defects.

[toc] | [prev] | [next] | [standalone]

#1500045

On Wed 12-10-16 09:08:58, Joe Perches wrote:
> On Wed, 2016-10-12 at 16:35 +0200, Michal Hocko wrote:
> > On Wed 12-10-16 22:30:03, Tetsuo Handa wrote:
> > > Hello.
> > > 
> > > I noticed that current linux.git generates hardly readable console output
> > > due to KERN_CONT changes. Are you suggesting developers that output like
> > > this be fixed?
> > 
> > 
> > Joe has already posted a patch
> > http://lkml.kernel.org/r/c7df37c8665134654a17aaeb8b9f6ace1d6db58b.1476239034.git.joe@perches.com
> > 
> > And in general I think that adding those KERN_CONT is a good thing to
> > do.
> 
> As do I, but there are about a quarter _million_ uses of
> printk/logging messages in the kernel tree with newlines.
> 
> Maybe 100 or so of the existing messages lack terminating
> newlines.

I think they are not critical and can be fix once somebody notices.

-- 
Michal Hocko
SUSE Labs

[toc] | [prev] | [next] | [standalone]

#1500126

On Thu, 2016-10-13 at 08:26 +0200, Michal Hocko wrote:
> On Wed 12-10-16 09:08:58, Joe Perches wrote:
> > On Wed, 2016-10-12 at 16:35 +0200, Michal Hocko wrote:
> > > On Wed 12-10-16 22:30:03, Tetsuo Handa wrote:
> > > > Hello.
> > > > 
> > > > I noticed that current linux.git generates hardly readable console output
> > > > due to KERN_CONT changes. Are you suggesting developers that output like
> > > > this be fixed?
> > > 
> > > 
> > > 
> > > Joe has already posted a patch
> > > http://lkml.kernel.org/r/c7df37c8665134654a17aaeb8b9f6ace1d6db58b.1476239034.git.joe@perches.com
> > > 
> > > And in general I think that adding those KERN_CONT is a good thing to
> > > do.
> > 
> > 
> > As do I, but there are about a quarter _million_ uses of
> > printk/logging messages in the kernel tree with newlines.
> > 
> > Maybe 100 or so of the existing messages lack terminating
> > newlines.
> 
> 
> I think they are not critical and can be fix once somebody notices.
 
As do I, but Linus objected to applying a patch when Colin Ian King
noticed one.

I think the 250,000 or so uses with newlines are enough of a
precedence to keep using newlines everywhere.

Now we'll have to have patches adding hundreds to thousands of the
missing KERN_CONTs for continuation lines that weren't previously a
problem in logging output but are now.

[toc] | [prev] | [next] | [standalone]

#1500135

On Thu 13-10-16 02:29:46, Joe Perches wrote:
> On Thu, 2016-10-13 at 08:26 +0200, Michal Hocko wrote:
[...]
> > I think they are not critical and can be fix once somebody notices.
>  
> As do I, but Linus objected to applying a patch when Colin Ian King
> noticed one.
> 
> I think the 250,000 or so uses with newlines are enough of a
> precedence to keep using newlines everywhere.

or simply fix missing KERN_CONTs and simply do not add any new missing \n

> Now we'll have to have patches adding hundreds to thousands of the
> missing KERN_CONTs for continuation lines that weren't previously a
> problem in logging output but are now.

I would be really surprised if we really had that many continuation
lines. They should be avoided as much as possible. Hundreds of thousands
just sounds more than over exaggerated...

I think you are just making much bigger deal from this than necessary.
Not requiring \n at the end of strings just makes a lot of sense if we
have a KERN_CONT with a well defined semantic. Which was the whole point
of the patch from Linus AFAIU. If there are some left overs, so what, we
can fix them as soon as somebody notices. The worst thing we will get is
a messy output but no information should be lost. We used to have a
messy output in the past regardless and we could live with it...

That being said I would be happier to know about this change before I
had to scratch my head when seeing this for the first time so a heads up
would be more than appreciated but fixing these issues is trivial not
not worth making a lot of noise about.

-- 
Michal Hocko
SUSE Labs

[toc] | [prev] | [next] | [standalone]

#1500139

On Thu, 2016-10-13 at 12:04 +0200, Michal Hocko wrote:
> On Thu 13-10-16 02:29:46, Joe Perches wrote:
> > On Thu, 2016-10-13 at 08:26 +0200, Michal Hocko wrote:
> 
> [...]
> > > I think they are not critical and can be fix once somebody notices.
> > 
> >  
> > As do I, but Linus objected to applying a patch when Colin Ian King
> > noticed one.
> > 
> > I think the 250,000 or so uses with newlines are enough of a
> > precedence to keep using newlines everywhere.
> 
> 
> or simply fix missing KERN_CONTs and simply do not add any new missing \n
> 
> > Now we'll have to have patches adding hundreds to thousands of the
> > missing KERN_CONTs for continuation lines that weren't previously a
> > problem in logging output but are now.
> 
> 
> I would be really surprised if we really had that many continuation
> lines. They should be avoided as much as possible. Hundreds of thousands
> just sounds more than over exaggerated...

Hey Michal.

"Hundreds _to_ thousands" of instances.  Not "hundreds _of_ thousands".

> Not requiring \n at the end of strings just makes a lot of sense if we
> have a KERN_CONT with a well defined semantic.

True enough.  And I am not at all arguing against having a
well defined KERN_CONT semantic.

But using KERN_CONT alone is not enough information to be able to
perfectly reassemble message fragments post hoc given multiple
threads possibly interleaving KERN_CONT.

I do think the inconsistency of mixing styles with and without
newlines not particularly good.

cheers, Joe

[toc] | [prev] | [next] | [standalone]

#1500164

On Thu 13-10-16 03:20:50, Joe Perches wrote:
> On Thu, 2016-10-13 at 12:04 +0200, Michal Hocko wrote:
[...]
> > I would be really surprised if we really had that many continuation
> > lines. They should be avoided as much as possible. Hundreds of thousands
> > just sounds more than over exaggerated...
> 
> Hey Michal.
> 
> "Hundreds _to_ thousands" of instances.  Not "hundreds _of_ thousands".

my bad I misread your words. Sorry about that

-- 
Michal Hocko
SUSE Labs

[toc] | [prev] | [next] | [standalone]

#1499781

On Wed, Oct 12, 2016 at 6:30 AM, Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>
> I noticed that current linux.git generates hardly readable console output
> due to KERN_CONT changes. Are you suggesting developers that output like
> this be fixed?

Yes. Needing to add a few KERN_CONT markers was pretty much expected,
since it's about 5 years since we enfroced it and new code won't
necessarily have it (and even back then I don't think we _always_ got
it right).

That said, looking at the printk's in the lowmem code, I think it
could be useful if there was some effort to see if the code could
somehow avoid the multi-printk thing. This is actually one area where

 (a) the problem actually happens while the system is running, rather
than booting

 (b) I've seen line mixing in the past

but the short term fix is to just add KERN_CONT markers to the lines
that are continuations.

NOTE! The reason I mention that (a) thing that it has traditionally
made it much messier to do logging of continuation lines in the first
place (because more things are going on and often one problem leads to
another and then the mixing is much more likely), but I actually
intentionally made it more likely to trigger the flushing issue in
commit bfd8d3f23b51 ("printk: make reading the kernel log flush
pending lines").

So if there is an active system logger that is reading messages *when*
one of those "one line in multiple printk's" things happen, that log
reader will now potentially cause the logging to be broken up because
the act of reading will flush the pending lines.

Now, honestly, that is something that we may end up reverting, but I'd
_like_ to try not to. Because without that flushing, there might be
one last partial line that the logger never sees. So it was me trying
to be aggressive about those partial lines, and the *hope* is that we
can just keep it, and that we can look at areas that have problems
with it.

We'll see. But the other issues are easily fixed by just adding
KERN_CONT where appropriate. It was actually very much what you were
supposed to do before too, if only as a marker to others that "yes,
I'm actually doing this, and no, I'm not supposed to have a log level"
(but with the new world order you actually *can* combine KERN_CONT
with a loglevel, so that if the beginning od the line got flushed, the
continuation can still be printed with the right log level).

                Linus

[toc] | [prev] | [next] | [standalone]

#1499803

On Wed, 2016-10-12 at 08:47 -0700, Linus Torvalds wrote:
< We'll see. But the other issues are easily fixed by just adding
> KERN_CONT where appropriate. It was actually very much what you were
> supposed to do before too, if only as a marker to others that "yes,
> I'm actually doing this, and no, I'm not supposed to have a log level"
> (but with the new world order you actually *can* combine KERN_CONT
> with a loglevel, so that if the beginning od the line got flushed, the
> continuation can still be printed with the right log level).

I think that might not be a good idea.

Anything that uses a KERN_CONT with a new log level
might as well be converted into multiple printks.

[toc] | [prev] | [next] | [standalone]

#1499824

On Wed, Oct 12, 2016 at 9:16 AM, Joe Perches <joe@perches.com> wrote:
>> (but with the new world order you actually *can* combine KERN_CONT
>> with a loglevel, so that if the beginning od the line got flushed, the
>> continuation can still be printed with the right log level).
>
> I think that might not be a good idea.
>
> Anything that uses a KERN_CONT with a new log level
> might as well be converted into multiple printks.

Generally yes.

The immediate reason for it was some really really nasty and horrible
indirection in the ACPI layer, which goes through something like
fifteen million different abstraction layers before it actually hits
"printk()", and some of them do vsprintf() in the middle.

It was something like ACPI_INFO() -> acpi_os_printf() ->
acpi_os_vprintf() which is completely broken and *always* has that
KERN_CONT marker at the beginning, but earlier phases can have the
level marker in it already..

In other words, it was a terminally broken piece of nasty code, but
there was no way I was going to touch the ACPI "OS independent"
layers, so I just said "screw this, if you want to mix KERN_CONT with
a level marker, you can".

So I agree, you normally shouldn't need to. In fact, the fewer
KERN_CONT's I see in the kernel, the better off we are. But
_sometimes_ KERN_CONT makes sense (and the OOM code is likely one of
the few places where it really might be the best of a number of bad
options: lots of information that needs to be pretty dense, and we
obviously can't afford to allocate a buffer for it dynamically, and
doing so statically isn't a great option either..)

                 Linus

[toc] | [prev] | [next] | [standalone]

#1499889 — [PATCH] acpi_os_vprintf: Use printk_get_level() to avoid unnecessary KERN_CONT

acpi_os_vprintf currently always uses a KERN_CONT prefix which may be
followed immediately by a proper KERN_<LEVEL>.  Check if the buffer
already has a KERN_<LEVEL> at the start of the buffer and avoid the
unnecessary KERN_CONT.

Signed-off-by: Joe Perches <joe@perches.com>
---
 drivers/acpi/osl.c | 13 ++++++++++---
 1 file changed, 10 insertions(+), 3 deletions(-)

diff --git a/drivers/acpi/osl.c b/drivers/acpi/osl.c
index 4305ee9db4b2..416953a42510 100644
--- a/drivers/acpi/osl.c
+++ b/drivers/acpi/osl.c
@@ -162,11 +162,18 @@ void acpi_os_vprintf(const char *fmt, va_list args)
 	if (acpi_in_debugger) {
 		kdb_printf("%s", buffer);
 	} else {
-		printk(KERN_CONT "%s", buffer);
+		if (printk_get_level(buffer))
+			printk("%s", buffer);
+		else
+			printk(KERN_CONT "%s", buffer);
 	}
 #else
-	if (acpi_debugger_write_log(buffer) < 0)
-		printk(KERN_CONT "%s", buffer);
+	if (acpi_debugger_write_log(buffer) < 0) {
+		if (printk_get_level(buffer))
+			printk("%s", buffer);
+		else
+			printk(KERN_CONT "%s", buffer);
+	}
 #endif
 }
 
-- 
2.10.0.rc2.1.g053435c

[toc] | [prev] | [next] | [standalone]

#1500606 — Re: [PATCH] acpi_os_vprintf: Use printk_get_level() to avoid unnecessary KERN_CONT

On Wednesday, October 12, 2016 11:50:34 AM Joe Perches wrote:
> acpi_os_vprintf currently always uses a KERN_CONT prefix which may be
> followed immediately by a proper KERN_<LEVEL>.  Check if the buffer
> already has a KERN_<LEVEL> at the start of the buffer and avoid the
> unnecessary KERN_CONT.
> 
> Signed-off-by: Joe Perches <joe@perches.com>
> ---
>  drivers/acpi/osl.c | 13 ++++++++++---
>  1 file changed, 10 insertions(+), 3 deletions(-)
> 
> diff --git a/drivers/acpi/osl.c b/drivers/acpi/osl.c
> index 4305ee9db4b2..416953a42510 100644
> --- a/drivers/acpi/osl.c
> +++ b/drivers/acpi/osl.c
> @@ -162,11 +162,18 @@ void acpi_os_vprintf(const char *fmt, va_list args)
>  	if (acpi_in_debugger) {
>  		kdb_printf("%s", buffer);
>  	} else {
> -		printk(KERN_CONT "%s", buffer);
> +		if (printk_get_level(buffer))
> +			printk("%s", buffer);
> +		else
> +			printk(KERN_CONT "%s", buffer);
>  	}
>  #else
> -	if (acpi_debugger_write_log(buffer) < 0)
> -		printk(KERN_CONT "%s", buffer);
> +	if (acpi_debugger_write_log(buffer) < 0) {
> +		if (printk_get_level(buffer))
> +			printk("%s", buffer);
> +		else
> +			printk(KERN_CONT "%s", buffer);
> +	}
>  #endif
>  }

Applied.

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1506653

Hi Linus,

On Wed, Oct 12, 2016 at 5:47 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Wed, Oct 12, 2016 at 6:30 AM, Tetsuo Handa
> <penguin-kernel@i-love.sakura.ne.jp> wrote:
>>
>> I noticed that current linux.git generates hardly readable console output
>> due to KERN_CONT changes. Are you suggesting developers that output like
>> this be fixed?
>
> Yes. Needing to add a few KERN_CONT markers was pretty much expected,
> since it's about 5 years since we enfroced it and new code won't
> necessarily have it (and even back then I don't think we _always_ got
> it right).
>
> That said, looking at the printk's in the lowmem code, I think it
> could be useful if there was some effort to see if the code could
> somehow avoid the multi-printk thing. This is actually one area where
>
>  (a) the problem actually happens while the system is running, rather
> than booting
>
>  (b) I've seen line mixing in the past
>
> but the short term fix is to just add KERN_CONT markers to the lines
> that are continuations.
>
> NOTE! The reason I mention that (a) thing that it has traditionally
> made it much messier to do logging of continuation lines in the first
> place (because more things are going on and often one problem leads to
> another and then the mixing is much more likely), but I actually
> intentionally made it more likely to trigger the flushing issue in
> commit bfd8d3f23b51 ("printk: make reading the kernel log flush
> pending lines").
>
> So if there is an active system logger that is reading messages *when*
> one of those "one line in multiple printk's" things happen, that log
> reader will now potentially cause the logging to be broken up because
> the act of reading will flush the pending lines.

These changes have an interesting side-effect on sequences of printk()s that
lack proper continuation: they introduced a discrepancy between dmesg output
and the actual kernel output.

Before:

    Atari hardware found: VIDEL STDMA-SCSI ST_MFP YM2149 PCM CODEC
DSP56K SCC ANALOG_JOY BLITTER IDE TT_CLK FDC_SPEED

Output of "dmesg" after:

    Atari hardware found:
    VIDEL
    STDMA-SCSI
    ST_MFP
    YM2149
    PCM
    CODEC
    DSP56K
    SCC
    ANALOG_JOY
    BLITTER
    IDE
    TT_CLK
    FDC_SPEED

Actual kernel output after:

    Atari hardware found: VIDEL
    STDMA-SCSI ST_MFP
    YM2149 PCM
    CODEC DSP56K
    SCC ANALOG_JOY
    BLITTER IDE
    TT_CLK FDC_SPEED

Note that the above is really early in the boot process, right after the debug
console is enabled, and before any system log consumer is running,

Of course I'm converting this code to use pr_cont() anyway...

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

[toc] | [prev] | [next] | [standalone]

#1506736

On Sun, Oct 23, 2016 at 2:22 AM, Geert Uytterhoeven
<geert@linux-m68k.org> wrote:
>
> These changes have an interesting side-effect on sequences of printk()s that
> lack proper continuation: they introduced a discrepancy between dmesg output
> and the actual kernel output.

Yes.

So the "print vs log" handling is really really horrible. I cleaned up
some of it, but left the really fundamental problems. I wanted to just
rewrite it all, but didn't quite have the heart for it.

The best solution by far would be to just not support KERN_CONT at
all, but there's too many "silly details" things that keep it from
being possible.

The basic issue is that we have the line buffer that is used for
continuations, and then the record buffer that is used for logging.

And those two per se sound fairly easy to handle ("KERN_CONT means
append to the line buffer, otherwise flush the line buffer and move to
the record buffer").

But what complicates things more is then the "console output", which
has two issues:

 - it is done outside the locking regime for the line buffer and the
record buffer.

 - it is done on _partial_ line buffers.

Again, this would be absolutely trivial if we just said "we only print
the record buffer". Easy, and solves all the problems. Except for
_one_ problem:

 - if a hang occurs in the middle of a continuation, we historically
*really* want that continuation to have been printed out.

For example, one of the really historical uses for partial lines is this:

       pr_info("Checking 'hlt' instruction... ");

       if (!boot_cpu_data.hlt_works_ok) {
               pr_cont("disabled\n");
               return;
       }
       halt();
       halt();
       halt();
       halt();
       pr_cont("OK\n");

and the point was that there used to be some really old i386 machines
that hung on the "hlt" instruction (probably not because of a CPU bug,
but because of either power supply issues or some DMA issues).

To support that, we really *had* to print out the continuation lines
even when they were partial. And that complicates the printk logic a
lot.

Now, that "hlt" case is long long gone, and maybe we should just say
"screw that". It would be really quite easy to say "we don't print out
continuation lines immediately, we just buffer them for 0.1s instead,
and KERN_CONT only works for things that really happen more or less
immediately".

Maybe that really is the right answer. Because the original cause of
us having to bend over backwards in this case is really no longer
there. And it would simplify printk a *lot*.

Let me whip up a minimal patch for you to try.

                Linus

[toc] | [prev] | [next] | [standalone]

#1506742

On Sun, 2016-10-23 at 11:11 -0700, Linus Torvalds wrote:
> On Sun, Oct 23, 2016 at 2:22 AM, Geert Uytterhoeven
> <geert@linux-m68k.org> wrote:
> > 
> > These changes have an interesting side-effect on sequences of printk()s that
> > lack proper continuation: they introduced a discrepancy between dmesg output
> > and the actual kernel output.
> 
> Yes.
> 
> So the "print vs log" handling is really really horrible. I cleaned up
> some of it, but left the really fundamental problems. I wanted to just
> rewrite it all, but didn't quite have the heart for it.
> 
> The best solution by far would be to just not support KERN_CONT at
> all,  but there's too many "silly details" things that keep it from
> being possible.
> 
> The basic issue is that we have the line buffer that is used for
> continuations, and then the record buffer that is used for logging.
> 
> And those two per se sound fairly easy to handle ("KERN_CONT means
> append to the line buffer, otherwise flush the line buffer and move to
> the record buffer").
> 
> But what complicates things more is then the "console output", which
> has two issues:
> 
>  - it is done outside the locking regime for the line buffer and the
> record buffer.
> 
>  - it is done on _partial_ line buffers.

EOL KERN_<LEVEL> and thread interleaving still exists.

> It would be really quite easy to say "we don't print out
> continuation lines immediately, we just buffer them for 0.1s instead,
> and KERN_CONT only works for things that really happen more or less
> immediately".

Or use to a start/stop buffer (maybe via KERN_<LEVEL> and \n) with
PID/TIDs added to /dev/kmsg and that short-term timer to reassemble.

> Maybe that really is the right answer. Because the original cause of
> us having to bend over backwards in this case is really no longer
> there. And it would simplify printk a *lot*.

A timer might be a good idea, but perhaps Sergey and Petr might
have some interest in that too. (added to cc's)

[toc] | [prev] | [next] | [standalone]

#1506746

On Sun, Oct 23, 2016 at 12:06 PM, Joe Perches <joe@perches.com> wrote:
> On Sun, 2016-10-23 at 11:11 -0700, Linus Torvalds wrote:
>>
>> And those two per se sound fairly easy to handle ("KERN_CONT means
>> append to the line buffer, otherwise flush the line buffer and move to
>> the record buffer").
>>
>> But what complicates things more is then the "console output", which
>> has two issues:
>>
>>  - it is done outside the locking regime for the line buffer and the
>> record buffer.
>>
>>  - it is done on _partial_ line buffers.
>
> EOL KERN_<LEVEL> and thread interleaving still exists.

Note that the thread interleaving is still trivial: it's easily done
at the point where we decide "can we append to the line buffer or
not". That's pretty simple. Just flush the record when the thread
changes.

So the interleaving will never go away, it's very fundamental - unless
we make the line buffer just be a per-thread thing. And yes, that
would be the cleanest solution, but it's also an extra buffer for each
thread, so realistically it's just not going to happen.

End result: I'm not worried about the interleaving. It will cause ugly
output, but we've always had that, and the solution to it is "if you
absolutely don't want interleaving, then don't try to print partial
lines!".

The classic "don't do that then" response, in other world.

No, the real complexity comes from that interaction with the console
output, which is done outside the core log locks, and which currently
has the added thing where we have a "has this line fragment been
flushed or not".

That "has this line fragment been flushed or not" is particularly
painful, because we may have flushed it *partially*. That "cont.cons"
thing is a counter of how many bytes have been flushed, and we can be
in the situation where we have had multiple continuations added to the
line buffer, and only *some* of them have been flushed to the console.

(Reasons for not flushing: we couldn't get the console lock because
another process held it due to logging or whatever).

And then the interface to the actual record logging only has a "all or
nothing was flushed" flag (LOG_NOCONS) to avoid flushing things twice.
So when we actually log the record, we lose the "this line was only
partially printed".

That whole "we've flushed part of the line to the console" thing is
why it would make things so much easier to just log full records to
the console. Getting rid of that gets rid of a lot of ugly and
hard-to-read crap. Yes, the line buffer would still remain, and yes,
you'd still see the interleaving with threads, but that's not
"complexity", that's just "visually ugly output".

                 Linus

[toc] | [prev] | [next] | [standalone]

#1506748

[Multipart message — attachments visible in raw view] — view raw

On Sun, Oct 23, 2016 at 12:32 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> No, the real complexity comes from that interaction with the console
> output, which is done outside the core log locks, and which currently
> has the added thing where we have a "has this line fragment been
> flushed or not".

Ok, so here's the stupid patch that removes all the partial line flushing.

NOTE! It still leaves all the games with LOG_NEWLINE and LOG_NOCONS
that are pretty much pointless with it. So there's room for more
simplification here.

In particular, the games with LOG_NEWLINE is what Geert's "console and
dmesg output looks different" at least partially comes from. What
happens is that "dmesg" always shows the records as one line (so it
effectively ignores LOG_NEWLINE), but the console output (in
msg_print_text() still has that LOG_NEWLINE logic.

In particular, msg_print_text() looks at the *previous* logged line to
decide whether it should do newlines etc, which is why Geert gets that
odd "two continuations per line" pattern on the console, but "one
continuation per line" in dmesg. That comes from the interaction with
flushing to the console and LOG_NEWLINE and just general complexity.

All of that LOG_NEWLINE code could be removed. But again, this patch
doesn't do that removal. It just removes the partial console flushing
and simplifies that part of the code.

(This patch removes way more lines than it adds, but the *real*
advantage is that it removes complexity. The rules for
console_cont_flush() really were _very_ hard to grok, it has subtle
interactions with cont_add() and cont_flush() through that "cont.cons"
and "cont.flushed" logic that is all removed by this patch).

                Linus

[toc] | [prev] | [next] | [standalone]

#1507101

Hi Linus,

On Sun, Oct 23, 2016 at 9:46 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Sun, Oct 23, 2016 at 12:32 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
>>
>> No, the real complexity comes from that interaction with the console
>> output, which is done outside the core log locks, and which currently
>> has the added thing where we have a "has this line fragment been
>> flushed or not".
>
> Ok, so here's the stupid patch that removes all the partial line flushing.
>
> NOTE! It still leaves all the games with LOG_NEWLINE and LOG_NOCONS
> that are pretty much pointless with it. So there's room for more
> simplification here.
>
> In particular, the games with LOG_NEWLINE is what Geert's "console and
> dmesg output looks different" at least partially comes from. What
> happens is that "dmesg" always shows the records as one line (so it
> effectively ignores LOG_NEWLINE), but the console output (in
> msg_print_text() still has that LOG_NEWLINE logic.
>
> In particular, msg_print_text() looks at the *previous* logged line to
> decide whether it should do newlines etc, which is why Geert gets that
> odd "two continuations per line" pattern on the console, but "one
> continuation per line" in dmesg. That comes from the interaction with
> flushing to the console and LOG_NEWLINE and just general complexity.

Thanks, Linux kernel output is again in sync with dmesg output.

Tested-by: Geert Uytterhoeven <geert@linux-m68k.org>

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

[toc] | [prev] | [next] | [standalone]

#1507235

Hello,

thanks for Cc-ing.

On (10/23/16 12:46), Linus Torvalds wrote:
> +static void deferred_cont_flush(void)
> +{
> +	static DEFINE_TIMER(timer, flush_timer, 0, 0);
> +
> +	if (!cont.len)
>  		return;
> +	mod_timer(&timer, jiffies + HZ/10);
>  }

[..]

> @@ -2360,6 +2285,8 @@ void console_unlock(void)
>  		return;
>  	}
>  
> +	deferred_cont_flush();
> +

is mod_timer() safe enough to rely on/call from
	panic()->console_flush_on_panic()->console_unlock() ?

shouldn't deferred_cont_flush() be called every time we jump
to `again' label in console_unlock()?

timer has debug object support, which probably can printk(), but
that shouldn't cause any troubles, I suppose.

	-ss

[toc] | [prev] | [next] | [standalone]

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web