On Tue 2016-08-23 14:18:31, Sergey Senozhatsky wrote:
> On (08/23/16 00:40), Sergey Senozhatsky wrote:
> > RFC and POC
> [..]
> > if (!(lflags & LOG_NEWLINE)) {
> > + if (!this_cpu_read(cont_printing)) {
> > + bool unsafe_pr_cont = preemptible() &&
> > + !rcu_preempt_depth();
>
> d'oh, how did it get there... this simply disables per-cpu pr_cont(). sorry.
> what I wanted to do there is to add a dependency on system_state:
>
> if (!this_cpu_read(cont_printing) && (system_state == SYSTEM_RUNNING)) {
> ....
> }
>
> one of the problems is x86 cpu_up, which does pr_cont()-s in announce_cpu()
> and then explicitly calls shedule() in do_boot_cpu(). so we have a
>
> pr_cont();
> shedule();
> pr_cont();
> shedule();
> ...
> pr_cont("\n");
>
> pattern. which is probably OK, given that we are in a non-smp mode yet. thus
> I'm enabling per-cpu pr_cont buffers only when the system is SYSTEM_RUNNING.
>
> ===8<====
>
> Signed-off-by: Sergey Senozhatsky <[email protected]>
> ---
> kernel/printk/printk.c | 190
> ++++++++++++++++---------------------------------
> 1 file changed, 61 insertions(+), 129 deletions(-)
The simplification is nice but...
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 0d3e026..7f48cbf 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> - return textlen;
> -}
> -
> asmlinkage int vprintk_emit(int facility, int level,
> const char *dict, size_t dictlen,
> const char *fmt, va_list args)
> @@ -1779,6 +1732,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> int printed_len = 0;
> int nmi_message_lost;
> bool in_sched = false;
> + struct cont *cont;
>
> if (level == LOGLEVEL_SCHED) {
> level = LOGLEVEL_DEFAULT;
> @@ -1789,6 +1743,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> printk_delay();
>
> local_irq_save(flags);
> + cont = this_cpu_ptr(&pcpu_cont);
> this_cpu = smp_processor_id();
>
> /*
> @@ -1878,12 +1833,19 @@ asmlinkage int vprintk_emit(int facility, int level,
> lflags |= LOG_PREFIX|LOG_NEWLINE;
>
> if (!(lflags & LOG_NEWLINE)) {
> + if (!this_cpu_read(cont_printing)) {
> + if (system_state == SYSTEM_RUNNING) {
> + this_cpu_write(cont_printing, true);
> + preempt_disable();
> + }
> + }
I am afraid that this is not acceptable. It means that printk() will have
an unexpected side effect. The missing "\n" at the end of a printed
string would disable preemption. See below for more.
> +
> /*
> * Flush the conflicting buffer. An earlier newline was missing,
> * or another task also prints continuation lines.
> */
> - if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
> - cont_flush(LOG_NEWLINE);
> + if (cont->len && (lflags & LOG_PREFIX))
> + cont_flush(cont, LOG_NEWLINE);
>
> /* buffer line if possible, otherwise store it right away */
> if (cont_add(facility, level, text, text_len))
> @@ -1895,6 +1857,11 @@ asmlinkage int vprintk_emit(int facility, int level,
> } else {
> bool stored = false;
>
> + if (this_cpu_read(cont_printing)) {
> + this_cpu_write(cont_printing, false);
> + preempt_enable();
> + }
If "\n" is missing by mistake. The preemption will not get enabled and
the task would stall.
Note that printk() is heavily used when debugging kernel. People would
hate us if every n-th build is unusable because of forgotten '\n'.
> /*
> * If an earlier newline was missing and it was the same task,
> * either merge it with the current buffer and flush, or if
> @@ -2051,7 +2018,6 @@ static struct cont {
> size_t len;
> size_t cons;
> u8 level;
> - bool flushed:1;
> } cont;
> static char *log_text(const struct printk_log *msg) { return NULL; }
> static char *log_dict(const struct printk_log *msg) { return NULL; }
> @@ -2344,42 +2310,6 @@ static inline int can_use_console(void)
> return cpu_online(raw_smp_processor_id()) || have_callable_console();
> }
>
> -static void console_cont_flush(char *text, size_t size)
> -{
> - unsigned long flags;
> - size_t len;
> -
> - raw_spin_lock_irqsave(&logbuf_lock, flags);
> -
> - if (!cont.len)
> - goto out;
> -
> - if (suppress_message_printing(cont.level)) {
> - cont.cons = cont.len;
> - if (cont.flushed)
> - cont.len = 0;
> - goto out;
> - }
> -
> - /*
> - * We still queue earlier records, likely because the console was
> - * busy. The earlier ones need to be printed before this one, we
> - * did not flush any fragment so far, so just let it queue up.
> - */
> - if (console_seq < log_next_seq && !cont.cons)
> - goto out;
> -
> - len = cont_print_text(text, size);
> - raw_spin_unlock(&logbuf_lock);
> - stop_critical_timings();
> - call_console_drivers(cont.level, NULL, 0, text, len);
> - start_critical_timings();
> - local_irq_restore(flags);
> - return;
> -out:
> - raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> -}
This is a trade off between a "perfect" output and an early output.
I do not feel like deciding about it.
In each case, a buggy line (without \n") would stay "hidden" in
the per-CPU buffer until another line with "\n" is printed
on the given CPU.
> /**
> * console_unlock - unlock the console system
> *
> @@ -2433,9 +2363,6 @@ again:
> return;
> }
>
> - /* flush buffered message fragment immediately to console */
> - console_cont_flush(text, sizeof(text));
> -
> for (;;) {
> struct printk_log *msg;
> size_t ext_len = 0;
I think that cont lines should be a corner case. There should be only
a limited use of them. We should not make too complicated things to
support them. Also printk() must not get harder to use because of them.
I still see a messed output rather as a cosmetic problem in compare with
possible possible deadlocks or hung tasks.
Best Regards,
Petr
