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

Groups > linux.kernel > #1652358 > unrolled thread

Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread

Back to article view | Back to linux.kernel

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

Contents

  Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Petr Mladek <pmladek@suse.com> - 2017-05-29 11:30 +0200
    Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Jan Kara <jack@suse.cz> - 2017-05-29 14:20 +0200
      Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-05-31 09:40 +0200
        Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Andreas Mohr <andi@lisas.de> - 2017-06-01 00:00 +0200
        Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-06-01 09:30 +0200
          Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-06-01 09:30 +0200
          Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-06-01 11:30 +0200
    Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-05-31 09:30 +0200

#1652358 — Re: [RFC][PATCHv3 2/5] printk: introduce printing kernel thread

On Wed 2017-05-10 14:59:35, Sergey Senozhatsky wrote:
> This patch introduces a '/sys/module/printk/parameters/atomic_print_limit'
> sysfs param, which sets the limit on number of lines a process can print
> from console_unlock(). Value 0 corresponds to the current behavior (no
> limitation). The printing offloading is happening from console_unlock()
> function and, briefly, looks as follows: as soon as process prints more
> than `atomic_print_limit' lines it attempts to offload printing to another
> process. Since nothing guarantees that there will another process sleeping
> on the console_sem or calling printk() on another CPU simultaneously, the
> patch also introduces an auxiliary kernel thread - printk_kthread, the
> main purpose of which is to take over printing duty. The workflow is, thus,
> turns into: as soon as process prints more than `atomic_print_limit' lines
> it wakes up printk_kthread and unlocks the console_sem. So in the best case
> at this point there will be at least 1 processes trying to lock the
> console_sem: printk_kthread. (There can also be a process that was sleeping
> on the console_sem and that was woken up by console semaphore up(); and
> concurrent printk() invocations from other CPUs). But in the worst case
> there won't be any processes ready to take over the printing duty: it
> may take printk_kthread some time to become running; or printk_kthread
> may even never become running (a misbehaving scheduler, or other critical
> condition). That's why after we wake_up() printk_kthread we can't
> immediately leave the printing loop, we must ensure that the console_sem
> has a new owner before we do so. Therefore, `atomic_print_limit' is a soft
> limit, not the hard one: we let task to overrun `atomic_print_limit'.
> But, at the same time, the console_unlock() printing loop behaves differently
> for tasks that have exceeded `atomic_print_limit': after every printed
> logbuf entry (call_console_drivers()) such a process wakes up printk_kthread,
> unlocks the console_sem and attempts to console_trylock() a bit later
> (if there any are pending messages in the logbuf, of course). In the best case
> scenario either printk_kthread or some other tasks will lock the console_sem,
> so current printing task will see failed console_trylock(), which will
> indicate a successful printing offloading. In the worst case, however,
> current will successfully console_trylock(), which will indicate that
> offloading did not take place and we can't return from console_unlock(),
> so the printing task will print one more line from the logbuf and attempt
> to offload printing once again; and it will continue doing so until another
> process locks the console_sem or until there are pending messages in the
> logbuf. So if everything goes wrong - we can't wakeup printk_kthread and
> there are no other processes sleeping on the console_sem or trying to down()
> it - then we will have the existing console_unlock() behavior: print all
> pending messages in one shot.

Please, try to avoid such long paragraphs ;-) It looks fine when you
read it for the first time. But it becomes problematic when you try
to go back and re-read some detail.

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 2cb7f4753b76..a113f684066c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2155,6 +2216,85 @@ static inline int can_use_console(void)
>  	return cpu_online(raw_smp_processor_id()) || have_callable_console();
>  }
>  
> +/*
> + * Under heavy printing load or with a slow serial console (or both)
> + * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
> + * lost interrupts, RCU stalls, etc. Therefore we attempt to limit the
> + * number of lines a process can print from console_unlock().
> + *
> + * There is one more reason to do offloading - there might be other processes
> + * (including user space tasks) sleeping on the console_sem in uninterruptible
> + * state; and keeping the console_sem locked for long time may have a negative
> + * impact on them.
> + *
> + * This function must be called from 'printk_safe' context under
> + * console_sem lock.
> + */
> +static inline bool console_offload_printing(void)
> +{
> +	static struct task_struct *printing_task;
> +	static unsigned long long lines_printed;
> +	static unsigned long saved_csw;
> +
> +	if (!printk_offloading_enabled())
> +		return false;
> +
> +	if (system_state != SYSTEM_RUNNING || oops_in_progress)
> +		return false;

Wow, I really like this test. I was not aware of this variable.

Well, I would allow to use the offload also during boot.
We have reports when softlockups happened during boot.
The offloading can be easily disabled via the command line
but not the other way around.


> +	/* A new task - reset the counters. */
> +	if (printing_task != current) {
> +		lines_printed = 0;
> +		printing_task = current;
> +		saved_csw = current->nvcsw + current->nivcsw;
> +		return false;
> +	}
> +
> +	lines_printed++;
> +	if (lines_printed < atomic_print_limit)
> +		return false;
> +
> +	if (current == printk_kthread) {
> +		/*
> +		 * Reset the `lines_printed' counter, just in case if
> +		 * printk_kthread is the only process left that would
> +		 * down() console_sem and call console_unlock().
> +		 */
> +		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
> +	 * reasonably and sufficiently large.
> +	 */
> +	if (lines_printed > 10 * (unsigned long long)atomic_print_limit &&
> +			saved_csw == (current->nvcsw + current->nivcsw)) {
> +		printk_enforce_emergency = true;
> +		pr_crit("Declaring printk emergency mode.\n");
> +		return false;
> +	}

This is interesting way how to detect that the system is in the
emergency state. The question is how reliable it is.

It might work only if the waken printk kthread is scheduled in a predictable
time period. You try to achieve this by setting read time priority
(4th patch of this patchset). The question is how this would work:


First, the real time priority is questionable on its own. Logging
is important but the real time priority is dangerous. Any "flood"
of messages will starve all other processes with normal priority.
It is better than a softlockup but it might cause problems as well.


Second, it might be pretty hard to tune the prediction of the
emergency situation. The above formula might depend on:

  + the speed of active consoles

  + length of the printed lines

  + the number and priorities of other real time tasks
    on the system and the related average time when
    printk kthread is scheduled

  + HZ size; the lower HZ the more messages might be
    handled in one jiffy

  + the current CPU speed, ...


Third, if the console_trylock() fails below, it is not guaranteed that
the other waiter will really continue printing. The console_trylock()
would fail because someone else called console_lock(), failed to get it,
and went into sleep. There is no guarantee that it will be waken
once again.

I have discussed this with my colleagues. They think that we are
lost anyway if the scheduling does not work. It is because many
console drivers use sleeping locks and depends on scheduling.

They suggested me to write down what we really wanted to achieve
first. I thought that I knew it. But it actually might be
interesting to write it down:


Ideal printk:

  + show and store all messages to know what's going on


Current printk does the best effort to:

  + store "all" messages into logbuf_log and

      + show important ones on console
      + allow to see/store them in userspace
      + allow to find them in crashdump


Current printk has limitations:

  + storing the messages:

      + limited buffer size => loosing messages
      + possible deadlocks => temporary passing via alternative
			buffers in NMI, recursion


  + userspace access ?:

      + on demand => more behind the reality that it might be


  + console output:

      + slow => async =>
		+ might be far behind
		+ loosing messages
		+ showing only ones with high log level
		+ possible softlockup
		+ not guaranteed when dying

      + possible deadlock => explicitly async in sched, NMI


Now, this patchset is trying to avoid the softlockup caused by console
output by making it even more async. This makes the other problems of
the async output more visible.

The patch tries to reduce the negative impact by detecting when
the negative impact is visible and switching back to the sync mode.

The fact is that we need to handle the emergency situation well.
This is where the system has troubles and the messages might
be crucial to debug the problem and fix it.


<repeating myself>

The question is if we are able to detect the emergency situation
reliable and if the solution does not bring other problems.

If the detection has too false positives, it will not help much
with the original problem (softlockup). If it has too false negatives,
it will increase the negative impact of the limits.

Also adding kthread with real time priority might have strange
side effects on its own.

</repeating myself>


Let me to look at it from the other side. What are the emergency
situations?

  + oops/panic() - easy to detect
  + suspend, shutdown, halt - rather easy to detect as well
  + flood of messages => console far behind logbuf_log
  + sudden dead without triggering panic()

Did I miss anything?

Anyway, we could detect the first three situations rather well:

  + oops/panic by a check for oops_in_progress

  + suspend, shutdown, ... by the check of system_state
    and the notifiers in the 5th patch

  + I would suggest to detect flood of messages by a difference
    between log_next_seq and console_seq. We could take into
    account the number of messages in the buffer
    (log_next_seq - log_first_seq)

  + I do not see a reliable way how to detect the sudden dead.


Please note, that we do not really need that questionable
trick with console_unlock(), console_trylock(), counting handled
messages over the limit, and realtime kthread.


In addition, I think that a semi-sync-async mode might better
handle the sudden dead. What is it? I have already talked about
something similar last time.

Normal printk() should do something like:

  printk()
    vprintk_emit()
      log_store()
      if (!deferred)
	console_trylock()
	console_unlock()
	  while (num_lines < atomic_print_limit)
	    handle message
	  up_console_sem()
	  if (pending_messages)
	    wakeup(printk_kthread)


and printk_kthread should do:

   while() {

       if (!pending_messages)
	 sleep()

       console_lock()

       preempt_disable()
       console_unlock()
	 while (pending_message && !need_resched)
	   handle message
	 up_console_sem()
       preempt_enable()
    }


By other words:

  + printk() should try to get console and handle few lines
    synchronously. It will handle its own message in most cases.

  + printk_kthread is only a fallback. It is waken when there are
    unhandled messages. It handles as many messages as
    possible in its assigned time slot. But it releases
    console_sem before it goes into sleep.


The advantages:

   + all messages are handled synchronously if there is not
     a flood of messages

   + if there is the flood of messages; kthread works only
     as a fallback; processes that produce the messages
     are involved into handling the console (nature throttling);
     the messages appear on the console even when printk_kthread
     is sleeping; but the softlockup is prevented

=> it should work pretty well in all situations, including the flood
   of messages and sudden dead.

What do you think, please?

Did I made a mistake in the logic?
Did I miss some important reason for an emergency situation?

I am sorry for the long mail. It took me long time to sort ideas.
I hope that it makes sense.


Best Regards,
Petr

[toc] | [next] | [standalone]

#1652482

On Mon 29-05-17 11:29:06, Petr Mladek wrote:
> On Wed 2017-05-10 14:59:35, Sergey Senozhatsky wrote:
> > This patch introduces a '/sys/module/printk/parameters/atomic_print_limit'
> > sysfs param, which sets the limit on number of lines a process can print
> > from console_unlock(). Value 0 corresponds to the current behavior (no
> > limitation). The printing offloading is happening from console_unlock()
> > function and, briefly, looks as follows: as soon as process prints more
> > than `atomic_print_limit' lines it attempts to offload printing to another
> > process. Since nothing guarantees that there will another process sleeping
> > on the console_sem or calling printk() on another CPU simultaneously, the
> > patch also introduces an auxiliary kernel thread - printk_kthread, the
> > main purpose of which is to take over printing duty. The workflow is, thus,
> > turns into: as soon as process prints more than `atomic_print_limit' lines
> > it wakes up printk_kthread and unlocks the console_sem. So in the best case
> > at this point there will be at least 1 processes trying to lock the
> > console_sem: printk_kthread. (There can also be a process that was sleeping
> > on the console_sem and that was woken up by console semaphore up(); and
> > concurrent printk() invocations from other CPUs). But in the worst case
> > there won't be any processes ready to take over the printing duty: it
> > may take printk_kthread some time to become running; or printk_kthread
> > may even never become running (a misbehaving scheduler, or other critical
> > condition). That's why after we wake_up() printk_kthread we can't
> > immediately leave the printing loop, we must ensure that the console_sem
> > has a new owner before we do so. Therefore, `atomic_print_limit' is a soft
> > limit, not the hard one: we let task to overrun `atomic_print_limit'.
> > But, at the same time, the console_unlock() printing loop behaves differently
> > for tasks that have exceeded `atomic_print_limit': after every printed
> > logbuf entry (call_console_drivers()) such a process wakes up printk_kthread,
> > unlocks the console_sem and attempts to console_trylock() a bit later
> > (if there any are pending messages in the logbuf, of course). In the best case
> > scenario either printk_kthread or some other tasks will lock the console_sem,
> > so current printing task will see failed console_trylock(), which will
> > indicate a successful printing offloading. In the worst case, however,
> > current will successfully console_trylock(), which will indicate that
> > offloading did not take place and we can't return from console_unlock(),
> > so the printing task will print one more line from the logbuf and attempt
> > to offload printing once again; and it will continue doing so until another
> > process locks the console_sem or until there are pending messages in the
> > logbuf. So if everything goes wrong - we can't wakeup printk_kthread and
> > there are no other processes sleeping on the console_sem or trying to down()
> > it - then we will have the existing console_unlock() behavior: print all
> > pending messages in one shot.

Actually I had something very similar in old versions of my patch set. And
it didn't work very well. The problem was that e.g. sometimes scheduler
decided that printk kthread should run on the same CPU as the process
currently doing printing and in such case printk kthread never took over
printing and the machine locked up due to heavy printing.

> First, the real time priority is questionable on its own. Logging
> is important but the real time priority is dangerous. Any "flood"
> of messages will starve all other processes with normal priority.
> It is better than a softlockup but it might cause problems as well.

Processes with real-time priority should have well bounded runtime (in
miliseconds). Printk kthread doesn't have such bounded runtime so it should
not be a real time process as it could hog the CPU it is running on...

So I think what Petr suggests below is better. Keep normal priority, print
something to console from the process doing printk() and just wake up
printk kthread and hope it can print the rest. It is not ideal but unless
there's a flood of messages there is no regression to current state.

> In addition, I think that a semi-sync-async mode might better
> handle the sudden dead. What is it? I have already talked about
> something similar last time.
> 
> Normal printk() should do something like:
> 
>   printk()
>     vprintk_emit()
>       log_store()
>       if (!deferred)
> 	console_trylock()
> 	console_unlock()
> 	  while (num_lines < atomic_print_limit)
> 	    handle message
> 	  up_console_sem()
> 	  if (pending_messages)
> 	    wakeup(printk_kthread)
> 
> 
> and printk_kthread should do:
> 
>    while() {
> 
>        if (!pending_messages)
> 	 sleep()
> 
>        console_lock()
> 
>        preempt_disable()
>        console_unlock()
> 	 while (pending_message && !need_resched)
> 	   handle message
> 	 up_console_sem()
>        preempt_enable()
>     }
> 
> 
> By other words:
> 
>   + printk() should try to get console and handle few lines
>     synchronously. It will handle its own message in most cases.
> 
>   + printk_kthread is only a fallback. It is waken when there are
>     unhandled messages. It handles as many messages as
>     possible in its assigned time slot. But it releases
>     console_sem before it goes into sleep.
> 
> 
> The advantages:
> 
>    + all messages are handled synchronously if there is not
>      a flood of messages
> 
>    + if there is the flood of messages; kthread works only
>      as a fallback; processes that produce the messages
>      are involved into handling the console (nature throttling);
>      the messages appear on the console even when printk_kthread
>      is sleeping; but the softlockup is prevented
> 
> => it should work pretty well in all situations, including the flood
>    of messages and sudden dead.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

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

#1653933

Hello Jan,

On (05/29/17 14:12), Jan Kara wrote:
[..]
> Actually I had something very similar in old versions of my patch set. And
> it didn't work very well. The problem was that e.g. sometimes scheduler
> decided that printk kthread should run on the same CPU as the process
> currently doing printing and in such case printk kthread never took over
> printing and the machine locked up due to heavy printing.

hm, interesting.

> > First, the real time priority is questionable on its own. Logging
> > is important but the real time priority is dangerous. Any "flood"
> > of messages will starve all other processes with normal priority.
> > It is better than a softlockup but it might cause problems as well.
> 
> Processes with real-time priority should have well bounded runtime (in
> miliseconds). Printk kthread doesn't have such bounded runtime so it should
> not be a real time process as it could hog the CPU it is running on...

yeah, I can easily make it a normal prio task. at the same time
printk_kthread has 'soft' limits on its execution. it's under the
same constraints as the rest of the processes that do printing.
there can be a random RT task doing console_trylock()->console_unlock(),
so we still can hog CPUs. but, yeah, I don't want printk_kthread to be
special.

> So I think what Petr suggests below is better. Keep normal priority, print
> something to console from the process doing printk() and just wake up
> printk kthread and hope it can print the rest. It is not ideal but unless
> there's a flood of messages there is no regression to current state.

hm, this is very close to what I do in my patch. with some additional
guarantess. because people mostly want to have good old printk. that
let's hope part basically doesn't work when it's needed the most. we
had a ton of cases of lost messages in serial logs.

I replied in more details in another mail.

	-ss

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

#1654653

On Wed, May 31, 2017 at 04:30:59PM +0900, Sergey Senozhatsky wrote:
> Hello Jan,
> 
> On (05/29/17 14:12), Jan Kara wrote:
> [..]
> > Actually I had something very similar in old versions of my patch set. And
> > it didn't work very well. The problem was that e.g. sometimes scheduler
> > decided that printk kthread should run on the same CPU as the process
> > currently doing printing and in such case printk kthread never took over
> > printing and the machine locked up due to heavy printing.
> 
> hm, interesting.

Not too knowledgeable, but just my thoughts:
was this on a non-preemption kernel (!CONFIG_PREEMPT).
If so, perhaps we are missing some non-preempt-case yield somewhere.
I'd think that it really *cannot* be that there are relevant processes
(printk kthread) which functionality invoked by a user of that process *does*
know about (read: printk() APIs), yet somehow those printk() APIs then
do not properly cause a yield
[thus possibly and hopefully: to the printk kernel thread]
(quite possibly after some certain amount of printk resource use exceeded).
--> implementation bug??
(due to staying at execution of a client process, despite that one making
massive calls to printk() APIs, where we then ought to be able to
properly set up a preemption point)

Pseudo code:

void printk_use_annotate()
{
  if (count_printk_since_last_servicing > 30)
    yield();
}

Note that a preemption yield action obviously will not reliably guarantee
hitting printk thread
(unless there's an API for directed yield),
thus this mechanism has to be qualified as *unreliable*,
thus this has to be taken into account by implementation code.

But all this reasoning is a strong indication that
there might be no
properly precisely handshaked producer/consumer protocol -
this would e.g. be the case for a proper select() loop
with event handling where the partner would be woken up *precisely*
(via POSIX 3-way handshake!)
when the condition for wakeup is fulfilled
(read: too many pending printk()s or some such),
rather than having some imprecise (sleep-type / "oh I do not have much to
do any more now") "handwaving" scheduling.


> yeah, I can easily make it a normal prio task. at the same time
> printk_kthread has 'soft' limits on its execution. it's under the
> same constraints as the rest of the processes that do printing.
> there can be a random RT task doing console_trylock()->console_unlock(),
> so we still can hog CPUs. but, yeah, I don't want printk_kthread to be
> special.

[printk_thread not special] Indeed. Think clean dependency abstraction.
printk kthread (i.e., that "more special" thread worker context)
should merely be *one* user of these printk queue servicing APIs.
And those servicing APIs should simply be invocable by anyone
who would want to take part in
getting the printk queue load properly serviced,
without any special handwaving.

[I can easily make all those "easy" wishlist requests -
I did not have to painfully design all that stuff ;-)]

Andreas Mohr

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

#1654883

On (05/31/17 16:30), Sergey Senozhatsky wrote:
> On (05/29/17 14:12), Jan Kara wrote:
> [..]
> > Actually I had something very similar in old versions of my patch set. And
> > it didn't work very well. The problem was that e.g. sometimes scheduler
> > decided that printk kthread should run on the same CPU as the process
> > currently doing printing and in such case printk kthread never took over
> > printing and the machine locked up due to heavy printing.
> 
> hm, interesting.

that's a tricky problem to deal with.



... so may be we can have per-CPU printk kthreads then

	static DEFINE_PER_CPU(struct task_struct *, printk_kthread);


SMP hotplug threads, to be precise, the same way as watchdog has it. and
then during offloading we can wake_up any printk_kthread that is knowingly
not from this-CPU, all of them, let them compete for the console_sem.

just a quick idea.

thoughts?

	-ss

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

#1654885

On (06/01/17 16:21), Sergey Senozhatsky wrote:
> On (05/31/17 16:30), Sergey Senozhatsky wrote:
> > On (05/29/17 14:12), Jan Kara wrote:
> > [..]
> > > Actually I had something very similar in old versions of my patch set. And
> > > it didn't work very well. The problem was that e.g. sometimes scheduler
> > > decided that printk kthread should run on the same CPU as the process
> > > currently doing printing and in such case printk kthread never took over
> > > printing and the machine locked up due to heavy printing.
> > 
> > hm, interesting.
> 
> that's a tricky problem to deal with.
> 
> 
> 
> ... so may be we can have per-CPU printk kthreads then
> 
> 	static DEFINE_PER_CPU(struct task_struct *, printk_kthread);
> 
> 
> SMP hotplug threads, to be precise, the same way as watchdog has it. and
> then during offloading we can wake_up any printk_kthread that is knowingly
> not from this-CPU, all of them, let them compete for the console_sem.
             ^^^  *OR* all of them

	     -ss

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

#1654961

On (06/01/17 16:21), Sergey Senozhatsky wrote:
> On (05/31/17 16:30), Sergey Senozhatsky wrote:
> > On (05/29/17 14:12), Jan Kara wrote:
> > [..]
> > > Actually I had something very similar in old versions of my patch set. And
> > > it didn't work very well. The problem was that e.g. sometimes scheduler
> > > decided that printk kthread should run on the same CPU as the process
> > > currently doing printing and in such case printk kthread never took over
> > > printing and the machine locked up due to heavy printing.
> > 
> > hm, interesting.
> 
> that's a tricky problem to deal with.
> 
> 
> 
> ... so may be we can have per-CPU printk kthreads then
> 
> 	static DEFINE_PER_CPU(struct task_struct *, printk_kthread);
> 
> 
> SMP hotplug threads, to be precise, the same way as watchdog has it. and
> then during offloading we can wake_up any printk_kthread that is knowingly
> not from this-CPU, all of them, let them compete for the console_sem.
> 
> just a quick idea.
> 
> thoughts?

and we, of course, can provide a user space knob to enforce cpumask
of printk_kthreads, if someone doesn't want to have too many printk
kthreads (e.g. a system with 200 CPUs). so we can wake_up printk_kthread
only on given CPUs.

so I hacked a quick and dirty version of printing offloading using smp
threads, ran some tests and it seems to work better then the version
with a single printk_kthread.

overall this looks like the right direction. to me. well, I may be
wrong.

	-ss

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

#1653916

Hello Petr,

On (05/29/17 11:29), Petr Mladek wrote:
[..]
> > +static inline bool console_offload_printing(void)
> > +{
> > +	static struct task_struct *printing_task;
> > +	static unsigned long long lines_printed;
> > +	static unsigned long saved_csw;
> > +
> > +	if (!printk_offloading_enabled())
> > +		return false;
> > +
> > +	if (system_state != SYSTEM_RUNNING || oops_in_progress)
> > +		return false;
> 
> Wow, I really like this test. I was not aware of this variable.
> 
> Well, I would allow to use the offload also during boot.
> We have reports when softlockups happened during boot.

hm, interesting. I guess we can tweak this part. e.g.
	"if system_stat > SYSTEM_RUNNING then return false"

> > +	/* A new task - reset the counters. */
> > +	if (printing_task != current) {
> > +		lines_printed = 0;
> > +		printing_task = current;
> > +		saved_csw = current->nvcsw + current->nivcsw;
> > +		return false;
> > +	}
> > +
> > +	lines_printed++;
> > +	if (lines_printed < atomic_print_limit)
> > +		return false;
> > +
> > +	if (current == printk_kthread) {
> > +		/*
> > +		 * Reset the `lines_printed' counter, just in case if
> > +		 * printk_kthread is the only process left that would
> > +		 * down() console_sem and call console_unlock().
> > +		 */
> > +		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
> > +	 * reasonably and sufficiently large.
> > +	 */
> > +	if (lines_printed > 10 * (unsigned long long)atomic_print_limit &&
> > +			saved_csw == (current->nvcsw + current->nivcsw)) {
> > +		printk_enforce_emergency = true;
> > +		pr_crit("Declaring printk emergency mode.\n");
> > +		return false;
> > +	}
> 
> This is interesting way how to detect that the system is in the
> emergency state. The question is how reliable it is.
> 
> It might work only if the waken printk kthread is scheduled in a predictable
> time period.

yep.

> You try to achieve this by setting read time priority

yes, that's the reason.

> (4th patch of this patchset). The question is how this would work:

> First, the real time priority is questionable on its own. Logging
> is important but the real time priority is dangerous. Any "flood"
> of messages will starve all other processes with normal priority.
> It is better than a softlockup but it might cause problems as well.

so I try to minimize the negative impact of RT prio here. printk_kthread
is not special any more. it's an auxiliary kthread that we sometimes
wake_up. the thing is that printk_kthread also must offload at some
point, basically the same `atomic_print_limit' limit applies to it as
well. I think I made a mistake by resetting `lines_printed' in
'current == printk_kthread' branch. what I meant to do was

	if (current == printk_kthread) {
		/*
		 * Do not reset `lines_printed' counter. Force
		 * printk_kthread to offload printing once it goes above
		 * the `atomic_print_limit' limit, but avoid
		 * `printk_enforce_emergency'. `printk_kthread' might be
		 * the only process left that would down() console_sem and
		 * call console_unlock().
		 */
		lines_printed--;
		return true;
	}

so `printk_kthread' will try to up()/down() console_sem once it reached
`atomic_print_limit'. just like any other process.

> Third, if the console_trylock() fails below, it is not guaranteed that
> the other waiter will really continue printing. The console_trylock()
> would fail because someone else called console_lock(), failed to get it,
> and went into sleep. There is no guarantee that it will be waken
> once again.

please explain, why wouldn't it? we call up() after every line we print
once the task exceeds `atomic_print_limit'. you mean there probably
won't be any tasks in console_sem wait list? just for that case we have
'if (current == printk_kthread)' branch. `printk_kthread' can indeed be
the one and only task to down() the console_sem.

>       + slow => async =>
> 		+ might be far behind
> 		+ loosing messages
> 		+ showing only ones with high log level
> 		+ possible softlockup
> 		+ not guaranteed when dying

yeah. good summary. the previous async printk implementation...
we officially hate it now.

[..]
> The patch tries to reduce the negative impact by detecting when
> the negative impact is visible and switching back to the sync mode.

um, sorry, no. or I simply don't follow. the patch keeps the existing sync
mode and switches to async mode when the problem probably can show up. we
don't work in async mode by default. only when task reaches atomic_print_limit.

[..]
>   + I would suggest to detect flood of messages by a difference
>     between log_next_seq and console_seq. We could take into
>     account the number of messages in the buffer
>     (log_next_seq - log_first_seq)

yeah, I think I already posted a patch that would do exactly this
thing. the problem with printk flood is that it's hard to do the
right thing. if you have just one flooding CPU then yes, forcing
that CPU to printk its messages is a good thing. but if you have
at least 2 CPUs flooding logbuf then we can't do anything. if you
force one CPU to print logbuf messages, the other CPU is still
enjoying the benefits and pleasures of fast printk path (just log_store())
which most likely results in lost messages anyway.

> In addition, I think that a semi-sync-async mode might better
> handle the sudden dead. What is it? I have already talked about
> something similar last time.

but this is what the patch does. but default we are in sync mode.
assuming that `atomic_print_limit' is large enough it can take
seconds before we offload printing to printk_kthread. so that
semi-sync-async is what we are trying to have. am I missing something?

and that's why I'm *a bit* (just *really a bit*) less concerned about cases
that we missed. I expect that `atomic_print_limit' usually will be around
thousands of lines, if not tens of thousands, giving enough time to sync
printing.

> Normal printk() should do something like:
> 
>   printk()
>     vprintk_emit()
>       log_store()
>       if (!deferred)
> 	console_trylock()
> 	console_unlock()
> 	  while (num_lines < atomic_print_limit)
> 	    handle message
> 	  up_console_sem()
> 	  if (pending_messages)
> 	    wakeup(printk_kthread)

this is close to what we do. at the same we have better guarantees.
we don't just wakeup(printk_kthread) and leave. we wait for any other
process to re-take the console_sem. until this happens we can't leave
console_unlock().


> and printk_kthread should do:
> 
>    while() {
> 
>        if (!pending_messages)
> 	 sleep()
> 
>        console_lock()
> 
>        preempt_disable()
>        console_unlock()
> 	 while (pending_message && !need_resched)
> 	   handle message
> 	 up_console_sem()
>        preempt_enable()
>     }

hm. I don't want printk_kthread to be special. just because there are cases
when printk_kthread won't be there. we had too many problems with relying on
printk_kthread in all the corner cases. I want printk_kthread to be just one
extra process that can do the printing for us. if we have X tasks sleeping in
UNINTERRUPTIBLE on console_sem then we better use them; keeping them
in UNINTERRUPTIBLE as long as printk_kthread has pending messages does
no good. those can be user spaces processes missing user-space watchdog's
heartbeat signals, etc. etc. or there can be another process that calls
printk way to often and basically floods logbuf. so printk_kthread will
give it a chance to successfully lock the console_sem and slow down a bit.

so the current logic is

1) we print messages synchronously. up until `atomic_print_limit'. when
  we reach `atomic_print_limit' we keep printing messages synchronously,
  but at the same time we begin asking for help from other processes.
  one of those other processes is printk_kthread. but we don't go all
  in, it doesn't work, and we make sure that one of those 'other processes'
  actually locked console_sem.

2) printk_kthread does the same as any other process. see 1)


> By other words:
> 
>   + printk() should try to get console and handle few lines
>     synchronously. It will handle its own message in most cases.
> 
>   + printk_kthread is only a fallback. It is waken when there are
>     unhandled messages. It handles as many messages as
>     possible in its assigned time slot. But it releases
>     console_sem before it goes into sleep.
> 
> 
> The advantages:
> 
>    + all messages are handled synchronously if there is not
>      a flood of messages
> 
>    + if there is the flood of messages; kthread works only
>      as a fallback; processes that produce the messages
>      are involved into handling the console (nature throttling);
>      the messages appear on the console even when printk_kthread
>      is sleeping; but the softlockup is prevented
> 
> => it should work pretty well in all situations, including the flood
>    of messages and sudden dead.
> 
> What do you think, please?

need to think more.

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web