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

[Sergey Senozhatsky]

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