Re: [PATCH v12 0/3] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello,

On (07/12/16 18:28), Petr Mladek wrote:
> I have tried the following:
> 
>        int a,b;
> 
>        for (a = 0; a < 1000; a++) {
>                for (b = 0; b < 10; b++) {
>                        pr_cont("item%04d", a*10 + b);
>                }
>                pr_cont("\n");
>        }
> 
> 
> [ 4913.000298] item8740item8741item8742item8743item8744item8745item8746item8747item8748item8749
> [ 4913.000310] item8750item8751item8752item8753item8754item8755item8756item8757item8758item8759
> [ 4913.000327] item8760item8761item8762item8763item8764item8765item8766item8767item8768item8769
> [ 4913.000342] item8770item8771item8772item8773item8774item8775item8776item8777item8778item8779
> [ 4913.000356] item8780
> [ 4913.000357] item8781
> [ 4913.000358] item8782
> [...]

hm.. so are there any 'concurrent' printk()-s coming from other CPUs
that are not getting printed on the console (because of loglevel restrictions),
but still screw up the cont buffer?.... otherwise, my expectation was that in
this particular case cpu issues a new pr_cont() only after it has printed
the current message via call_console_drivers()->write(). so partially flushed
cont buffer was not really expected to happen. I was wrong, obviously.

> > KERN_CONT output is heavily relying on the fact there will be no other
> > CPU(-s)/process(-es) doing any sort (KERN_CONT etc.) of printk-s simultaneously.
> > This basically means that pr_cont() CPU is expected to be the one that actually
> > does the printing and log_store() of the entire cont buffer:
> 
> In particular, the partially flushed cont buffer could not be used for new
> messages until the rest of it is flushed to the console. It is because
> the number of flushed characters is stored in the struct cont.
> > 	pr_cont()
> > 		console_unlock()
> > 			console_cont_flush()
> > 			log_store()	/* cont buffer */
> > 	pr_cont()
> > 		console_unlock()
> > 			console_cont_flush()
> > 			log_store()	/* cont buffer */
> > 	....
> > 
> > Async printk breaks this contract, because console_cont_flush() is now deferred.
> > Thus pr_cont() will see a not fully flushed cont buffer, which will force it to
> > append a new KERN_CONT not to cont buffer, but to buffer log as a separate log
> > entry via log_store(). Due to the deferred nature of console_cont_flush() the
> > very next pr_cont() may see cont buffer being flushed, so it will keep the
> > message in the cont buffer and log_store() it later. So the cont line will split
> > across several log entries -- printk_kthread can take some time to wkeup,
> > during which pr_cont() will keep splitting cont line:
> 
> I guess that the problem was there even before async printk. For
> example, we do not keep lockbuf_lock between console_cont_flush()
> and printing other lines from the ring buffer. It means that
> new lines might appear in the buffer in the meantime.
> 
> Note that we call consoles in console_cont_flush() without
> lockbuf_lock. So there is relatively long time for the race.
> 
[...]
> Another solution would be to remember cont.cons outside
> of struct cont. Then the cont buffer could be reused
> immediately.

just an idea.
... or try to make KERN_CONT SMP-safe. there are many pr_cont() call
sites. ACPI is one notable example. the others include OOM, some cgroup
related output (or... was it memcg), etc., etc.

so we *may be* can have a per-cpu cont buffer and add new API
pr_cont_begin()/pr_cont_end(), that would disable preemption.


+	pr_cont_begin() /* preempt_disable() */

	for (.....)
		pr_cont("%pS ....);

+	pr_cont_end() /* preempt_enable() */

pr_cont_end() also can flush this CPU's cont buffer and store the log
line. this will probably break very long cont lines (not sure if we
have any of those though). and may be flush_on_panic() would have to
do some extra work iterating each cpu.

> The saved position will be used either for the actual
> cont buffer or for the very first message in the ring
> buffer. The situation might be detected by comparing
> console_seq, log_next_seq, and log_first_seq.

we still can have pr_cont() happening on several cpus simultaneously.
console_seq is getting reset, when we register a new CON_PRINTBUFFER
console.

> if (console_seq == log_next_seq)
>    cont buffer still includes the very last message
> 
> if (console_seq < log_first_seq)
>    the message was lost => no partialy flushed message around
> 
> if (console_seq < log_next_seq && cont.cons)
>    the current message in the log buffer is partially printed
> 
> 
> Well, this looks quite complicated. And I am afraid that
> I have missed something.
> 
> I am still scratching my head around it.

	-ss