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

Groups > linux.kernel > #1611720 > unrolled thread

[RFC][PATCHv2 0/8] printk: introduce printing kernel thread

Back to article view | Back to linux.kernel

Contents

  [RFC][PATCHv2 0/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
    [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
      Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Petr Mladek <pmladek@suse.com> - 2017-04-04 11:10 +0200
        Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-04 11:40 +0200
      Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:20 +0200
        Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 07:20 +0200
          Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-07 09:30 +0200
            Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 10:20 +0200
              Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-07 14:10 +0200
    [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
      Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in  unsafe places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:40 +0200
        Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in  unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-01 02:10 +0200
    [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Petr Mladek <pmladek@suse.com> - 2017-03-31 15:20 +0200
        Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Peter Zijlstra <peterz@infradead.org> - 2017-03-31 15:40 +0200
          Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-03 13:30 +0200
            Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Petr Mladek <pmladek@suse.com> - 2017-04-03 14:50 +0200
    [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in  unsafe places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:40 +0200
    [RFC][PATCHv2 8/8] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-03-31 04:40 +0200
        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-03-31 06:10 +0200
          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Ye Xiaolong <xiaolong.ye@intel.com> - 2017-03-31 08:50 +0200
            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-31 16:50 +0200
              Re: [printk]  fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage ebiederm@xmission.com (Eric W. Biederman) - 2017-03-31 17:40 +0200
                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Jan Kara <jack@suse.cz> - 2017-04-03 11:40 +0200
                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-03 12:10 +0200
                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:40 +0200
                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 06:50 +0200
                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 09:20 +0200
                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 09:50 +0200
                          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 10:20 +0200
                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 14:20 +0200
                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 14:50 +0200
                                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Steven Rostedt <rostedt@goodmis.org> - 2017-04-07 16:50 +0200
                                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-07 17:20 +0200
                                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Peter Zijlstra <peterz@infradead.org> - 2017-04-07 17:30 +0200
                                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-07 17:50 +0200
                                      Re: [printk]  fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage ebiederm@xmission.com (Eric W. Biederman) - 2017-04-09 20:30 +0200
                                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-10 06:50 +0200
                                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-09 12:20 +0200
                                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-10 07:00 +0200
                                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-10 14:00 +0200
                                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-10 17:10 +0200
                                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-10 20:50 +0200
                                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-11 03:50 +0200
                                          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-11 18:30 +0200
                                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-12 20:50 +0200
                                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-13 06:40 +0200
                                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-13 08:00 +0200
                                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-13 10:30 +0200
                                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-13 16:10 +0200
                                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-14 06:50 +0200
                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Steven Rostedt <rostedt@goodmis.org> - 2017-04-07 16:40 +0200
                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-09 12:00 +0200
                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-03 13:00 +0200
            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Ye Xiaolong <xiaolong.ye@intel.com> - 2017-04-05 09:40 +0200
              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-05 10:50 +0200
      Re: [RFC][PATCHv2 8/8] printk: enable printk offloading Petr Mladek <pmladek@suse.com> - 2017-04-03 17:50 +0200
        Re: [RFC][PATCHv2 8/8] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-04 14:30 +0200
    [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:10 +0200
      Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:30 +0200
        Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Andreas Mohr <andi@lisas.de> - 2017-04-09 13:00 +0200
          Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Petr Mladek <pmladek@suse.com> - 2017-04-10 14:30 +0200
            Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-10 16:40 +0200
    [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Petr Mladek <pmladek@suse.com> - 2017-04-03 17:30 +0200
        Re: [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-04 10:30 +0200

Page 3 of 4 — ← Prev page 1 2 [3] 4  Next page →

#1619469 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

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

On Sat 2017-04-08 00:13:06, Sergey Senozhatsky wrote:
> On (04/07/17 14:44), Pavel Machek wrote:
> [..]
> > > [..]
> > > > I believe "spend at most 2 seconds in printk(), then print a warning
> > > > and offload" is a solution closer to what we had before.
> > > 
> > > a warning here can be very noisy.
> > 
> > Well, on normally-configured it should be ok. We don't commonly see
> > printk problems... If it is too noisy, perhaps we should increase from
> > 2 seconds, but I don't think it will be problem.
> 
> we are looking at different typical setups :) serial console being 45
> seconds behind logbuf does not surprise me anymore.
> 
> [..]
> > > what we have been thinking about is something like printk-stall detection.
> > > we probably (there are some if-s) can detect in printk() that offloading
> > > does not work and we must automatically switch to printk_emergency mode.
> > > that, in theory, can relax our dependency on printk_emergency_begin/end
> > > being in the right place at the right time. need to think more about it.
> > 
> > So... I don't really like the begin/end interface. I would rather have
> > printk_emergency(KERN_ ...).
> 
> you mean a single printk_emergency() switches printk to emergency mode
> or printk_emergency(KERN_ ... ) is a single message that must be printed
> in emergency mode?

The latter. Having state is ugly.

> printk() depends on console_trylock(). we can't expect printk_emergency(KERN_ ...)
> to always do more than just log_store().
> 
> the idea behind begin/end interface is that you can do
> 
> 	emergency_begin
> 	printk
> 	pr_cont
> 	pr_cont
> 	pr_cont
> 	printk
> 	dump_stack
> 	emergency_end
> 
> with out the need of rewriting dump_stack() or anything else to use
> printk_emergency(). we, for example, do this in sysrq patch from this
> series.

Well.. I guess it is less work to include emergency_begin/end() but I
also believe result will state-less solution will be cleaner.

> > Second... I don't think "stuck detector" is that helpful. What I
> > usually seen was some rather innocent kernel message followed by
> > hard-lock. That's where "message delayed" is useful..
> 
> a side note,
> that's rather unclear to me how would "message delayed" really help.
> if your system hard-lockup so badly and there are no printk messages
> even from NMI watchdog, then we won't be able to print that message.

We are talking about

   printk("unusual condition");
   do_something_clever(); /* Which unfortunately hard-crashes the machine */

that works with my proposal, but not with yours. Seen it happen many
times before.

									Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

#1619632 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/09/17 12:12), Pavel Machek wrote:
[..]
> > a side note,
> > that's rather unclear to me how would "message delayed" really help.
> > if your system hard-lockup so badly and there are no printk messages
> > even from NMI watchdog, then we won't be able to print that message.
> 
> We are talking about
> 
>    printk("unusual condition");
>    do_something_clever(); /* Which unfortunately hard-crashes the machine */
> 
> that works with my proposal, but not with yours. Seen it happen many
> times before.

I see your point, sure.
I can't completely agree on "that works with my proposal, but not with yours."

on SMP system this would be true only if no other CPU holds the console_sem
at the time we call printk(). (skipping irrelevant cases when we have suspended
console or !online CPU and !CON_ANYTIME console). and there is nothing that
makes "no other CPU holds the console_sem" always true on SMP system at any
given point in time. so no, "A always works, B never works" is not accurate.

but, once again, I see your point.

	-ss

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

#1619853 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Mon 2017-04-10 13:53:39, Sergey Senozhatsky wrote:
> On (04/09/17 12:12), Pavel Machek wrote:
> [..]
> > > a side note,
> > > that's rather unclear to me how would "message delayed" really help.
> > > if your system hard-lockup so badly and there are no printk messages
> > > even from NMI watchdog, then we won't be able to print that message.
> > 
> > We are talking about
> > 
> >    printk("unusual condition");
> >    do_something_clever(); /* Which unfortunately hard-crashes the machine */
> > 
> > that works with my proposal, but not with yours. Seen it happen many
> > times before.
> 
> I see your point, sure.
> I can't completely agree on "that works with my proposal, but not with yours."
> 
> on SMP system this would be true only if no other CPU holds the console_sem
> at the time we call printk(). (skipping irrelevant cases when we have suspended
> console or !online CPU and !CON_ANYTIME console). and there is nothing that
> makes "no other CPU holds the console_sem" always true on SMP system at any
> given point in time. so no, "A always works, B never works" is not accurate.
> 
> but, once again, I see your point.

A compromise might be to move the offloading from vprintk_emit() to
console_unlock(). By other words, the printk could always try to
flush some messages to the console. The console might trigger
the offload (wakeup kthread) after few lines or when the printing
takes too long.

We could go even furter. We could replace the cond_resched() in
console_unlock() with a need_resched() check. Then we could avoid
sleeping with console_sem taken.

It will avoid the softlockups caused by printk(). It should
work pretty well in most critical situations.

Of course, it will not guarantee that we will see all messages when
there is a flood of messages from many CPUs. But it was never
guaranteed.

Best Regards,
Petr

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

#1620011 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/10/17 13:54), Petr Mladek wrote:
[..]
> > > that works with my proposal, but not with yours. Seen it happen many
> > > times before.
> > 
> > I see your point, sure.
> > I can't completely agree on "that works with my proposal, but not with yours."
> > 
> > on SMP system this would be true only if no other CPU holds the console_sem
> > at the time we call printk(). (skipping irrelevant cases when we have suspended
> > console or !online CPU and !CON_ANYTIME console). and there is nothing that
> > makes "no other CPU holds the console_sem" always true on SMP system at any
> > given point in time. so no, "A always works, B never works" is not accurate.
> > 
> > but, once again, I see your point.
> 
> A compromise might be to move the offloading from vprintk_emit() to
> console_unlock(). By other words, the printk could always try to
> flush some messages to the console. The console might trigger
> the offload (wakeup kthread) after few lines

yep, that's the proposal.


hm, this also should align with one more thing.

we briefly discussed it before, and it was on my list, that
wake_up(printk_kthread) _eventually_ better be moved to console_unlock()
[1] (I also had it in the slides at KS, but I believe we didn't have much
time back then).

vprintk_emit() is not the only console_lock() caller. user space does
console_lock() and console_unlock() calls, and in some cases a user
space process can stuck in system call printing kernel messages to a
potentially slow console [2]. it can be unpleasant, but far less dramatic
than doing console_unlock() from IRQ, or under spin_lock. so it was
moved down the list. seems we have one more reason to reshuffle the
list and do offloading from console_unlock() from the beginning.

will take a look.

/* in our "in-house" kernels we do 'async' console_unlock(). not
exactly the way it's shown in [1], but quite similar. */

[1] https://marc.info/?l=linux-kernel&m=145750373530161
[2] https://marc.info/?l=linux-kernel&m=145762735308470

	-ss

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

#1620617 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

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

On Mon 2017-04-10 13:53:39, Sergey Senozhatsky wrote:
> On (04/09/17 12:12), Pavel Machek wrote:
> [..]
> > > a side note,
> > > that's rather unclear to me how would "message delayed" really help.
> > > if your system hard-lockup so badly and there are no printk messages
> > > even from NMI watchdog, then we won't be able to print that message.
> > 
> > We are talking about
> > 
> >    printk("unusual condition");
> >    do_something_clever(); /* Which unfortunately hard-crashes the machine */
> > 
> > that works with my proposal, but not with yours. Seen it happen many
> > times before.
> 
> I see your point, sure.
> I can't completely agree on "that works with my proposal, but not with yours."
> 
> on SMP system this would be true only if no other CPU holds the console_sem
> at the time we call printk(). (skipping irrelevant cases when we have suspended
> console or !online CPU and !CON_ANYTIME console). and there is nothing that
> makes "no other CPU holds the console_sem" always true on SMP system at any
> given point in time. so no, "A always works, B never works" is not
> accurate.

Ok, you are right. OTOH the common case is console_sem is unlocked (at
least on systems I develop on). 

> but, once again, I see your point.

Good. Does that mean that the next version of patches will work ok in
that case?
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

#1620825 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/10/17 20:48), Pavel Machek wrote:
[..]
> > but, once again, I see your point.
> 
> Good. Does that mean that the next version of patches will work ok in
> that case?

yes.

we also likely will get rid of printk_begin/end in PM code.
but we still need to have printk_emergency hints from the
outside world in the rest of the places (sysrq etc.)    :(

	-ss

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

#1621454 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/11/17 10:46), Sergey Senozhatsky wrote:
> On (04/10/17 20:48), Pavel Machek wrote:
> [..]
> > > but, once again, I see your point.
> > 
> > Good. Does that mean that the next version of patches will work ok in
> > that case?
> 
> yes.

ok... so I'm looking at something like below right now.
not really tested yet.

I put some comments into the code.

it does offloading after X printed lines by the same process.
if we reschedule, then the counter resets. which is probably OK,
we don't really want any process, except for printk_kthread, to
stay in console_unlock() forever. "number of lines printed" is
probably easier to understand (easily converted to the number of
pageup/pagedown you need to press, terminal buffer history size,
etc.) than seconds we spent on printing (which doesn't even
correspond to messages' timestamps in general case).

when the limit of "number of lines printed" is 0, then no
offloading takes place.

it also has some simple mechanism to handle cases when
we try to wake_up() printk_kthread, but it never becomes alive.
it's a bit simple minded, probably.

wake_up is done from printk_safe context, so warnings/printks
from there should do no harm (in fact, we even do pr_crit()
error reporting, when we enforce printk_emergency mode).

I'll do more tests tomorrow, and will take a closer look.
this code is basically just compiles, boots and passes some
trivial tests. quite possible I've missed something important.

once verified, then the next question will be -- do we even
need printk_emergency_begin/end or we can leave without it.

// given that printk_emergency enforcement works properly


but, once again, the code might be stupid and wrong.
and I need some sleep.

---
 include/linux/console.h |   3 +
 kernel/printk/printk.c  | 200 ++++++++++++++++++++++++++++++++++++++++++++++--
 2 files changed, 198 insertions(+), 5 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 5949d1855589..f1a86944072e 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -187,6 +187,9 @@ extern bool console_suspend_enabled;
 extern void suspend_console(void);
 extern void resume_console(void);
 
+extern void printk_emergency_begin(void);
+extern void printk_emergency_end(void);
+
 int mda_console_init(void);
 void prom_con_init(void);
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6cf756dbee39..c0075e8b3a09 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/kthread.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -402,7 +403,8 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 	} while (0)
 
 /*
- * Delayed printk version, for scheduler-internal messages:
+ * Used both for deferred printk version (scheduler-internal messages)
+ * and printk_kthread control.
  */
 #define PRINTK_PENDING_WAKEUP	0x01
 #define PRINTK_PENDING_OUTPUT	0x02
@@ -445,6 +447,48 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+static struct task_struct *printk_kthread __read_mostly;
+/*
+ * We can't call into the scheduler (wake_up() printk kthread) during
+ * suspend/kexec/etc. This temporarily switches printk to old behaviour.
+ */
+static atomic_t printk_emergency __read_mostly;
+/*
+ * Disable printk_kthread permanently. Unlike `oops_in_progress'
+ * it doesn't go back to 0.
+ */
+static bool printk_enforce_emergency __read_mostly;
+
+static unsigned int atomic_print_limit = 10000;
+
+module_param_named(atomic_print_limit, atomic_print_limit, uint, 0644);
+MODULE_PARM_DESC(atomic_print_limit,
+		 "max lines to print before offloading to printk kthread");
+
+static inline bool printk_kthread_enabled(void)
+{
+	return !printk_enforce_emergency &&
+		printk_kthread && atomic_read(&printk_emergency) == 0;
+}
+
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does not stop the printk_kthread if it's already
+ * printing logbuf messages.
+ */
+void printk_emergency_begin(void)
+{
+	atomic_inc(&printk_emergency);
+}
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+	atomic_dec(&printk_emergency);
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1765,6 +1809,15 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
+	/*
+	 * Emergency level indicates that the system is unstable and, thus,
+	 * we better stop relying on wake_up(printk_kthread) and try to do
+	 * a direct printing.
+	 */
+	if (level == LOGLEVEL_EMERG)
+		printk_enforce_emergency = true;
+
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1882,6 +1935,9 @@ static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static bool suppress_message_printing(int level) { return false; }
 
+void printk_emergency_begin(void) {}
+void printk_emergency_end(void) {}
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2141,6 +2197,89 @@ static inline int can_use_console(void)
 	return cpu_online(raw_smp_processor_id()) || have_callable_console();
 }
 
+/*
+ * Under heavy printing load/slow serial console/etc console_unlock() can
+ * stall CPUs, which can result in soft/hard-lockups, lost interrupts, RCU
+ * stalls, etc. Therefore we attempt to print the messages to console from
+ * a dedicated printk_kthread, which always runs in schedulable context.
+ *
+ * There are several possible scenarios:
+ *
+ * a) When we got a large number of pending messages to print.
+ * e.g.
+ *    vprintk_emit() or console_lock()
+ *     console_unlock()
+ *      <<massive dump>>
+ *
+ * b) When we printk() a large number of messages.
+ * e.g.
+ *   vprintk_emit()->console_unlock()   <<print 1 message>>
+ *   vprintk_emit()->console_unlock()   <<print 1 message>>
+ *   ...
+ *   vprintk_emit()->console_unlock()   <<print 1 message>>
+ *
+ * In all those cases we can be in atomic context, we need to offload
+ * printing at some point.
+ *
+ * This function must be called from 'printk_safe' context.
+ */
+static inline bool console_offload_printing(void)
+{
+	static struct task_struct *printing_task = NULL;
+	static unsigned long lines_printed = 0;
+
+	if (!atomic_print_limit || !printk_kthread_enabled())
+		return false;
+
+	/* We rescheduled - reset the counters. */
+	if (printing_task != current) {
+		lines_printed = 0;
+		printing_task = current;
+		return false;
+	}
+
+	if (current == printk_kthread)
+		return false;
+
+	/*
+	 * Don't reset the counter, let CPU overrun the limit.
+	 * The idea is that
+	 *
+	 *   a) woken up printk_kthread (if succeeded)
+	 * or
+	 *   b) concurrent printk from another CPU (if any)
+	 *
+	 * will change `printing_task' and reset the counter. This also
+	 * let us to introduce additional policies later, for instance,
+	 * if we can't wakeup printk_kthread for Y times, e.g.
+	 *
+	 *            lines_printed > 2 * atomic_print_limit
+	 *
+	 * then we can declare emergency and stop relying on printk_kthread.
+	 *
+	 * If neither a) nor b) happens - we continue printing from
+	 * current process. Which is bad and can be risky, but we can't
+	 * wake_up() printk_kthread, so things already don't look normal.
+	 */
+	lines_printed++;
+	if (lines_printed < atomic_print_limit)
+		return false;
+
+	/*
+	 * A trivial emergency enforcement.
+	 * Assumes that `atomic_print_limit' is large enough.
+	 */
+	if (lines_printed > 2 * (unsigned long)atomic_print_limit) {
+		printk_enforce_emergency = true;
+		pr_crit("Declaring printk emergency mode.\n");
+		return false;
+	}
+
+	/* Must be executed in 'printk_safe' context. */
+	wake_up_process(printk_kthread);
+	return true;
+}
+
 /**
  * console_unlock - unlock the console system
  *
@@ -2163,8 +2302,17 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool do_cond_resched, retry;
+	bool did_offload;
 
 	if (console_suspended) {
+		/*
+		 * Here and later, we need to clear the PENDING_OUTPUT bit
+		 * in order to avoid an infinite loop in printk_kthread
+		 * function when console_unlock() cannot flush messages
+		 * because we suspended consoles. Someone else will print
+		 * the messages from resume_console().
+		 */
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		up_console_sem();
 		return;
 	}
@@ -2186,6 +2334,7 @@ void console_unlock(void)
 	do_cond_resched = console_may_schedule;
 again:
 	console_may_schedule = 0;
+	did_offload = 0;
 
 	/*
 	 * We released the console_sem lock, so we need to recheck if
@@ -2193,6 +2342,7 @@ void console_unlock(void)
 	 * console.
 	 */
 	if (!can_use_console()) {
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		console_locked = 0;
 		up_console_sem();
 		return;
@@ -2221,7 +2371,7 @@ void console_unlock(void)
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (did_offload || console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
@@ -2253,9 +2403,28 @@ void console_unlock(void)
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(ext_text, ext_len, text, len);
 		start_critical_timings();
+
+		/*
+		 * Sometimes we may lock console_sem before printk_kthread.
+		 * In this case we will jump to `again' label (if there are
+		 * pending messages), print one more line from current
+		 * process, break out of printing loop (we don't reset the
+		 * counter of printed lines) and do up_console_sem() to
+		 * wakeup printk_kthread again.
+		 *
+		 * If printk_kthread never wakes up (which may indicate that
+		 * the system is unstable or something weird is going on),
+		 * then we will keep jumping to `again' label and printing
+		 * one message from the logbuf. This is a bit ugly, but at
+		 * least we will print out the logbuf.
+		 *
+		 * If such condition occurs, console_offload_printing() can
+		 * declare `printk_emergency' at some point.
+		 */
+		did_offload = console_offload_printing();
 		printk_safe_exit_irqrestore(flags);
 
-		if (do_cond_resched)
+		if (!did_offload && do_cond_resched)
 			cond_resched();
 	}
 	console_locked = 0;
@@ -2276,6 +2445,8 @@ void console_unlock(void)
 	 */
 	raw_spin_lock(&logbuf_lock);
 	retry = console_seq != log_next_seq;
+	if (!retry)
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	raw_spin_unlock(&logbuf_lock);
 	printk_safe_exit_irqrestore(flags);
 
@@ -2669,8 +2840,11 @@ late_initcall(printk_late_init);
 #if defined CONFIG_PRINTK
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
-	if (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
-		/* If trylock fails, someone else is doing the printing */
+	if (test_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
+		/*
+		 * If trylock fails, someone else is doing the printing.
+		 * PRINTK_PENDING_OUTPUT bit is cleared by console_unlock().
+		 */
 		if (console_trylock())
 			console_unlock();
 	}
@@ -2684,6 +2858,22 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_kthread_func(void *data)
+{
+	while (1) {
+		set_current_state(TASK_INTERRUPTIBLE);
+		if (!test_bit(PRINTK_PENDING_OUTPUT, &printk_pending))
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		console_lock();
+		console_unlock();
+	}
+
+	return 0;
+}
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.12.2

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

#1622479 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

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

On Wed 2017-04-12 01:19:53, Sergey Senozhatsky wrote:
> On (04/11/17 10:46), Sergey Senozhatsky wrote:
> > On (04/10/17 20:48), Pavel Machek wrote:
> > [..]
> > > > but, once again, I see your point.
> > > 
> > > Good. Does that mean that the next version of patches will work ok in
> > > that case?
> > 
> > yes.
> 
> ok... so I'm looking at something like below right now.
> not really tested yet.
> 
> I put some comments into the code.
> 
> it does offloading after X printed lines by the same process.
> if we reschedule, then the counter resets. which is probably OK,
> we don't really want any process, except for printk_kthread, to
> stay in console_unlock() forever. "number of lines printed" is
> probably easier to understand (easily converted to the number of
> pageup/pagedown you need to press, terminal buffer history size,
> etc.) than seconds we spent on printing (which doesn't even
> correspond to messages' timestamps in general case).

Design looks good to me... certainly better than previous version :-).
								

> when the limit of "number of lines printed" is 0, then no
> offloading takes place.

And with "number of lines printed" set to 999999, it will get us
previous behaviour, right? 

Thanks,
								Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

#1622711 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/12/17 20:43), Pavel Machek wrote:
[..]
> > when the limit of "number of lines printed" is 0, then no
> > offloading takes place.
> 
> And with "number of lines printed" set to 999999, it will get us
> previous behaviour, right? 

`atomic_print_limit' set to zero disables offloading explicitly.
at the same time, an unreasonably high `atomic_print_limit' value
makes offloading less possible and starting from some value,
basically, disables it implicitly.

	-ss

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

#1622730 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/12/17 01:19), Sergey Senozhatsky wrote:
[..]
> it does offloading after X printed lines by the same process.
> if we reschedule, then the counter resets. which is probably OK,
> we don't really want any process, except for printk_kthread, to
> stay in console_unlock() forever.

may be this can be changed. we don't want even printk_kthread to keep
console_sem locked for too long, because other process that might want
to lock console_sem have to sleep in TASK_UNINTERRUPTIBLE as long as
printing thread has pending messages to print. so may be the rule can
be "every process prints up to `atomic_print_limit' lines and then
offloads printing - wake_up()s printk_kthread and up()s console_sem".
some other process (printk_kthread or a process from console_sem wait
list, let them compete for console_sem) will eventually down()
console_sem and print the next `atomic_print_limit' lines, while
current process will have a chance to return from console_unlock() and
do something else.

[..]
> the next question will be -- do we even need printk_emergency_begin/end
> or we can leave without it.

what I meant here -- drop sysrq and kexec printk_emergency_begin/end
patches, but keep printk_emergency_begin/end API and do
printk_emergency_begin/end in console_suspend()/resume().
PM already calls console_suspend()/resume(). something like that...

	-ss

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

#1622810 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/13/17 14:50), Sergey Senozhatsky wrote:
[..]
> On (04/12/17 01:19), Sergey Senozhatsky wrote:
> [..]
> > it does offloading after X printed lines by the same process.
> > if we reschedule, then the counter resets. which is probably OK,
> > we don't really want any process, except for printk_kthread, to
> > stay in console_unlock() forever.
> 
> may be this can be changed. we don't want even printk_kthread to keep
> console_sem locked for too long, because other process that might want
> to lock console_sem have to sleep in TASK_UNINTERRUPTIBLE as long as
> printing thread has pending messages to print. so may be the rule can
> be "every process prints up to `atomic_print_limit' lines and then
> offloads printing - wake_up()s printk_kthread and up()s console_sem".
> some other process (printk_kthread or a process from console_sem wait
> list, let them compete for console_sem) will eventually down()
> console_sem and print the next `atomic_print_limit' lines, while
> current process will have a chance to return from console_unlock() and
> do something else.

something like this, perhaps.

static inline bool console_offload_printing(void)
{
	static struct task_struct *printing_task;
	static unsigned long lines_printed;
	static bool did_wakeup;

	if (!atomic_print_limit || !printk_kthread_enabled())
		return false;

	/* We rescheduled - reset the counters. */
	if (printing_task != current) {
		did_wakeup = false;
		lines_printed = 0;
		printing_task = current;
		return false;
	}

	/*
	 * Don't reset the counter, let CPU overrun the limit.
	 * The idea is that
	 *
	 *   a) woken up printk_kthread (if succeeded)
	 * or
	 *   b) concurrent printk from another CPU (if any)
	 *
	 * will change `printing_task' and reset the counter.
	 * If neither a) nor b) happens - we continue printing from
	 * current process. Which is bad and can be risky, but we can't
	 * wake_up() printk_kthread, so things already don't look normal.
	 */
	lines_printed++;
	if (lines_printed < atomic_print_limit)
		return false;

	if (current == printk_kthread) {
		/*
		 * Reset the counter, just in case if printk_kthread is the
		 * only process left that would down() console_sem.
		 */
		lines_printed = 0;
		return true;
	}

	/*
	 * A trivial emergency enforcement - give up on printk_kthread if
	 * we can't wake it up. This assumes that `atomic_print_limit' is
	 * large enough.
	 */
	if (lines_printed > 2 * (unsigned long long)atomic_print_limit) {
		printk_enforce_emergency = true;
		pr_crit("Declaring printk emergency mode.\n");
		return false;
	}

	/*
	 * Must be executed in 'printk_safe' context. Call into the
	 * scheduler just once, in case if it backfires on us with
	 * warnings and backtraces.
	 */
	if (!did_wakeup) {
		did_wakeup = true;
		wake_up_process(printk_kthread);
	}
	return true;
}

	-ss

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

#1623058 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Wed 2017-04-12 01:19:53, Sergey Senozhatsky wrote:
> On (04/11/17 10:46), Sergey Senozhatsky wrote:
> > On (04/10/17 20:48), Pavel Machek wrote:
> > [..]
> > > > but, once again, I see your point.
> > > 
> > > Good. Does that mean that the next version of patches will work ok in
> > > that case?
> > 
> > yes.
> 
> ok... so I'm looking at something like below right now.
> not really tested yet.
> 
> I put some comments into the code.
> 
> it does offloading after X printed lines by the same process.
> if we reschedule, then the counter resets. which is probably OK,
> we don't really want any process, except for printk_kthread, to
> stay in console_unlock() forever. "number of lines printed" is
> probably easier to understand (easily converted to the number of
> pageup/pagedown you need to press, terminal buffer history size,
> etc.) than seconds we spent on printing (which doesn't even
> correspond to messages' timestamps in general case).
> 
> when the limit of "number of lines printed" is 0, then no
> offloading takes place.
> 
> it also has some simple mechanism to handle cases when
> we try to wake_up() printk_kthread, but it never becomes alive.
> it's a bit simple minded, probably.
> 
> wake_up is done from printk_safe context, so warnings/printks
> from there should do no harm (in fact, we even do pr_crit()
> error reporting, when we enforce printk_emergency mode).
> 
> I'll do more tests tomorrow, and will take a closer look.
> this code is basically just compiles, boots and passes some
> trivial tests. quite possible I've missed something important.
> 
> once verified, then the next question will be -- do we even
> need printk_emergency_begin/end or we can leave without it.
> 
> // given that printk_emergency enforcement works properly
> 
> 
> but, once again, the code might be stupid and wrong.
> and I need some sleep.
> 
> ---
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 6cf756dbee39..c0075e8b3a09 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2141,6 +2197,89 @@ static inline int can_use_console(void)
>  	return cpu_online(raw_smp_processor_id()) || have_callable_console();
>  }
>  
> +/*
> + * Under heavy printing load/slow serial console/etc console_unlock() can
> + * stall CPUs, which can result in soft/hard-lockups, lost interrupts, RCU
> + * stalls, etc. Therefore we attempt to print the messages to console from
> + * a dedicated printk_kthread, which always runs in schedulable context.
> + *
> + * There are several possible scenarios:
> + *
> + * a) When we got a large number of pending messages to print.
> + * e.g.
> + *    vprintk_emit() or console_lock()
> + *     console_unlock()
> + *      <<massive dump>>
> + *
> + * b) When we printk() a large number of messages.
> + * e.g.
> + *   vprintk_emit()->console_unlock()   <<print 1 message>>
> + *   vprintk_emit()->console_unlock()   <<print 1 message>>
> + *   ...
> + *   vprintk_emit()->console_unlock()   <<print 1 message>>
> + *
> + * In all those cases we can be in atomic context, we need to offload
> + * printing at some point.
> + *
> + * This function must be called from 'printk_safe' context.
> + */
> +static inline bool console_offload_printing(void)
> +{
> +	static struct task_struct *printing_task = NULL;
> +	static unsigned long lines_printed = 0;
> +
> +	if (!atomic_print_limit || !printk_kthread_enabled())
> +		return false;
> +
> +	/* We rescheduled - reset the counters. */
> +	if (printing_task != current) {
> +		lines_printed = 0;
> +		printing_task = current;
> +		return false;
> +	}

If we want to check that the process rescheduled, we should
store/check also current->nvcsw + current->nivcsw.

This might be even more important in the detection of
the emergency situation, see below.


> +	if (current == printk_kthread)
> +		return false;

Yup, printk_kthread is special. You suggest another solution
in the other reply.

IMHO, the best solution would be if printk_kthread calls
console_unlock() with disabled preemption and does the offload
(releases console_sem) when need_resched() returns true.

By other words, printk_kthread should use its allotted time
as much as possible. But it should not block the console_sem
when sleeping.

My only fear is that it is getting more and more complicated.
On the other hand, any partial solution is asking for
troubles and complains.

> +
> +	/*
> +	 * Don't reset the counter, let CPU overrun the limit.
> +	 * The idea is that
> +	 *
> +	 *   a) woken up printk_kthread (if succeeded)
> +	 * or
> +	 *   b) concurrent printk from another CPU (if any)
> +	 *
> +	 * will change `printing_task' and reset the counter. This also
> +	 * let us to introduce additional policies later, for instance,
> +	 * if we can't wakeup printk_kthread for Y times, e.g.
> +	 *
> +	 *            lines_printed > 2 * atomic_print_limit
> +	 *
> +	 * then we can declare emergency and stop relying on printk_kthread.
> +	 *
> +	 * If neither a) nor b) happens - we continue printing from
> +	 * current process. Which is bad and can be risky, but we can't
> +	 * wake_up() printk_kthread, so things already don't look normal.
> +	 */
> +	lines_printed++;
> +	if (lines_printed < atomic_print_limit)
> +		return false;
> +
> +	/*
> +	 * A trivial emergency enforcement.
> +	 * Assumes that `atomic_print_limit' is large enough.
> +	 */
> +	if (lines_printed > 2 * (unsigned long)atomic_print_limit) {
> +		printk_enforce_emergency = true;
> +		pr_crit("Declaring printk emergency mode.\n");
> +		return false;
> +	}

The only messages that are printed on my workstation are the same
few lines everytime I connect my phone over USB to get it charged.
I am not sure if they are printed by the same process. But I would
get scared if printk switches to the emergency mode just because
there is only one process "regularly" producing messages.

It might help to check the number of process switch counts as
suggested above.


> +	/* Must be executed in 'printk_safe' context. */
> +	wake_up_process(printk_kthread);
> +	return true;
> +}
> +
>  /**
>   * console_unlock - unlock the console system
>   *
> @@ -2163,8 +2302,17 @@ void console_unlock(void)
>  	unsigned long flags;
>  	bool wake_klogd = false;
>  	bool do_cond_resched, retry;
> +	bool did_offload;
>  
>  	if (console_suspended) {
> +		/*
> +		 * Here and later, we need to clear the PENDING_OUTPUT bit
> +		 * in order to avoid an infinite loop in printk_kthread
> +		 * function when console_unlock() cannot flush messages
> +		 * because we suspended consoles. Someone else will print
> +		 * the messages from resume_console().
> +		 */
> +		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
>  		up_console_sem();
>  		return;
>  	}
> @@ -2186,6 +2334,7 @@ void console_unlock(void)
>  	do_cond_resched = console_may_schedule;
>  again:
>  	console_may_schedule = 0;
> +	did_offload = 0;

It would make more sense to clear the variable before the again:
target. In fact, there is a logic mistake, see below.
>  
>  	/*
>  	 * We released the console_sem lock, so we need to recheck if
> @@ -2193,6 +2342,7 @@ void console_unlock(void)
>  	 * console.
>  	 */
>  	if (!can_use_console()) {
> +		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
>  		console_locked = 0;
>  		up_console_sem();
>  		return;
> @@ -2221,7 +2371,7 @@ void console_unlock(void)
>  			len = 0;
>  		}
>  skip:
> -		if (console_seq == log_next_seq)
> +		if (did_offload || console_seq == log_next_seq)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> @@ -2253,9 +2403,28 @@ void console_unlock(void)
>  		stop_critical_timings();	/* don't trace print latency */
>  		call_console_drivers(ext_text, ext_len, text, len);
>  		start_critical_timings();
> +
> +		/*
> +		 * Sometimes we may lock console_sem before printk_kthread.
> +		 * In this case we will jump to `again' label (if there are
> +		 * pending messages), print one more line from current
> +		 * process, break out of printing loop (we don't reset the
> +		 * counter of printed lines) and do up_console_sem() to
> +		 * wakeup printk_kthread again.
> +		 *
> +		 * If printk_kthread never wakes up (which may indicate that
> +		 * the system is unstable or something weird is going on),
> +		 * then we will keep jumping to `again' label and printing
> +		 * one message from the logbuf. This is a bit ugly, but at
> +		 * least we will print out the logbuf.
> +		 *
> +		 * If such condition occurs, console_offload_printing() can
> +		 * declare `printk_emergency' at some point.

I am a bit confused by the comment above. The again goto target is
used only when there is a race between leaving the loop and releasing
the console_sem. It is a corner case.

If there are messages from other CPUs, they most likely appear during
the slow call_console_drivers(). They are handled inside the
for(;;) cycle unless we reach the atomic_print_limit and
wake up the printk_kthread.

IMHO, we should just mention here that the jobs might get offloaded
to prevent softlookups when console_unlock() is called in atomic
context.

> +		 */
> +		did_offload = console_offload_printing();
>  		printk_safe_exit_irqrestore(flags);
>  
> -		if (do_cond_resched)
> +		if (!did_offload && do_cond_resched)
>  			cond_resched();
>  	}
>  	console_locked = 0;
> @@ -2276,6 +2445,8 @@ void console_unlock(void)
>  	 */
>  	raw_spin_lock(&logbuf_lock);
>  	retry = console_seq != log_next_seq;

This should be:

	retry = console_seq != log_next_seq && !did_offload;

Otherwise, it would never leave.

I know that this was only proposal and you did it late until
late night.

Anyway, I like the proposal. I have a good feeling about
this way. Also I really like how the main logic is localized
in console_offload_printing().

Best Regards,
Petr

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

#1623504 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

Hello Petr,

thanks for taking a look!

On (04/13/17 16:03), Petr Mladek wrote:
> > +static inline bool console_offload_printing(void)
> > +{
> > +	static struct task_struct *printing_task = NULL;
> > +	static unsigned long lines_printed = 0;
> > +
> > +	if (!atomic_print_limit || !printk_kthread_enabled())
> > +		return false;
> > +
> > +	/* We rescheduled - reset the counters. */
> > +	if (printing_task != current) {
> > +		lines_printed = 0;
> > +		printing_task = current;
> > +		return false;
> > +	}
> 
> If we want to check that the process rescheduled, we should
> store/check also current->nvcsw + current->nivcsw.

ok.

[..]
> My only fear is that it is getting more and more complicated.
> On the other hand, any partial solution is asking for
> troubles and complains.

yeah. we have to aim slightly different and conflicting targets - introducing
a new printk behavior, while preserving an already existing guarantees. which
is a bit tricky.


[..]
> > +	if (lines_printed > 2 * (unsigned long)atomic_print_limit) {
> > +		printk_enforce_emergency = true;
> > +		pr_crit("Declaring printk emergency mode.\n");
> > +		return false;
> > +	}
> 
> The only messages that are printed on my workstation are the same
> few lines everytime I connect my phone over USB to get it charged.

you are right. this is a known and yet to be resolved issue.


> It might help to check the number of process switch counts as
> suggested above.

will take a look at your 'current->nvcsw + current->nivcsw' idea.
thanks.


[..]
> > +		/*
> > +		 * Sometimes we may lock console_sem before printk_kthread.
> > +		 * In this case we will jump to `again' label (if there are
> > +		 * pending messages), print one more line from current
> > +		 * process, break out of printing loop (we don't reset the
> > +		 * counter of printed lines) and do up_console_sem() to
> > +		 * wakeup printk_kthread again.
> > +		 *
> > +		 * If printk_kthread never wakes up (which may indicate that
> > +		 * the system is unstable or something weird is going on),
> > +		 * then we will keep jumping to `again' label and printing
> > +		 * one message from the logbuf. This is a bit ugly, but at
> > +		 * least we will print out the logbuf.
> > +		 *
> > +		 * If such condition occurs, console_offload_printing() can
> > +		 * declare `printk_emergency' at some point.
> 
> I am a bit confused by the comment above. The again goto target is
> used only when there is a race between leaving the loop and releasing
> the console_sem. It is a corner case.

not really.

this is the part where "preserve printk guarantees" jumps in.

when we limit the number of lines we can print we have to leave this loop
with not fully flushed logbuf. so `goto again' is not solely for corner
case anymore. when we prematurely leave the printing loop, we wake_up
printk_kthread, unlock console_sem... and then we have no idea if
printk_kthread going to wake_up at all, and, if it's going to, how much
time will it take. at the same time we have a task that is already in
console_unlock() and, probably, we still have pending messages in the logbuf.
that's why the process that just has left the printing loop [and there easily
might be pending messages in the logbuf] does the whole 'retry' thing. we can
have a misbehaving high priority process or something, that would prevent
printk_kthread from becoming running just when we need it. so, at least
sometimes, the printing process (the one that breaks ouf of printing loop
and wakes up printk_kthread) can re-acquire console_sem and print one more
line, then it up() console_sem, which, hopefully, will wake_up printk_kthread.
if printk_kthread did become running then if would be in console_sem wait
list at this point. if it didn't - then we

	a) wake up some other process that is probably in console_sem list
	   (hopefully there is one)

or

	b) continue printing from the current process. because printk_kthread
	   is still not running and there are no other processes that want to
	   console_lock(). not much we can do at this point.


so in expected/normal scenario, we fail to re-acquire the console_sem lock
(console_trylock()), which means that either printk_kthread or some other
process from console_sem wait list acquired the console_sem and will take
over printing.


I do something like this

---
@@ -2427,6 +2427,8 @@ void console_unlock(void)
                console_seq++;
                raw_spin_unlock(&logbuf_lock);
 
+               sprintf(text + 7, "{%s}", current->comm);
+
                stop_critical_timings();        /* don't trace print latency */
                call_console_drivers(ext_text, ext_len, text, len);
                start_critical_timings();
---


and fire up some silly printk tests (I don't care what exactly it prints,
I'm curious what process prints it). it sort of makes it easier to observe
the behaviour.



> If there are messages from other CPUs, they most likely appear during
> the slow call_console_drivers(). They are handled inside the
> for(;;) cycle unless we reach the atomic_print_limit and
> wake up the printk_kthread.

but `atomic_print_limit' can be quite restrictive. we break out of the
printing loop then `atomic_print_limit' tells us to do so, not when we
the logbuf is empty.


[..]
> > @@ -2276,6 +2445,8 @@ void console_unlock(void)
> >  	 */
> >  	raw_spin_lock(&logbuf_lock);
> >  	retry = console_seq != log_next_seq;
> 
> This should be:
> 
> 	retry = console_seq != log_next_seq && !did_offload;
> 
> Otherwise, it would never leave.

it is expected to leave at some point, when we would know for sure that
a successful offloading took place. otherwise we probably shouldn't leave.
we invoked wake_up_process(), but that does not really buy us anything
(from printk guarantees POV). we trust one thing only - a process holding
the console_sem lock. because that's "a fact"; wake_up_process() is nothing
but "a promise".


so, in short, the basic idea is:
- the worse the situation is, the closer printk behavior to the original one.


the bigger the scheduling latencies are, the more time we spent
in console_unlock(), printing more than `atomic_print_limit' chars.


in more details:

once we cross the `atomic_print_limit' we start this thing


@again label:

1) call_console_drivers()	- print a single logbuf entry

1) up()				- "somebody please take over" (we expect that at
				  least one process will do this - printk_kthread.
				  but we don't know when, and not entirely sure
				  if it will. so we are increasing our chances
				  by waking up printk_kthread, but we don't
				  completely count on it).

2) console_trylock()		- if successful
					then "eeehhh, OK... I'll print one more line"
					goto @again
				  else
					return, someone console_lock()-ed

yes, in absolutely bad scenario -- even printk_kthread can't lock
console_sem - this means old printk behaviour. but that's sort of exactly
what we want to do with the printk_emergency_begin/end annotations anyway.
in exchange we print out the logbuf eventually.


I'm trying to find a compromise that would make everyone happy. may be
I'm missing an easier/better solution, wouldn't be the first time ever :)

	-ss

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

#1618849 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On Fri, 7 Apr 2017 10:14:49 +0200
Pavel Machek <pavel@ucw.cz> wrote:

> > serial console can be quite slow. and port->lock, that is acquired by
> > console_unlock()->call_console_drivers()->write(), is also accessible
> > by serial driver's IRQ handler, and this lock may be busy long
> > enough -- as long as that IRQ handler transmits/receives chars. but
> > that's not the point.  
> 
> Well. This is what we had for 20 years.

But for the last 20 years we were not booting on machines with over 200
CPUs. Well, we were, but those had custom kernels (which probably
dismantled printk).

-- Steve

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

#1619468 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

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

On Fri 2017-04-07 10:29:17, Steven Rostedt wrote:
> On Fri, 7 Apr 2017 10:14:49 +0200
> Pavel Machek <pavel@ucw.cz> wrote:
> 
> > > serial console can be quite slow. and port->lock, that is acquired by
> > > console_unlock()->call_console_drivers()->write(), is also accessible
> > > by serial driver's IRQ handler, and this lock may be busy long
> > > enough -- as long as that IRQ handler transmits/receives chars. but
> > > that's not the point.  
> > 
> > Well. This is what we had for 20 years.
> 
> But for the last 20 years we were not booting on machines with over 200
> CPUs. Well, we were, but those had custom kernels (which probably
> dismantled printk).

Well, not a problem. Just find a solution that works for dual core
machines as well as it did for 20 years.

2 seconds timeout as proposed earlier should work well for big
machines, and with no regressions on small machines.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

#1615090 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (03/31/17 10:28), Eric W. Biederman wrote:
[..]
> > ... I'd also probably add pr_emerg() print-out to emergency_restart(),
> > the same way kernel_restart()/kernel_halt()/kernel_power_off() do.
> >
> > for those cases when emergency_restart() is called with printk in
> > kthreaded mode, not in emergency mode.
> 
> No. No. No.
> 
> emergency_restart should be the equivalent of a watchdog going off.
> AKA it is long past the point where you want to be coordinating
> with other parts of the kernel.  Rebooting is the priority.
> A print statement absolutely does not belong in emergency_restart.
> 
> The fact that nothing managed to get printed out without magic flushing
> code is highly disturbing.

Eric, have you checked what is usually going on right before the
emergency_restart() call?

a quick grep.

kernel/panic.c

	pr_emerg("Kernel panic - not syncing: %s\n", buf);
...
	console_flush_on_panic();
...
	emergency_restart();


kernel/debug/kdb/kdb_main.c

	kdb_printf("forcing reboot\n");
	kdb_reboot(0, NULL);
		emergency_restart();


kernel/debug/gdbstub.c

	gdb_cmd_reboot()
		printk(KERN_CRIT "Executing emergency reboot\n");
		machine_emergency_restart();


drivers/tty/sysrq.c

	__handle_sysrq()
		pr_info("SysRq : ");
		pr_cont("%s\n", op_p->action_msg);
		op_p->handler(key);
			sysrq_handle_reboot()
				emergency_restart()

and so on...


all those printk()-s, that are happening right before emergency_restart(),
in fact flush (!) all the pending logbuf messages to the serial console.
and seems it doesn't cause any troubles on you side. but having printk()
not one line _before_the emergency_restart(), but _in_ emergency_restart()
is all of a sudden very disturbing. how come?


> Looking from the outside this patchset appears to be broken by design.
> 
> If you don't want kernel functions suffering from the overhead of
> printing to a slow output device, don't do that then.

sorry, this is not productive. "don't use printk()" is not a solution.


> The point of printk is to give debugging output.  You have fundamentally
> incapacitated printk from serving it's primary purpose.

the point of the patch set is that printk has a fundamental issue -- it
can easily soft/hard lockup the system; it can stall RCU; it can cause
OOM; and so on and on and on.

	-ss

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

#1616653 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On 03/31, Ye Xiaolong wrote:
>On 03/31, Sergey Senozhatsky wrote:
>>On (03/31/17 11:35), Sergey Senozhatsky wrote:
>>[..]
>>> > [   21.009531] VFS: Warning: trinity-c2 using old stat() call. Recompile your binary.
>>> > [   21.148898] VFS: Warning: trinity-c0 using old stat() call. Recompile your binary.
>>> > [   22.298208] warning: process `trinity-c2' used the deprecated sysctl system call with 
>>> > 
>>> > Elapsed time: 310
>>> > BUG: kernel reboot-without-warning in test stage
>>> 
>>> so as far as I understand, this is the "missing kernel messages"
>>> type of bug report. a worst case scenario.
>>
>>panic() should have called console_flush_on_panic(), which sould have
>>flushed the messages regardless the printk_kthread state. so it probably
>>was not panic() that rebooted the kernel. (probably).
>>
>>kernel_restart() and kernel_halt() have pr_emerg() messages, printk switches
>>to printk_emergency mode the first time it sees EMERG level message. (may be
>>we switch to late).
>>
>>on the other hand, there is a emergency_restart(), where we don't switch
>>to printk_emergency mode and don't flush the existing kernel messages.
>>there is a bunch of places that call emergency_restart(), including sysrq.
>>
>>may I ask you, how do you usually restart the vm after the test?
>>`echo X > /proc/sysrq-trigger'?
>
>Yes.
>
>>
>>does this patch make it any better?
>
>I am trying it and will post the result once I get it.

Sorry for the late. I applied the patch of on top of the fbc14616f4 ("printk: enable printk offloading") 
and the "reboot-without-waring" issue is gone for 6 times of tests.

testcase/path_params/tbox_group/run: trinity/300s/vm-kbuild-yocto-ia32

fbc14616f483788a  a75384abd8885080d6923d7036  
----------------  --------------------------  
          4:4         -100%            0:6     dmesg.BUG:kernel_reboot-without-warning_in_test_stage

Thanks,
Xiaolong

>
>Thanks,
>Xiaolong
>>
>>---
>> drivers/tty/sysrq.c | 8 ++------
>> 1 file changed, 2 insertions(+), 6 deletions(-)
>>
>>diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
>>index 817dfb69914d..069f5540be36 100644
>>--- a/drivers/tty/sysrq.c
>>+++ b/drivers/tty/sysrq.c
>>@@ -240,7 +240,6 @@ static DECLARE_WORK(sysrq_showallcpus, sysrq_showregs_othercpus);
>> 
>> static void sysrq_handle_showallcpus(int key)
>> {
>>-	printk_emergency_begin();
>> 	/*
>> 	 * Fall back to the workqueue based printing if the
>> 	 * backtrace printing did not succeed or the
>>@@ -255,7 +254,6 @@ static void sysrq_handle_showallcpus(int key)
>> 		}
>> 		schedule_work(&sysrq_showallcpus);
>> 	}
>>-	printk_emergency_end();
>> }
>> 
>> static struct sysrq_key_op sysrq_showallcpus_op = {
>>@@ -282,10 +280,8 @@ static struct sysrq_key_op sysrq_showregs_op = {
>> 
>> static void sysrq_handle_showstate(int key)
>> {
>>-	printk_emergency_begin();
>> 	show_state();
>> 	show_workqueue_state();
>>-	printk_emergency_end();
>> }
>> static struct sysrq_key_op sysrq_showstate_op = {
>> 	.handler	= sysrq_handle_showstate,
>>@@ -296,9 +292,7 @@ static struct sysrq_key_op sysrq_showstate_op = {
>> 
>> static void sysrq_handle_showstate_blocked(int key)
>> {
>>-	printk_emergency_begin();
>> 	show_state_filter(TASK_UNINTERRUPTIBLE);
>>-	printk_emergency_end();
>> }
>> static struct sysrq_key_op sysrq_showstate_blocked_op = {
>> 	.handler	= sysrq_handle_showstate_blocked,
>>@@ -537,6 +531,7 @@ void __handle_sysrq(int key, bool check_mask)
>> 	int orig_log_level;
>> 	int i;
>> 
>>+	printk_emergency_begin();
>> 	rcu_sysrq_start();
>> 	rcu_read_lock();
>> 	/*
>>@@ -582,6 +577,7 @@ void __handle_sysrq(int key, bool check_mask)
>> 	}
>> 	rcu_read_unlock();
>> 	rcu_sysrq_end();
>>+	printk_emergency_end();
>> }
>> 
>> void handle_sysrq(int key)
>>-- 
>>2.12.2
>>

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

#1616710 — Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

On (04/05/17 15:29), Ye Xiaolong wrote:
[..]
> >>does this patch make it any better?
> >
> >I am trying it and will post the result once I get it.
> 
> Sorry for the late. I applied the patch of on top of the fbc14616f4 ("printk: enable printk offloading") 
> and the "reboot-without-waring" issue is gone for 6 times of tests.
> 
> testcase/path_params/tbox_group/run: trinity/300s/vm-kbuild-yocto-ia32
> 
> fbc14616f483788a  a75384abd8885080d6923d7036  
> ----------------  --------------------------  
>           4:4         -100%            0:6     dmesg.BUG:kernel_reboot-without-warning_in_test_stage

thanks!

	-ss

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

#1615351 — Re: [RFC][PATCHv2 8/8] printk: enable printk offloading

On Wed 2017-03-29 18:25:11, Sergey Senozhatsky wrote:
> Initialize the kernel printing thread and enable printk()
> offloading.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 19 +++++++++++++++++++
>  1 file changed, 19 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 0d96839bb450..acfdc50580db 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2796,6 +2796,25 @@ static int printk_kthread_func(void *data)
>  	return 0;
>  }
>  
> +/*
> + * Init printk kthread at late_initcall stage, after core/arch/device/etc.
> + * initialization.
> + */
> +static int __init init_printk_kthread(void)
> +{
> +	struct task_struct *thread;
> +
> +	thread = kthread_run(printk_kthread_func, NULL, "printk");
> +	if (IS_ERR(thread)) {
> +		pr_err("printk: unable to create printing thread\n");
> +		return PTR_ERR(thread);
> +	}
> +
> +	printk_kthread = thread;
> +	return 0;
> +}
> +late_initcall(init_printk_kthread);

I like the simplicity. I just wonder if people on tiny devices might
want to disable it. In each case, it does not make sense on non-SMP
machines or when people force the emergency mode all the time.

I am not sure what is the practice here. I wonder if we should be
proactive or keep it as is and wait until anyone complains. IMHO,
it is not that big deal but...

Best Regards,
Petr

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

#1615974 — Re: [RFC][PATCHv2 8/8] printk: enable printk offloading

On (04/03/17 17:42), Petr Mladek wrote:
> > +/*
> > + * Init printk kthread at late_initcall stage, after core/arch/device/etc.
> > + * initialization.
> > + */
> > +static int __init init_printk_kthread(void)
> > +{
> > +	struct task_struct *thread;
> > +
> > +	thread = kthread_run(printk_kthread_func, NULL, "printk");
> > +	if (IS_ERR(thread)) {
> > +		pr_err("printk: unable to create printing thread\n");
> > +		return PTR_ERR(thread);
> > +	}
> > +
> > +	printk_kthread = thread;
> > +	return 0;
> > +}
> > +late_initcall(init_printk_kthread);
> 
> I like the simplicity. I just wonder if people on tiny devices might
> want to disable it. In each case, it does not make sense on non-SMP
> machines or when people force the emergency mode all the time.
> 
> I am not sure what is the practice here. I wonder if we should be
> proactive or keep it as is and wait until anyone complains. IMHO,
> it is not that big deal but...

I tend to agree that this is not a big deal, as of now.
I've bigger concerns.

	-ss

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

Page 3 of 4 — ← Prev page 1 2 [3] 4  Next page →

Back to top | Article view | linux.kernel

csiph-web