Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

On Mon 2017-05-08 15:37:41, Sergey Senozhatsky wrote:
> Hello,
> 
> On (04/07/17 10:40), Steven Rostedt wrote:
> [..]
> > On Fri, 7 Apr 2017 14:44:55 +0200
> > Pavel Machek  wrote:
> > 
> > > Well, I have to agree here. This is 20 years worth of mess :-(.
> > 
> > Maybe someone should propose a micro-conf at Linux Plumbers where we
> > can brain storm a way to re-invent printk()? Seems it can do with a
> > completely new rewrite. ;-)
> 
> So I've been thinking about it... I'm somewhat limited in budget this
> year and can do either LPC or KS* - purely depending on which one can
> "attract" a required critical mass. From _this_ point of view KS,
> perhaps, would be more appropriate, especially given that it's in EU
> this year, if I'm not mistaken. But LPC has its own merits too, of
> course. LPC's microconference sounds good enough.
> 
> What do you guys think?
> 
> 
> * I obviously don't expect to be invited to the KS, all I said is that
>   I can be in Prague around that time so we can sit somewhere and talk.

I live in Prague and will be happy to discuss printk issues with
interested people.

I think about rewriting printk from time to time. Some brainstorming
might be helpful. On the other hand, I have become aware of many new printk
limits and deficiencies last year. The more I know the less I am sure
that I know enough for making a good design. I would personally prefer
to give it some longer time to gather information. Especially I am
interested into more feedback about the printk kthread and console
work offloading. Also I still do not have enough experience about
how different consoles are used and behave.

Best Regards,
Petr

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

On Mon 2017-05-08 15:37:41, Sergey Senozhatsky wrote:
> Hello,
> 
> On (04/07/17 10:40), Steven Rostedt wrote:
> [..]
> > On Fri, 7 Apr 2017 14:44:55 +0200
> > Pavel Machek  wrote:
> > 
> > > Well, I have to agree here. This is 20 years worth of mess :-(.
> > 
> > Maybe someone should propose a micro-conf at Linux Plumbers where we
> > can brain storm a way to re-invent printk()? Seems it can do with a
> > completely new rewrite. ;-)
> 
> So I've been thinking about it... I'm somewhat limited in budget this
> year and can do either LPC or KS* - purely depending on which one can
> "attract" a required critical mass. From _this_ point of view KS,
> perhaps, would be more appropriate, especially given that it's in EU
> this year, if I'm not mistaken. But LPC has its own merits too, of
> course. LPC's microconference sounds good enough.
> 
> What do you guys think?
> 
> 
> * I obviously don't expect to be invited to the KS, all I said is that
>   I can be in Prague around that time so we can sit somewhere and talk.

I live in Prague and will be happy to discuss printk issues with
interested people.

I think about rewriting printk from time to time. Some brainstorming
might be helpful. On the other hand, I have become aware of many new printk
limits and deficiencies last year. The more I know the less I am sure
that I know enough for making a good design. I would personally prefer
to give it some longer time to gather information. Especially I am
interested into more feedback about the printk kthread and console
work offloading. Also I still do not have enough experience about
how different consoles are used and behave.

Best Regards,
Petr

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

Hello,

On (04/07/17 10:40), Steven Rostedt wrote:
[..]
> On Fri, 7 Apr 2017 14:44:55 +0200
> Pavel Machek  wrote:
> 
> > Well, I have to agree here. This is 20 years worth of mess :-(.
> 
> Maybe someone should propose a micro-conf at Linux Plumbers where we
> can brain storm a way to re-invent printk()? Seems it can do with a
> completely new rewrite. ;-)

So I've been thinking about it... I'm somewhat limited in budget this
year and can do either LPC or KS* - purely depending on which one can
"attract" a required critical mass. From _this_ point of view KS,
perhaps, would be more appropriate, especially given that it's in EU
this year, if I'm not mistaken. But LPC has its own merits too, of
course. LPC's microconference sounds good enough.

What do you guys think?


* I obviously don't expect to be invited to the KS, all I said is that
  I can be in Prague around that time so we can sit somewhere and talk.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

Hello,

On (04/07/17 10:40), Steven Rostedt wrote:
[..]
> On Fri, 7 Apr 2017 14:44:55 +0200
> Pavel Machek  wrote:
> 
> > Well, I have to agree here. This is 20 years worth of mess :-(.
> 
> Maybe someone should propose a micro-conf at Linux Plumbers where we
> can brain storm a way to re-invent printk()? Seems it can do with a
> completely new rewrite. ;-)

So I've been thinking about it... I'm somewhat limited in budget this
year and can do either LPC or KS* - purely depending on which one can
"attract" a required critical mass. From _this_ point of view KS,
perhaps, would be more appropriate, especially given that it's in EU
this year, if I'm not mistaken. But LPC has its own merits too, of
course. LPC's microconference sounds good enough.

What do you guys think?


* I obviously don't expect to be invited to the KS, all I said is that
  I can be in Prague around that time so we can sit somewhere and talk.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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(_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 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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(_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 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

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()
> + *  <>
> + *
> + * b) When we printk() a large number of messages.
> + * e.g.
> + *   vprintk_emit()->console_unlock()   <>
> + *   vprintk_emit()->console_unlock()   <>
> + *   ...
> + *   vprintk_emit()->console_unlock()   <>
> + *
> + * 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 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

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()
> + *  <>
> + *
> + * b) When we printk() a large number of messages.
> + * e.g.
> + *   vprintk_emit()->console_unlock()   <>
> + *   vprintk_emit()->console_unlock()   <>
> + *   ...
> + *   vprintk_emit()->console_unlock()   <>
> + *
> + * 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 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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 99, 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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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 99, 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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

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 99, 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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

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 99, 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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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 
 #include 
 #include 
+#include 
 
 #include 
 #include 
@@ -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 = 1;
+
+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(_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(_emergency);
+}
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+   atomic_dec(_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, _pending);
logbuf_unlock_irqrestore(flags);
 
/* If called from the scheduler, we can not call up(). */
@@ -1882,6 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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 
 #include 
 #include 
+#include 
 
 #include 
 #include 
@@ -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 = 1;
+
+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(_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(_emergency);
+}
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+   atomic_dec(_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, _pending);
logbuf_unlock_irqrestore(flags);
 
/* If called from the scheduler, we can not call up(). */
@@ -1882,6 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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=145750373530161
[2] https://marc.info/?l=linux-kernel=145762735308470

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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=145750373530161
[2] https://marc.info/?l=linux-kernel=145762735308470

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

Hello Eric,

On (04/09/17 13:21), Eric W. Biederman wrote:
[..]
> It sounds like you are blaming printk when the problem is a very slow
> logging device.

sure, slow logging device definitely adds up to the problem. if there
is no delay in call_console_driver() then printk()->console_unlock()
take no time. anything (uart, fbdev, etc.) that makes call_console_drivers()
slower makes printk() slower. the patch set is not about offloading during
panic(), when offloading make no sense, as you mentioned, or about
uncommon/extreme/impossible cases of 45sec delays in printk. no.

but about the fact that printk() called from inappropriate context
can introduce delays/timeouts/stalls and lockups. several CPUs may call
printk simultaneously, but we don't have any mechanism that would grant
console_sem ownership to a CPU in !atomic context. the winner (the CPU
that first acquires console_sem) prints it all, as long as there are
pending messages.

e.g.
 lkml.kernel.org/r/20160701165959.GR12473@ubuntu
e.g.
 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/kernel/printk/printk.c?id=8d91f8b15361dfb438ab6eb3b319e2ded43458ff

and so on.

I've even seen when printk->console_unlock() invoked from RCU read side
caused OOM condition (some RCU protected objects are small, but some are
big -- e.g. slab pages: kmem_rcu_free()). that's very rare, but I've seen
it.

so there are too many uncertainties and too many inappropriate contexts
for printk.

but yes, you are right, if there is nothing that makes call_console_driver()
slow, then there is no issue.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

Hello Eric,

On (04/09/17 13:21), Eric W. Biederman wrote:
[..]
> It sounds like you are blaming printk when the problem is a very slow
> logging device.

sure, slow logging device definitely adds up to the problem. if there
is no delay in call_console_driver() then printk()->console_unlock()
take no time. anything (uart, fbdev, etc.) that makes call_console_drivers()
slower makes printk() slower. the patch set is not about offloading during
panic(), when offloading make no sense, as you mentioned, or about
uncommon/extreme/impossible cases of 45sec delays in printk. no.

but about the fact that printk() called from inappropriate context
can introduce delays/timeouts/stalls and lockups. several CPUs may call
printk simultaneously, but we don't have any mechanism that would grant
console_sem ownership to a CPU in !atomic context. the winner (the CPU
that first acquires console_sem) prints it all, as long as there are
pending messages.

e.g.
 lkml.kernel.org/r/20160701165959.GR12473@ubuntu
e.g.
 
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/kernel/printk/printk.c?id=8d91f8b15361dfb438ab6eb3b319e2ded43458ff

and so on.

I've even seen when printk->console_unlock() invoked from RCU read side
caused OOM condition (some RCU protected objects are small, but some are
big -- e.g. slab pages: kmem_rcu_free()). that's very rare, but I've seen
it.

so there are too many uncertainties and too many inappropriate contexts
for printk.

but yes, you are right, if there is nothing that makes call_console_driver()
slow, then there is no issue.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Eric W. Biederman]

Sergey Senozhatsky  writes:

> On (04/07/17 17:23), Peter Zijlstra wrote:
> [..]
>> > we are looking at different typical setups :) serial console being 45
>> > seconds behind logbuf does not surprise me anymore.
>> 
>> That does sound like you're doing something wrong and should look at
>> reducing printk() more than anything else.
>
> yeah, 45sec is an extreme case that simply doesn't surprise me anymore ;)
> that's not a normal/usual delay, of course, we are not this mad. on average
> it's much better and may be not so far 2 seconds after all. a massive OOM
> report, of course, appends logbuf messages at a much higher rate than UART
> serial console can swallow, so the delay is getting larger, expectedly.
> and, no, I don't add any printk-s, I'm looking at the lockup reports

Are you running your serial consoles at 9600 baud?

I would think the first thing to do would be to up your serial console
baud rate to 115200 or at least 38400.

Similarly anything the kernel is certain to survive I would set loglevel
such that it is logging somewhere with syslog rather than printk.

Of course my expectation on a production machine is to have panic on oom
set, to print the huge OOM message and then reboot.  So I don't possibly
see how offloading to another thread and then switching right back to
emergency mode is at all practical to solve the delay for a serious
situation like OOM.

It sounds like you are blaming printk when the problem is a very slow
logging device.

Eric

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Eric W. Biederman]

Sergey Senozhatsky  writes:

> On (04/07/17 17:23), Peter Zijlstra wrote:
> [..]
>> > we are looking at different typical setups :) serial console being 45
>> > seconds behind logbuf does not surprise me anymore.
>> 
>> That does sound like you're doing something wrong and should look at
>> reducing printk() more than anything else.
>
> yeah, 45sec is an extreme case that simply doesn't surprise me anymore ;)
> that's not a normal/usual delay, of course, we are not this mad. on average
> it's much better and may be not so far 2 seconds after all. a massive OOM
> report, of course, appends logbuf messages at a much higher rate than UART
> serial console can swallow, so the delay is getting larger, expectedly.
> and, no, I don't add any printk-s, I'm looking at the lockup reports

Are you running your serial consoles at 9600 baud?

I would think the first thing to do would be to up your serial console
baud rate to 115200 or at least 38400.

Similarly anything the kernel is certain to survive I would set loglevel
such that it is logging somewhere with syslog rather than printk.

Of course my expectation on a production machine is to have panic on oom
set, to print the huge OOM message and then reboot.  So I don't possibly
see how offloading to another thread and then switching right back to
emergency mode is at all practical to solve the delay for a serious
situation like OOM.

It sounds like you are blaming printk when the problem is a very slow
logging device.

Eric

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 10:29:17, Steven Rostedt wrote:
> On Fri, 7 Apr 2017 10:14:49 +0200
> Pavel Machek  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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 10:29:17, Steven Rostedt wrote:
> On Fri, 7 Apr 2017 10:14:49 +0200
> Pavel Machek  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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (04/07/17 17:23), Peter Zijlstra wrote:
[..]
> > we are looking at different typical setups :) serial console being 45
> > seconds behind logbuf does not surprise me anymore.
> 
> That does sound like you're doing something wrong and should look at
> reducing printk() more than anything else.

yeah, 45sec is an extreme case that simply doesn't surprise me anymore ;)
that's not a normal/usual delay, of course, we are not this mad. on average
it's much better and may be not so far 2 seconds after all. a massive OOM
report, of course, appends logbuf messages at a much higher rate than UART
serial console can swallow, so the delay is getting larger, expectedly.
and, no, I don't add any printk-s, I'm looking at the lockup reports

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (04/07/17 17:23), Peter Zijlstra wrote:
[..]
> > we are looking at different typical setups :) serial console being 45
> > seconds behind logbuf does not surprise me anymore.
> 
> That does sound like you're doing something wrong and should look at
> reducing printk() more than anything else.

yeah, 45sec is an extreme case that simply doesn't surprise me anymore ;)
that's not a normal/usual delay, of course, we are not this mad. on average
it's much better and may be not so far 2 seconds after all. a massive OOM
report, of course, appends logbuf messages at a much higher rate than UART
serial console can swallow, so the delay is getting larger, expectedly.
and, no, I don't add any printk-s, I'm looking at the lockup reports

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Peter Zijlstra]

On Sat, Apr 08, 2017 at 12:13:06AM +0900, 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.

That does sound like you're doing something wrong and should look at
reducing printk() more than anything else.

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Peter Zijlstra]

On Sat, Apr 08, 2017 at 12:13:06AM +0900, 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.

That does sound like you're doing something wrong and should look at
reducing printk() more than anything else.

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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?

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.

> 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 had sort of similar type of issue years ago. cpu could receive
STOP_IPI while holding console_sem and we couldn't print anything
(that was before we learned the console_trylock();console_unlock()
trick). if you, on the other hand, can access vmcore, then you know
where to look for the messages anyway.

but let's keep it for later. this nuance is not really important now.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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?

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.

> 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 had sort of similar type of issue years ago. cpu could receive
STOP_IPI while holding console_sem and we couldn't print anything
(that was before we learned the console_trylock();console_unlock()
trick). if you, on the other hand, can access vmcore, then you know
where to look for the messages anyway.

but let's keep it for later. this nuance is not really important now.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Steven Rostedt]

On Fri, 7 Apr 2017 14:44:55 +0200
Pavel Machek  wrote:

> Well, I have to agree here. This is 20 years worth of mess :-(.

Maybe someone should propose a micro-conf at Linux Plumbers where we
can brain storm a way to re-invent printk()? Seems it can do with a
completely new rewrite. ;-)

-- Steve

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Steven Rostedt]

On Fri, 7 Apr 2017 14:44:55 +0200
Pavel Machek  wrote:

> Well, I have to agree here. This is 20 years worth of mess :-(.

Maybe someone should propose a micro-conf at Linux Plumbers where we
can brain storm a way to re-invent printk()? Seems it can do with a
completely new rewrite. ;-)

-- Steve

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Steven Rostedt]

On Fri, 7 Apr 2017 10:14:49 +0200
Pavel Machek  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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Steven Rostedt]

On Fri, 7 Apr 2017 10:14:49 +0200
Pavel Machek  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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 21:10:21, Sergey Senozhatsky wrote:
> On (04/07/17 10:14), Pavel Machek wrote:
> [..]
> > Well. This is what we had for 20 years.
> 
> I guess it's not just me who is a bit unhappy with printk. ask
> Peter Zijlstra what's the first word that comes into his mind
> when we reads "printk"  :)

Well, still we should make sure we are improving.

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

> it's quite common that serial console (`console_seq') is a bit behind
> the logbuf head (`log_next_seq'). because log_store() can be much faster
> that call into console drivers.
> 
> another case is that  printk() != console_unlock().  console_sem can be
> locked by VT, TTY, fbdev, (not to mention that some other CPU might be
> doing printing), etc. etc. all printk()-s in the meantime will just
> log_store() messages, so we can have a bunch on pending messsges in
> logbuf, it's normal. the CPU that owns the console_sem will print all
> those pending messages from console_unlock() path. the distance between
> `log_next_seq' and `console_seq' can be much bigger than 2 seconds or
> 240/320/etc chars. so wrong offloading can leave with nothing valuable
> in the serial output, even if we would defer it.
> 
> well, I'm not arguing. just saying that it's not so easy to do everything
> right here.
>

Well, I have to agree here. This is 20 years worth of mess :-(.

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

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..
Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) 
http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 21:10:21, Sergey Senozhatsky wrote:
> On (04/07/17 10:14), Pavel Machek wrote:
> [..]
> > Well. This is what we had for 20 years.
> 
> I guess it's not just me who is a bit unhappy with printk. ask
> Peter Zijlstra what's the first word that comes into his mind
> when we reads "printk"  :)

Well, still we should make sure we are improving.

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

> it's quite common that serial console (`console_seq') is a bit behind
> the logbuf head (`log_next_seq'). because log_store() can be much faster
> that call into console drivers.
> 
> another case is that  printk() != console_unlock().  console_sem can be
> locked by VT, TTY, fbdev, (not to mention that some other CPU might be
> doing printing), etc. etc. all printk()-s in the meantime will just
> log_store() messages, so we can have a bunch on pending messsges in
> logbuf, it's normal. the CPU that owns the console_sem will print all
> those pending messages from console_unlock() path. the distance between
> `log_next_seq' and `console_seq' can be much bigger than 2 seconds or
> 240/320/etc chars. so wrong offloading can leave with nothing valuable
> in the serial output, even if we would defer it.
> 
> well, I'm not arguing. just saying that it's not so easy to do everything
> right here.
>

Well, I have to agree here. This is 20 years worth of mess :-(.

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

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..
Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) 
http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (04/07/17 10:14), Pavel Machek wrote:
[..]
> Well. This is what we had for 20 years.

I guess it's not just me who is a bit unhappy with printk. ask
Peter Zijlstra what's the first word that comes into his mind
when we reads "printk"  :)


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

it's quite common that serial console (`console_seq') is a bit behind
the logbuf head (`log_next_seq'). because log_store() can be much faster
that call into console drivers.

another case is that  printk() != console_unlock().  console_sem can be
locked by VT, TTY, fbdev, (not to mention that some other CPU might be
doing printing), etc. etc. all printk()-s in the meantime will just
log_store() messages, so we can have a bunch on pending messsges in
logbuf, it's normal. the CPU that owns the console_sem will print all
those pending messages from console_unlock() path. the distance between
`log_next_seq' and `console_seq' can be much bigger than 2 seconds or
240/320/etc chars. so wrong offloading can leave with nothing valuable
in the serial output, even if we would defer it.

well, I'm not arguing. just saying that it's not so easy to do everything
right here.

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.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (04/07/17 10:14), Pavel Machek wrote:
[..]
> Well. This is what we had for 20 years.

I guess it's not just me who is a bit unhappy with printk. ask
Peter Zijlstra what's the first word that comes into his mind
when we reads "printk"  :)


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

it's quite common that serial console (`console_seq') is a bit behind
the logbuf head (`log_next_seq'). because log_store() can be much faster
that call into console drivers.

another case is that  printk() != console_unlock().  console_sem can be
locked by VT, TTY, fbdev, (not to mention that some other CPU might be
doing printing), etc. etc. all printk()-s in the meantime will just
log_store() messages, so we can have a bunch on pending messsges in
logbuf, it's normal. the CPU that owns the console_sem will print all
those pending messages from console_unlock() path. the distance between
`log_next_seq' and `console_seq' can be much bigger than 2 seconds or
240/320/etc chars. so wrong offloading can leave with nothing valuable
in the serial output, even if we would defer it.

well, I'm not arguing. just saying that it's not so easy to do everything
right here.

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.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 16:46:34, Sergey Senozhatsky wrote:
> On (04/07/17 09:15), Pavel Machek wrote:
> > On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> > > Hello,
> > > 
> > > On (04/06/17 19:33), Pavel Machek wrote:
> > > > > This patch set gives up part of the printk() reliability for bounded
> > > > > latency (at least unless we detect we are really in trouble) which is 
> > > > > IMHO
> > > > > a good trade-off for lots of users (and others can just turn this 
> > > > > feature
> > > > > off).
> > > > 
> > > > If they can ever realize they were bitten by this feature.
> > > > 
> > > > Can we go for different tradeoff?
> > > > 
> > > > In console_unlock(), if you detect too much work, print "Too many
> > > > messages to print, %d bytes delayed" and wake up kernel thread.
> > > 
> > > "too many messages" is undefined. console_unlock() can be called from
> > > IRQ handler or with preemtion disabled, or under spin_lock, or under
> > > RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> > > from console_unlock() it may be already too late.
> > 
> > So lets define "too many messages" as 240 characters. We know printk
> > worked rather well for us for more than 20 years. Kernel code is used
> > to printk taking few miliseconds.
> 
> 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.

> [..]
> > Yeah? So you know modified printk() does not work, that's why
> > "emergency mode" exists. Unfortunately, you can't rely on fact that
> > you can detect half-crashed machines by printk levels. You usually
> > can't.
> 
> I'm not happy with those printk_emergency_begin()/end(), sure. but that's
> the reality -- every single solution that would offload printing duty implies
> that there will be cases when offloading would not be possible. either
> PENDING_PRINTK_IPI to other CPUs, or irq_work(PENDING_OUTPUT) on a local CPU,
> or anything else (um... what it is?... softirq? tasklet? print one logbuf
> entry from every IRQ handler? dunno, anything else?). There will be cases
> when we won't be able to expect that something will take over and finish
> printing for us. Well, may be I'm missing some other solution that would
> offload printing, eliminating lockup conditions, and at the same time work
> in 100% of the cases.

I don't have magic solution in my sleeve. You made a good case that
spending 30 seconds in printk() is a bad idea. I agree with that. Your
solution is to introduce printk_emergency_begin()/end(). I don't agree
there.

I believe "spend at most 2 seconds in printk(), then print a warning
and offload" is a solution closer to what we had before.

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 16:46:34, Sergey Senozhatsky wrote:
> On (04/07/17 09:15), Pavel Machek wrote:
> > On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> > > Hello,
> > > 
> > > On (04/06/17 19:33), Pavel Machek wrote:
> > > > > This patch set gives up part of the printk() reliability for bounded
> > > > > latency (at least unless we detect we are really in trouble) which is 
> > > > > IMHO
> > > > > a good trade-off for lots of users (and others can just turn this 
> > > > > feature
> > > > > off).
> > > > 
> > > > If they can ever realize they were bitten by this feature.
> > > > 
> > > > Can we go for different tradeoff?
> > > > 
> > > > In console_unlock(), if you detect too much work, print "Too many
> > > > messages to print, %d bytes delayed" and wake up kernel thread.
> > > 
> > > "too many messages" is undefined. console_unlock() can be called from
> > > IRQ handler or with preemtion disabled, or under spin_lock, or under
> > > RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> > > from console_unlock() it may be already too late.
> > 
> > So lets define "too many messages" as 240 characters. We know printk
> > worked rather well for us for more than 20 years. Kernel code is used
> > to printk taking few miliseconds.
> 
> 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.

> [..]
> > Yeah? So you know modified printk() does not work, that's why
> > "emergency mode" exists. Unfortunately, you can't rely on fact that
> > you can detect half-crashed machines by printk levels. You usually
> > can't.
> 
> I'm not happy with those printk_emergency_begin()/end(), sure. but that's
> the reality -- every single solution that would offload printing duty implies
> that there will be cases when offloading would not be possible. either
> PENDING_PRINTK_IPI to other CPUs, or irq_work(PENDING_OUTPUT) on a local CPU,
> or anything else (um... what it is?... softirq? tasklet? print one logbuf
> entry from every IRQ handler? dunno, anything else?). There will be cases
> when we won't be able to expect that something will take over and finish
> printing for us. Well, may be I'm missing some other solution that would
> offload printing, eliminating lockup conditions, and at the same time work
> in 100% of the cases.

I don't have magic solution in my sleeve. You made a good case that
spending 30 seconds in printk() is a bad idea. I agree with that. Your
solution is to introduce printk_emergency_begin()/end(). I don't agree
there.

I believe "spend at most 2 seconds in printk(), then print a warning
and offload" is a solution closer to what we had before.

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (04/07/17 09:15), Pavel Machek wrote:
> On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> > Hello,
> > 
> > On (04/06/17 19:33), Pavel Machek wrote:
> > > > This patch set gives up part of the printk() reliability for bounded
> > > > latency (at least unless we detect we are really in trouble) which is 
> > > > IMHO
> > > > a good trade-off for lots of users (and others can just turn this 
> > > > feature
> > > > off).
> > > 
> > > If they can ever realize they were bitten by this feature.
> > > 
> > > Can we go for different tradeoff?
> > > 
> > > In console_unlock(), if you detect too much work, print "Too many
> > > messages to print, %d bytes delayed" and wake up kernel thread.
> > 
> > "too many messages" is undefined. console_unlock() can be called from
> > IRQ handler or with preemtion disabled, or under spin_lock, or under
> > RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> > from console_unlock() it may be already too late.
> 
> So lets define "too many messages" as 240 characters. We know printk
> worked rather well for us for more than 20 years. Kernel code is used
> to printk taking few miliseconds.

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.

[..]
> Yeah? So you know modified printk() does not work, that's why
> "emergency mode" exists. Unfortunately, you can't rely on fact that
> you can detect half-crashed machines by printk levels. You usually
> can't.

I'm not happy with those printk_emergency_begin()/end(), sure. but that's
the reality -- every single solution that would offload printing duty implies
that there will be cases when offloading would not be possible. either
PENDING_PRINTK_IPI to other CPUs, or irq_work(PENDING_OUTPUT) on a local CPU,
or anything else (um... what it is?... softirq? tasklet? print one logbuf
entry from every IRQ handler? dunno, anything else?). There will be cases
when we won't be able to expect that something will take over and finish
printing for us. Well, may be I'm missing some other solution that would
offload printing, eliminating lockup conditions, and at the same time work
in 100% of the cases.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (04/07/17 09:15), Pavel Machek wrote:
> On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> > Hello,
> > 
> > On (04/06/17 19:33), Pavel Machek wrote:
> > > > This patch set gives up part of the printk() reliability for bounded
> > > > latency (at least unless we detect we are really in trouble) which is 
> > > > IMHO
> > > > a good trade-off for lots of users (and others can just turn this 
> > > > feature
> > > > off).
> > > 
> > > If they can ever realize they were bitten by this feature.
> > > 
> > > Can we go for different tradeoff?
> > > 
> > > In console_unlock(), if you detect too much work, print "Too many
> > > messages to print, %d bytes delayed" and wake up kernel thread.
> > 
> > "too many messages" is undefined. console_unlock() can be called from
> > IRQ handler or with preemtion disabled, or under spin_lock, or under
> > RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> > from console_unlock() it may be already too late.
> 
> So lets define "too many messages" as 240 characters. We know printk
> worked rather well for us for more than 20 years. Kernel code is used
> to printk taking few miliseconds.

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.

[..]
> Yeah? So you know modified printk() does not work, that's why
> "emergency mode" exists. Unfortunately, you can't rely on fact that
> you can detect half-crashed machines by printk levels. You usually
> can't.

I'm not happy with those printk_emergency_begin()/end(), sure. but that's
the reality -- every single solution that would offload printing duty implies
that there will be cases when offloading would not be possible. either
PENDING_PRINTK_IPI to other CPUs, or irq_work(PENDING_OUTPUT) on a local CPU,
or anything else (um... what it is?... softirq? tasklet? print one logbuf
entry from every IRQ handler? dunno, anything else?). There will be cases
when we won't be able to expect that something will take over and finish
printing for us. Well, may be I'm missing some other solution that would
offload printing, eliminating lockup conditions, and at the same time work
in 100% of the cases.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> Hello,
> 
> On (04/06/17 19:33), Pavel Machek wrote:
> > > This patch set gives up part of the printk() reliability for bounded
> > > latency (at least unless we detect we are really in trouble) which is IMHO
> > > a good trade-off for lots of users (and others can just turn this feature
> > > off).
> > 
> > If they can ever realize they were bitten by this feature.
> > 
> > Can we go for different tradeoff?
> > 
> > In console_unlock(), if you detect too much work, print "Too many
> > messages to print, %d bytes delayed" and wake up kernel thread.
> 
> "too many messages" is undefined. console_unlock() can be called from
> IRQ handler or with preemtion disabled, or under spin_lock, or under
> RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> from console_unlock() it may be already too late.

So lets define "too many messages" as 240 characters. We know printk
worked rather well for us for more than 20 years. Kernel code is used
to printk taking few miliseconds. 

> besides, this does not really address any of the concerns you have
> pointed out in other emails. we might be unable to wake_up printk_kthread
> (because there is a misbehaving higher prio process, or because the
> scheduler is misbehaving, etc. etc.) so the "emergency mode" is still
> here and still requires special handling.

Yeah? So you know modified printk() does not work, that's why
"emergency mode" exists. Unfortunately, you can't rely on fact that
you can detect half-crashed machines by printk levels. You usually
can't.

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

On Fri 2017-04-07 13:44:40, Sergey Senozhatsky wrote:
> Hello,
> 
> On (04/06/17 19:33), Pavel Machek wrote:
> > > This patch set gives up part of the printk() reliability for bounded
> > > latency (at least unless we detect we are really in trouble) which is IMHO
> > > a good trade-off for lots of users (and others can just turn this feature
> > > off).
> > 
> > If they can ever realize they were bitten by this feature.
> > 
> > Can we go for different tradeoff?
> > 
> > In console_unlock(), if you detect too much work, print "Too many
> > messages to print, %d bytes delayed" and wake up kernel thread.
> 
> "too many messages" is undefined. console_unlock() can be called from
> IRQ handler or with preemtion disabled, or under spin_lock, or under
> RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
> from console_unlock() it may be already too late.

So lets define "too many messages" as 240 characters. We know printk
worked rather well for us for more than 20 years. Kernel code is used
to printk taking few miliseconds. 

> besides, this does not really address any of the concerns you have
> pointed out in other emails. we might be unable to wake_up printk_kthread
> (because there is a misbehaving higher prio process, or because the
> scheduler is misbehaving, etc. etc.) so the "emergency mode" is still
> here and still requires special handling.

Yeah? So you know modified printk() does not work, that's why
"emergency mode" exists. Unfortunately, you can't rely on fact that
you can detect half-crashed machines by printk levels. You usually
can't.

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

Hello,

On (04/06/17 19:33), Pavel Machek wrote:
> > This patch set gives up part of the printk() reliability for bounded
> > latency (at least unless we detect we are really in trouble) which is IMHO
> > a good trade-off for lots of users (and others can just turn this feature
> > off).
> 
> If they can ever realize they were bitten by this feature.
> 
> Can we go for different tradeoff?
> 
> In console_unlock(), if you detect too much work, print "Too many
> messages to print, %d bytes delayed" and wake up kernel thread.

"too many messages" is undefined. console_unlock() can be called from
IRQ handler or with preemtion disabled, or under spin_lock, or under
RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
from console_unlock() it may be already too late.

besides, this does not really address any of the concerns you have
pointed out in other emails. we might be unable to wake_up printk_kthread
(because there is a misbehaving higher prio process, or because the
scheduler is misbehaving, etc. etc.) so the "emergency mode" is still
here and still requires special handling.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

Hello,

On (04/06/17 19:33), Pavel Machek wrote:
> > This patch set gives up part of the printk() reliability for bounded
> > latency (at least unless we detect we are really in trouble) which is IMHO
> > a good trade-off for lots of users (and others can just turn this feature
> > off).
> 
> If they can ever realize they were bitten by this feature.
> 
> Can we go for different tradeoff?
> 
> In console_unlock(), if you detect too much work, print "Too many
> messages to print, %d bytes delayed" and wake up kernel thread.

"too many messages" is undefined. console_unlock() can be called from
IRQ handler or with preemtion disabled, or under spin_lock, or under
RCU read lock, etc. etc. By the time we decide to wake up printk_kthread
from console_unlock() it may be already too late.

besides, this does not really address any of the concerns you have
pointed out in other emails. we might be unable to wake_up printk_kthread
(because there is a misbehaving higher prio process, or because the
scheduler is misbehaving, etc. etc.) so the "emergency mode" is still
here and still requires special handling.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

Hi!

> This patch set gives up part of the printk() reliability for bounded
> latency (at least unless we detect we are really in trouble) which is IMHO
> a good trade-off for lots of users (and others can just turn this feature
> off).

If they can ever realize they were bitten by this feature.

Can we go for different tradeoff?

In console_unlock(), if you detect too much work, print "Too many
messages to print, %d bytes delayed" and wake up kernel thread.

You still get the latency, and people bitten by this feature will at
least get fair warning.

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Pavel Machek]

Hi!

> This patch set gives up part of the printk() reliability for bounded
> latency (at least unless we detect we are really in trouble) which is IMHO
> a good trade-off for lots of users (and others can just turn this feature
> off).

If they can ever realize they were bitten by this feature.

Can we go for different tradeoff?

In console_unlock(), if you detect too much work, print "Too many
messages to print, %d bytes delayed" and wake up kernel thread.

You still get the latency, and people bitten by this feature will at
least get fair warning.

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


signature.asc
Description: Digital signature

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Ye Xiaolong]

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(_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
>>

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Ye Xiaolong]

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(_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
>>

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

On Mon 2017-04-03 11:31:52, Jan Kara wrote:
> On Fri 31-03-17 10:28:15, Eric W. Biederman wrote:
> > Sergey Senozhatsky  writes:
> > 
> > > On (03/31/17 14:39), 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.
> > >
> > >
> > > ... 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.

Sergey suggested to add pr_emerg() because it would signalize
emergency situation, printk kthread would be disabled and all
messages would be printed to the console directly (the old way).
It will _not_ be necessary to wakeup the kthread.

Note that the we could do it also _without_ pr_emerg().
Instead we could call simple/fast printk_emergency_begin()
as we do in other similar situations, for example during
kexec, suspend, see 4th and 6th patch of this patchset.


> > The fact that nothing managed to get printed out without magic flushing
> > code is highly disturbing.
> > 
> > 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, but the above is just contradictory. On one hand you say that
> missing messages is disturbing and on the other hand you say we should have
> no messages to avoid the overhead of printing. The fact is kernel has tons
> of messages because people want to see what happens to possibly debug stuff.
> And I don't see as viable to reduce amount of messages as it is neverending
> fight and always someone will be unhappy. As a result currently some machines
> are not able to boot due to printk traffic and there are other nasty
> effects from CPUs getting stuck printing messages to serial console (and
> this really bothers people as is proved by the fact that about every 6
> months someone comes with a hack to printk to fix the particular lockup he
> is hitting).

Yup, the fact is that there are situations when printk() itself brings
the system into problems, for example when too many messages are
flushed to a slow console in interrupt context.


> This patch set gives up part of the printk() reliability for bounded
> latency (at least unless we detect we are really in trouble) which is IMHO
> a good trade-off for lots of users (and others can just turn this feature
> off).

My view of this patchset is the following:

Deferred console output is perfectly fine when the system is in
reasonable state. The deferring is needed to keep the system safe
in some situations.

Of course, the view is different when the deferring is not longer
reliable (panic, kexec, suspend, restart). We try to detect these
situations, disable deferring, and push the messages the old way.
We call this emergency mode.

I am sure that we miss some situations. Also they might be hard
to detect. For this case, there is the kernel 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Petr Mladek]

On Mon 2017-04-03 11:31:52, Jan Kara wrote:
> On Fri 31-03-17 10:28:15, Eric W. Biederman wrote:
> > Sergey Senozhatsky  writes:
> > 
> > > On (03/31/17 14:39), 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.
> > >
> > >
> > > ... 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.

Sergey suggested to add pr_emerg() because it would signalize
emergency situation, printk kthread would be disabled and all
messages would be printed to the console directly (the old way).
It will _not_ be necessary to wakeup the kthread.

Note that the we could do it also _without_ pr_emerg().
Instead we could call simple/fast printk_emergency_begin()
as we do in other similar situations, for example during
kexec, suspend, see 4th and 6th patch of this patchset.


> > The fact that nothing managed to get printed out without magic flushing
> > code is highly disturbing.
> > 
> > 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, but the above is just contradictory. On one hand you say that
> missing messages is disturbing and on the other hand you say we should have
> no messages to avoid the overhead of printing. The fact is kernel has tons
> of messages because people want to see what happens to possibly debug stuff.
> And I don't see as viable to reduce amount of messages as it is neverending
> fight and always someone will be unhappy. As a result currently some machines
> are not able to boot due to printk traffic and there are other nasty
> effects from CPUs getting stuck printing messages to serial console (and
> this really bothers people as is proved by the fact that about every 6
> months someone comes with a hack to printk to fix the particular lockup he
> is hitting).

Yup, the fact is that there are situations when printk() itself brings
the system into problems, for example when too many messages are
flushed to a slow console in interrupt context.


> This patch set gives up part of the printk() reliability for bounded
> latency (at least unless we detect we are really in trouble) which is IMHO
> a good trade-off for lots of users (and others can just turn this feature
> off).

My view of this patchset is the following:

Deferred console output is perfectly fine when the system is in
reasonable state. The deferring is needed to keep the system safe
in some situations.

Of course, the view is different when the deferring is not longer
reliable (panic, kexec, suspend, restart). We try to detect these
situations, disable deferring, and push the messages the old way.
We call this emergency mode.

I am sure that we miss some situations. Also they might be hard
to detect. For this case, there is the kernel parameter, sysfs
knob that will 

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Jan Kara]

On Fri 31-03-17 10:28:15, Eric W. Biederman wrote:
> Sergey Senozhatsky  writes:
> 
> > On (03/31/17 14:39), 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.
> >
> >
> > ... 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.
> 
> 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, but the above is just contradictory. On one hand you say that
missing messages is disturbing and on the other hand you say we should have
no messages to avoid the overhead of printing. The fact is kernel has tons
of messages because people want to see what happens to possibly debug stuff.
And I don't see as viable to reduce amount of messages as it is neverending
fight and always someone will be unhappy. As a result currently some machines
are not able to boot due to printk traffic and there are other nasty
effects from CPUs getting stuck printing messages to serial console (and
this really bothers people as is proved by the fact that about every 6
months someone comes with a hack to printk to fix the particular lockup he
is hitting).

This patch set gives up part of the printk() reliability for bounded
latency (at least unless we detect we are really in trouble) which is IMHO
a good trade-off for lots of users (and others can just turn this feature
off).

Honza
-- 
Jan Kara 
SUSE Labs, CR

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Jan Kara]

On Fri 31-03-17 10:28:15, Eric W. Biederman wrote:
> Sergey Senozhatsky  writes:
> 
> > On (03/31/17 14:39), 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.
> >
> >
> > ... 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.
> 
> 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, but the above is just contradictory. On one hand you say that
missing messages is disturbing and on the other hand you say we should have
no messages to avoid the overhead of printing. The fact is kernel has tons
of messages because people want to see what happens to possibly debug stuff.
And I don't see as viable to reduce amount of messages as it is neverending
fight and always someone will be unhappy. As a result currently some machines
are not able to boot due to printk traffic and there are other nasty
effects from CPUs getting stuck printing messages to serial console (and
this really bothers people as is proved by the fact that about every 6
months someone comes with a hack to printk to fix the particular lockup he
is hitting).

This patch set gives up part of the printk() reliability for bounded
latency (at least unless we detect we are really in trouble) which is IMHO
a good trade-off for lots of users (and others can just turn this feature
off).

Honza
-- 
Jan Kara 
SUSE Labs, CR

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Eric W. Biederman]

Sergey Senozhatsky  writes:

> On (03/31/17 14:39), 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.
>
>
> ... 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.

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.

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

NAK to the entire concept.

Eric

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Eric W. Biederman]

Sergey Senozhatsky  writes:

> On (03/31/17 14:39), 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.
>
>
> ... 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.

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.

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

NAK to the entire concept.

Eric

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (03/31/17 14:39), 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.


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

---

diff --git a/kernel/reboot.c b/kernel/reboot.c
index e4ced883d8de..5bce29da913b 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -60,6 +60,7 @@ void (*pm_power_off_prepare)(void);
  */
 void emergency_restart(void)
 {
+   pr_emerg("Emergency restart\n");
kmsg_dump(KMSG_DUMP_EMERG);
machine_emergency_restart();
 }

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (03/31/17 14:39), 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.


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

---

diff --git a/kernel/reboot.c b/kernel/reboot.c
index e4ced883d8de..5bce29da913b 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -60,6 +60,7 @@ void (*pm_power_off_prepare)(void);
  */
 void emergency_restart(void)
 {
+   pr_emerg("Emergency restart\n");
kmsg_dump(KMSG_DUMP_EMERG);
machine_emergency_restart();
 }

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Ye Xiaolong]

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.

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(_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
>

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Ye Xiaolong]

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.

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(_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
>

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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'?

does this patch make it any better?

---
 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(_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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

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'?

does this patch make it any better?

---
 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(_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

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (03/31/17 05:38), kernel test robot wrote:
> FYI, we noticed the following commit:
> 
> commit: fbc14616f483788afabe77d05bfb99883dc66c73 ("printk: enable printk 
> offloading")
> url: 
> https://github.com/0day-ci/linux/commits/Sergey-Senozhatsky/printk-introduce-printing-kernel-thread/20170330-185752

thanks for the report!

[..]
> +-+++
> | | fd8b6b120c | fbc14616f4 |
> +-+++
> | boot_successes  | 8  | 8  |
> | boot_failures   | 0  | 6  |
> | BUG:kernel_reboot-without-warning_in_test_stage | 0  | 4  |
> | BUG:kernel_hang_in_test_stage   | 0  | 2  |
> +-+++
> 
> 
> 
> [   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.

-ss

Re: [printk] fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage

[Sergey Senozhatsky]

On (03/31/17 05:38), kernel test robot wrote:
> FYI, we noticed the following commit:
> 
> commit: fbc14616f483788afabe77d05bfb99883dc66c73 ("printk: enable printk 
> offloading")
> url: 
> https://github.com/0day-ci/linux/commits/Sergey-Senozhatsky/printk-introduce-printing-kernel-thread/20170330-185752

thanks for the report!

[..]
> +-+++
> | | fd8b6b120c | fbc14616f4 |
> +-+++
> | boot_successes  | 8  | 8  |
> | boot_failures   | 0  | 6  |
> | BUG:kernel_reboot-without-warning_in_test_stage | 0  | 4  |
> | BUG:kernel_hang_in_test_stage   | 0  | 2  |
> +-+++
> 
> 
> 
> [   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.

-ss