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

Groups > linux.kernel > #1506653 > unrolled thread

Re: linux.git: printk() problem

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  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 →

#1506653 — Re: linux.git: printk() problem

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] | [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]

#1507241

> 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();
> > +
> 

[    0.000000] BUG: spinlock bad magic on CPU#0, swapper/0
[    0.000000]  lock: __init_begin+0x1cebc0/0x1da000, .magic: 00000000, .owner: swapper/0, .owner_cpu: 0
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted 4.9.0-rc1-next-20161024-dbg-dirty #150
[    0.000000]  ffffffff81803c18 ffffffff81221216 ffffffff8180a540 ffffffff81ac7bc0
[    0.000000]  ffffffff81803c38 ffffffff81081414 ffffffff81ac7bc0 0000000000000046
[    0.000000]  ffffffff81803c58 ffffffff81081444 ffffffff81ac7bc0 ffffffff81737e85
[    0.000000] Call Trace:
[    0.000000]  [<ffffffff81221216>] dump_stack+0x4f/0x65
[    0.000000]  [<ffffffff81081414>] spin_dump+0x8a/0x8f
[    0.000000]  [<ffffffff81081444>] spin_bug+0x2b/0x2d
[    0.000000]  [<ffffffff81081604>] do_raw_spin_unlock+0x22/0x81
[    0.000000]  [<ffffffff814b145a>] _raw_spin_unlock_irqrestore+0x2c/0x4e
[    0.000000]  [<ffffffff81097974>] mod_timer+0x266/0x2a0
[    0.000000]  [<ffffffff81084f14>] deferred_cont_flush+0x2a/0x2c
[    0.000000]  [<ffffffff81086092>] console_unlock+0x28/0x45c
[    0.000000]  [<ffffffff8108686c>] ? vprintk_emit+0x3a6/0x3c5
[    0.000000]  [<ffffffff81086875>] vprintk_emit+0x3af/0x3c5
[    0.000000]  [<ffffffff810869f7>] vprintk_default+0x1d/0x1f
[    0.000000]  [<ffffffff810ecb95>] printk+0x48/0x50
[    0.000000]  [<ffffffff810869f7>] ? vprintk_default+0x1d/0x1f
[    0.000000]  [<ffffffff81adb082>] e820_print_map+0x4a/0x70
[    0.000000]  [<ffffffff81000000>] ? 0xffffffff81000000
[    0.000000]  [<ffffffff81adbbc4>] setup_memory_map+0x37/0x3a
[    0.000000]  [<ffffffff81ad9264>] setup_arch+0x16d/0x890
[    0.000000]  [<ffffffff81ad3b9c>] start_kernel+0x59/0x40c
[    0.000000]  [<ffffffff81ad328e>] x86_64_start_reservations+0x2a/0x2c
[    0.000000]  [<ffffffff81ad340a>] x86_64_start_kernel+0x17a/0x18d
[    0.000000]  [<ffffffff810001a5>] start_cpu+0x5/0x14
[    0.000000]  [<ffffffff810001a5>] ? start_cpu+0x5/0x14
[    0.000000] usable

	-ss

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

#1507500

On Mon, Oct 24, 2016 at 7:08 AM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
>
> is mod_timer() safe enough to rely on/call from
>         panic()->console_flush_on_panic()->console_unlock() ?

I don't think that's a big issue: the whole "panic()" siotuation is
very much about best effort.

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

actually, I think we should just do it at the end.

And your "spinlock bad magic" reports says to me that we should
actually delay it even more, and just do it in klogd, to avoid the
whole issue with "printk() is used very _very_ early during boot".

Because if klogd isn't even running yet, then we clearly don't care
about timely flushing to the logs.

So here's a new version - TOTALLY UNTESTED! - that removes even more
redundant code (all the "test previous record flags" crud - it is not
sensible to think that the previous record was what a continuation was
all about, since the whole reason the continuation didn't get merged
was that something else happened in between).

Note the "totally untested" part. It compiles for me. But it may do
unspeakably stupid things. Caveat applior.

             Linus

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

#1507504

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

On Mon, Oct 24, 2016 at 10:54 AM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> Note the "totally untested" part. It compiles for me. But it may do
> unspeakably stupid things. Caveat applior.

Well, it is hard to apply a patch that I didn't even attach. Blush.

               Linus

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

#1507920

Hello,

Cc more people

report: https://marc.info/?l=linux-kernel&m=147721454506634&w=2

patch: https://marc.info/?l=linux-kernel&m=147733173800859


FB is using ext header a lot (afaik), so may be Tejun or Calvin
will also be interested.

On (10/24/16 10:55), Linus Torvalds wrote:
> > Note the "totally untested" part. It compiles for me. But it may do
> > unspeakably stupid things. Caveat applior.
> 
> Well, it is hard to apply a patch that I didn't even attach. Blush.

[..]

> -static void cont_flush(void)
> +static bool cont_flush(void)
>  {
> -	if (cont.flushed)
> -		return;
> -	if (cont.len == 0)
> +	if (!cont.len)
> +		return false;
> +
> +	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
> +		  NULL, 0, cont.buf, cont.len);
> +	cont.len = 0;
> +	return true;
> +}


I think cont_flush() should grab the logbuf_lock lock, because
it does log_store() and touches the cont.len. so something like
this perhaps

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c7f490f..47f887c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1608,13 +1608,20 @@ static struct cont {
 
 static bool cont_flush(void)
 {
+       unsigned long flags;
+       bool flushed = false;
+
+       raw_spin_lock_irqsave(&logbuf_lock, flags);
        if (!cont.len)
-               return false;
+               goto out;
 
        log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
                  NULL, 0, cont.buf, cont.len);
        cont.len = 0;
-       return true;
+       flushed = true;
+out:
+       raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+       return flushed;
 }


[..]
> @@ -2449,7 +2311,6 @@ void console_unlock(void)
>  		}
>  		console_idx = log_next(console_idx);
>  		console_seq++;
> -		console_prev = msg->flags;
>  		raw_spin_unlock(&logbuf_lock);
>  
>  		stop_critical_timings();	/* don't trace print latency */
> @@ -2483,7 +2344,7 @@ void console_unlock(void)
>  	if (retry && console_trylock())
>  		goto again;
>  
> -	if (wake_klogd)
> +	if (wake_klogd || cont.len)
			^^^^^^^^^^
this _technically_ can result in additional spurious wakeups - cont.len
check is done outside of console_sem && logbuf_lock - but I don't think
this is a huge problem.

	-ss

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

#1507922

On Mon, Oct 24, 2016 at 6:55 PM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
>
> I think cont_flush() should grab the logbuf_lock lock, because
> it does log_store() and touches the cont.len. so something like
> this perhaps

Absolutely. Good catch.

>> -     if (wake_klogd)
>> +     if (wake_klogd || cont.len)
>                         ^^^^^^^^^^
> this _technically_ can result in additional spurious wakeups - cont.len
> check is done outside of console_sem && logbuf_lock - but I don't think
> this is a huge problem.

Yes. We could easily just do it inside the spinlock and make it part
of the wake_klogd logic, but as you say, it doesn't actually matter.

And yes, it would be lovely if people who use the network console
(which I think is the only user of the whole extended console thing)
would test this too.

It really makes things potentially much simpler. It's not just that it
removes 150 lines, it's 150 lines of  really nasty complex special
case crud.

I'm obviously not going to apply it for 4.9, but it might be "do it
for 4.10 and mark it for stable if nobody notices any issues", because
apart from the code simplification it also gets more cases "right".
Right now the console flushing often means that we end up not merging
continuation lines as much as we could.

           Linus

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

#1507928

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

On Mon, Oct 24, 2016 at 7:06 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Mon, Oct 24, 2016 at 6:55 PM, Sergey Senozhatsky
> <sergey.senozhatsky.work@gmail.com> wrote:
>>
>> I think cont_flush() should grab the logbuf_lock lock, because
>> it does log_store() and touches the cont.len. so something like
>> this perhaps
>
> Absolutely. Good catch.

Actually, you can't do it the way you did (inside cont_flush), because
"cont_flush()" is already called with logbuf_lock held in most cases
(see "cont_add()").

So it's really just the timer function that needs to take the
logbuf_lock before it calls cont_flush().

So here's a new version. How does this look to you?

Again, this still tests "cont.len" outside the lock (not just in
console_unlock(), but also in deferred_cont_flush()). And it's fine:
even if it sees the "wrong" value due to some race, it does so either
because cont.len was just set to non-zero (and whoever set it will
force the re-check anyway), or it got cleared just as it was tested
(and at worst you end up with an extra timer invocation).

              Linus

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

#1507959

On (10/24/16 19:22), Linus Torvalds wrote:
> On Mon, Oct 24, 2016 at 7:06 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> > On Mon, Oct 24, 2016 at 6:55 PM, Sergey Senozhatsky
> > <sergey.senozhatsky.work@gmail.com> wrote:
> >>
> >> I think cont_flush() should grab the logbuf_lock lock, because
> >> it does log_store() and touches the cont.len. so something like
> >> this perhaps
> >
> > Absolutely. Good catch.
> 
> Actually, you can't do it the way you did (inside cont_flush), because
> "cont_flush()" is already called with logbuf_lock held in most cases
> (see "cont_add()").

right. my bad, realized too late.

> So it's really just the timer function that needs to take the
> logbuf_lock before it calls cont_flush().

yes.

> So here's a new version. How does this look to you?

ok, looks much better.

there are several things that I want to mention here, just to make
sure we don't miss anything (just my 5 cents).

1) the way we dumpstack on x86 (at least on x86) is a spaghetti of
printk() and pr_cont() calls. for instance, arch/x86/kernel/dumpstack_64.c
show_regs() does pr_cont() to print out the registers, while the stack and
backtrace are printed with printk(). so, I assume, the backtrace now will
look a bit upside-down, because cont lines are printed with the delay.
correct?

2) flush on oops. not that panic printk is deadlock proof (not at all)
   but:
     a) rather unlikely, but what if BUG_ON() or panic() happens
      under lock_timer_base()?
     b) what if timer event never happens? (we are in panic, who knows)

  so how about skipping mod_timer in deferred_cont_flush() and just
  cont_flush() when we are in oops? here is probably one more thing we
  need to "fix" first. oops_in_progress is unreliable. x86 oops_end()
  does bust_spinlocks(0) before it calls panic(). panic() increments
  oops_in_progress but decrements it back to 0 (bust_spinlocks(0)) before
  it does console_flush_on_panic(). so there is (almost) no way
  console_flush_on_panic() can see oops_in_progress != 0.


diff --git a/kernel/panic.c b/kernel/panic.c
index e6480e2..8e17540 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -228,7 +228,6 @@ void panic(const char *fmt, ...)
        if (_crash_kexec_post_notifiers)
                __crash_kexec(NULL);
 
-       bust_spinlocks(0);
 
        /*
         * We may have ended up stopping the CPU holding the lock (in
@@ -240,6 +239,7 @@ void panic(const char *fmt, ...)
         */
        debug_locks_off();
        console_flush_on_panic();
+       bust_spinlocks(0);
 
        if (!panic_blink)
                panic_blink = no_blink;
---

	-ss

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

#1507961

On Tue, 2016-10-25 at 13:06 +0900, Sergey Senozhatsky wrote:
>   so how about skipping mod_timer in deferred_cont_flush() and just
>   cont_flush() when we are in oops? here is probably one more thing we
>   need to "fix" first. oops_in_progress is unreliable. x86 oops_end()
>   does bust_spinlocks(0) before it calls panic(). panic() increments
>   oops_in_progress but decrements it back to 0 (bust_spinlocks(0)) before
>   it does console_flush_on_panic(). so there is (almost) no way
>   console_flush_on_panic() can see oops_in_progress != 0.

I think Linus' insistence on not requiring EOL/newline is misguided.
It'd be simpler to avoid the flushes and have a require EOL/newline.

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

#1507964

On Mon, Oct 24, 2016 at 9:06 PM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
>
> 1) the way we dumpstack on x86 (at least on x86) is a spaghetti of
> printk() and pr_cont() calls. for instance, arch/x86/kernel/dumpstack_64.c
> show_regs() does pr_cont() to print out the registers, while the stack and
> backtrace are printed with printk(). so, I assume, the backtrace now will
> look a bit upside-down, because cont lines are printed with the delay.
> correct?

No. Most cont lines never hit the delay, because when the line is
completed, it is flushed (and then printed synchronously, assuming it
can get the console lock).

So the timeout only ever comes into effect if the line isn't completed
in time at all. Which is actually very rare, and never happens for the
"let's print things out in multiple chinks because we're using a
loop".

Similarly, if a new printk() happens due to interleaving, the previous
buffered line is always flushed first, so buffering never causes
out-of-order behavior.

Basically, the only time the timer actually does anything is if
something just does a printk() without a newline, and no other
printouts happen for the next 0.1s.

> 2) flush on oops.

Again, really not an issue for the exact reason above: nothing is ever
buffered when something new is printed.

And all you need to guarantee that last line of the oops itself is
printed is that it has a newline.

So again, the timer only matters for the exceptional case, not for the
normal situation. It's literally there to guarantee basic timeliness.

         Linus

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

#1507968

On (10/24/16 21:15), Linus Torvalds wrote:
[..]
> No. Most cont lines never hit the delay, because when the line is
> completed, it is flushed (and then printed synchronously, assuming it
> can get the console lock).
> 
> So the timeout only ever comes into effect if the line isn't completed
> in time at all. Which is actually very rare, and never happens for the
> "let's print things out in multiple chinks because we're using a
> loop".
> 
> Similarly, if a new printk() happens due to interleaving, the previous
> buffered line is always flushed first, so buffering never causes
> out-of-order behavior.

thanks. the patch works fine on my x86 box.

> Basically, the only time the timer actually does anything is if
> something just does a printk() without a newline, and no other
> printouts happen for the next 0.1s.

ok. perhaps, like slow serial console. will test on arm board later.

	-ss

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

#1508338

On Mon 2016-10-24 19:22:59, Linus Torvalds wrote:
> On Mon, Oct 24, 2016 at 7:06 PM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> > On Mon, Oct 24, 2016 at 6:55 PM, Sergey Senozhatsky
> > <sergey.senozhatsky.work@gmail.com> wrote:
> >>
> >> I think cont_flush() should grab the logbuf_lock lock, because
> >> it does log_store() and touches the cont.len. so something like
> >> this perhaps
> >
> > Absolutely. Good catch.
> 
> Actually, you can't do it the way you did (inside cont_flush), because
> "cont_flush()" is already called with logbuf_lock held in most cases
> (see "cont_add()").
> 
> So it's really just the timer function that needs to take the
> logbuf_lock before it calls cont_flush().
> 
> So here's a new version. How does this look to you?
> 
> Again, this still tests "cont.len" outside the lock (not just in
> console_unlock(), but also in deferred_cont_flush()). And it's fine:
> even if it sees the "wrong" value due to some race, it does so either
> because cont.len was just set to non-zero (and whoever set it will
> force the re-check anyway), or it got cleared just as it was tested
> (and at worst you end up with an extra timer invocation).
> 
> +static void flush_timer(unsigned long data)
> +{
> +	unsigned long flags;
> +	bool did_flush;
> +
> +	raw_spin_lock_irqsave(&logbuf_lock, flags);
> +	did_flush = cont_flush();
> +	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +	if (did_flush)
> +		wake_up_klogd();

We wake only klogd and syslog but not console here. Same problem is
also with some other recently added cont_flush() calls, e.g. in
kmsg_dump(), kmsg_dump_get_line().

BTW: It should be safe to call wake_up_klogd() in the locked area.
It just modifies a per-CPU variable and queues IRQ work.

I have played with it a bit and the result is below. Feel free
to just use the pieces or the idea if you like a part of it.


From 226c4bfbe9f81bdd3b91b6b0ff3e268b1c09085f Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Tue, 25 Oct 2016 15:23:13 +0200
Subject: [PATCH] printk: Poke console when cont buffer is flushed

The commit bfd8d3f23b51018388be041 ("printk: make reading the kernel
log flush pending lines") allows to add new message into the log
buffer without flushing it to the console.

This patch reworks wake_up_klogd() to a generic printk_poke().
It pokes the loggers or console or both where necessary.

I have renamed some some variables and functions. I am not
if it is better readable now. Anyway, the old names came
from times before printk_deferred() when the irq work
handled only klogd.

I am not super happy the new state because the irq work is
called from many locations and there are cycles.
The cycle breaks when cont.len is zero but it might
be worth some clean up. For example, deferred_cont_flush()
call in printk_poke_func() looks superfluous. But
I wanted to be rather conservative for the moment.

Also I wonder if we really need per-CPU variable for
the printk_pending/printk_need_poke flag. A global
variable might help to reduce some calls and it would
not complicate the code.

This patch is based on top of the fix proposed at
https://lkml.kernel.org/r/CA+55aFwKYnrMJr_vSE+GfDGszeUGyd=CPUD15-zZ8yWQW61GBA@mail.gmail.com

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 include/linux/printk.h |  7 ++++--
 kernel/printk/printk.c | 67 ++++++++++++++++++++++++++++----------------------
 lib/bust_spinlocks.c   |  2 +-
 3 files changed, 44 insertions(+), 32 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index eac1af8502bb..6fdced13d2c9 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -31,6 +31,9 @@ static inline const char *printk_skip_level(const char *buffer)
 	return buffer;
 }
 
+#define PRINTK_POKE_CONSOLE	0x01
+#define PRINTK_POKE_LOGGERS	0x02
+
 #define CONSOLE_EXT_LOG_MAX	8192
 
 /* printk's without a loglevel use this.. */
@@ -185,7 +188,7 @@ extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write, void __user *buf,
 			  size_t *lenp, loff_t *ppos);
 
-extern void wake_up_klogd(void);
+extern void printk_poke(int poke);
 
 char *log_buf_addr_get(void);
 u32 log_buf_len_get(void);
@@ -220,7 +223,7 @@ static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 	return false;
 }
 
-static inline void wake_up_klogd(void)
+static inline void printk_poke(int poke)
 {
 }
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e63aa679614e..2c231bb73744 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1620,13 +1620,11 @@ static bool cont_flush(void)
 static void flush_timer(unsigned long data)
 {
 	unsigned long flags;
-	bool did_flush;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	did_flush = cont_flush();
+	if (cont_flush())
+		printk_poke(PRINTK_POKE_CONSOLE | PRINTK_POKE_LOGGERS);
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
-	if (did_flush)
-		wake_up_klogd();
 }
 
 static void deferred_cont_flush(void)
@@ -2233,7 +2231,7 @@ void console_unlock(void)
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
 	static u64 seen_seq;
 	unsigned long flags;
-	bool wake_klogd = false;
+	bool poke_loggers = false;
 	bool do_cond_resched, retry;
 
 	if (console_suspended) {
@@ -2274,7 +2272,7 @@ void console_unlock(void)
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
-			wake_klogd = true;
+			poke_loggers = true;
 			seen_seq = log_next_seq;
 		}
 
@@ -2350,8 +2348,8 @@ void console_unlock(void)
 	if (retry && console_trylock())
 		goto again;
 
-	if (wake_klogd || cont.len)
-		wake_up_klogd();
+	if (poke_loggers || cont.len)
+		printk_poke(PRINTK_POKE_LOGGERS);
 }
 EXPORT_SYMBOL(console_unlock);
 
@@ -2730,40 +2728,45 @@ static int __init printk_late_init(void)
 
 #if defined CONFIG_PRINTK
 /*
- * Delayed printk version, for scheduler-internal messages:
+ * Poke console and loggers via IRQ work so that it can be done
+ * from any context.
  */
-#define PRINTK_PENDING_WAKEUP	0x01
-#define PRINTK_PENDING_OUTPUT	0x02
-
-static DEFINE_PER_CPU(int, printk_pending);
+static DEFINE_PER_CPU(int, printk_need_poke);
 
-static void wake_up_klogd_work_func(struct irq_work *irq_work)
+static void printk_poke_func(struct irq_work *irq_work)
 {
-	int pending = __this_cpu_xchg(printk_pending, 0);
+	int poke = __this_cpu_xchg(printk_need_poke, 0);
 
-	if (pending & PRINTK_PENDING_OUTPUT) {
+	if (poke & PRINTK_POKE_CONSOLE) {
 		/* If trylock fails, someone else is doing the printing */
 		if (console_trylock())
 			console_unlock();
 	}
 
-	if (pending & PRINTK_PENDING_WAKEUP)
+	if (poke & PRINTK_POKE_LOGGERS)
 		wake_up_interruptible(&log_wait);
+
 	deferred_cont_flush();
 }
 
-static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
-	.func = wake_up_klogd_work_func,
+static DEFINE_PER_CPU(struct irq_work, printk_poke_work) = {
+	.func = printk_poke_func,
 	.flags = IRQ_WORK_LAZY,
 };
 
-void wake_up_klogd(void)
+void printk_poke(int poke)
 {
 	preempt_disable();
-	if (waitqueue_active(&log_wait)) {
-		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
-		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
-	}
+
+	if (poke & PRINTK_POKE_CONSOLE)
+		this_cpu_or(printk_need_poke, PRINTK_POKE_CONSOLE);
+
+	if ((poke & PRINTK_POKE_LOGGERS) && waitqueue_active(&log_wait))
+		this_cpu_or(printk_need_poke, PRINTK_POKE_LOGGERS);
+
+	if (this_cpu_read(printk_need_poke))
+		irq_work_queue(this_cpu_ptr(&printk_poke_work));
+
 	preempt_enable();
 }
 
@@ -2777,8 +2780,7 @@ int printk_deferred(const char *fmt, ...)
 	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
 	va_end(args);
 
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
-	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+	printk_poke(PRINTK_POKE_CONSOLE);
 	preempt_enable();
 
 	return r;
@@ -2893,6 +2895,7 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 {
 	struct kmsg_dumper *dumper;
 	unsigned long flags;
+	int did_flush = 0;
 
 	if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump)
 		return;
@@ -2906,7 +2909,7 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 		dumper->active = true;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
-		cont_flush();
+		did_flush |= cont_flush();
 		dumper->cur_seq = clear_seq;
 		dumper->cur_idx = clear_idx;
 		dumper->next_seq = log_next_seq;
@@ -2920,6 +2923,9 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 		dumper->active = false;
 	}
 	rcu_read_unlock();
+
+	if (did_flush)
+		printk_poke(PRINTK_POKE_CONSOLE);
 }
 
 /**
@@ -2997,7 +3003,8 @@ bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
 	bool ret;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	cont_flush();
+	if (cont_flush())
+		printk_poke(PRINTK_POKE_CONSOLE);
 	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 
@@ -3039,7 +3046,9 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 		goto out;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	cont_flush();
+	if (cont_flush())
+		printk_poke(PRINTK_POKE_CONSOLE);
+
 	if (dumper->cur_seq < log_first_seq) {
 		/* messages are gone, move to first available one */
 		dumper->cur_seq = log_first_seq;
diff --git a/lib/bust_spinlocks.c b/lib/bust_spinlocks.c
index f8e0e5367398..2bd31977058f 100644
--- a/lib/bust_spinlocks.c
+++ b/lib/bust_spinlocks.c
@@ -26,6 +26,6 @@ void __attribute__((weak)) bust_spinlocks(int yes)
 #endif
 		console_unblank();
 		if (--oops_in_progress == 0)
-			wake_up_klogd();
+			printk_poke(PRINTK_POKE_LOGGERS);
 	}
 }
-- 
1.8.5.6

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

#1507925

On (10/25/16 10:55), Sergey Senozhatsky wrote:
> I think cont_flush() should grab the logbuf_lock lock, because
> it does log_store() and touches the cont.len. so something like
> this perhaps
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index c7f490f..47f887c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1608,13 +1608,20 @@ static struct cont {
>  
>  static bool cont_flush(void)
>  {
> +       unsigned long flags;
> +       bool flushed = false;
> +
> +       raw_spin_lock_irqsave(&logbuf_lock, flags);
>         if (!cont.len)
> -               return false;
> +               goto out;
>  
>         log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
>                   NULL, 0, cont.buf, cont.len);
>         cont.len = 0;
> -       return true;
> +       flushed = true;
> +out:
> +       raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +       return flushed;
>  }


... clearly, wasn't tested at all! sorry about that.
what I meant was cont_flush() from deferred_cont_flush()->flush_timer().


diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c7f490f..bd7841c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1619,7 +1619,14 @@ static bool cont_flush(void)
 
 static void flush_timer(unsigned long data)
 {
-	if (cont_flush())
+	unsigned long flags;
+	bool flushed;
+
+	raw_spin_lock_irqsave(&logbuf_lock, flags);
+	flushed = cont_flush();
+	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+
+	if (flushed)
 		wake_up_klogd();
 }

 	-ss

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

#1506757

On Sun, 2016-10-23 at 12:32 -0700, Linus Torvalds wrote:
> 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.

I doubt there are cases where more than a few of
these interleaving threads are simultaneous.

Perhaps it could be a pool of active thread
continuation buffers.  

> 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.

Yup, best solution.

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

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web