Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello Petr,

On (03/22/16 14:11), Petr Mladek wrote:
[..]
> > -	/* cpu currently holding logbuf_lock in this function */
> > -	static unsigned int logbuf_cpu = UINT_MAX;
> > +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
> > +	bool sync_print = printk_sync;
> 
> I still think that this local variable adds more mess than good.
> Please, rename it to do_printk_sync at least. It will a poor human
> to distinguish it from the global one ;-)

ok, I'll take a look :)

> > +	 * Set printing_func() sleep condition early, under the @logbuf_lock.
> > +	 * So printing kthread (if RUNNING) will go to console_lock() and spin
> > +	 * on @logbuf_lock.
> > +	 */
> > +	if (!printk_sync)
> > +		need_flush_console = true;
> 
> We set this variable for each call and also when printk_kthread is
> NULL or when sync_printk is false.

hm, yes. (printk_kthread && !need_flush_console) makes more sense.
so we it doesn't get re-dirty if already set.

> We migth want to clear it also from console_unlock(). I think that
> a good place would be in the check:
> 
> 	raw_spin_lock(&logbuf_lock);
> 	retry = console_seq != log_next_seq;
> 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);

hm, what's wrong with clearing it in printk_kthread  printing function?

> > +	if (!sync_print) {
> > +		if (in_sched) {
> > +			/*
> > +			 * @in_sched messages may come too early, when we don't
> > +			 * yet have @printk_kthread. We can't print deferred
> > +			 * messages directly, because this may deadlock, route
> > +			 * them via IRQ context.
> > +			 */
> > +			__this_cpu_or(printk_pending,
> > +					PRINTK_PENDING_OUTPUT);
> > +			irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> > +		} else if (printk_kthread && !in_panic) {
> > +			/* Offload printing to a schedulable context. */
> > +			wake_up_process(printk_kthread);
> > +		} else {
> > +			sync_print = true;
> > +		}
> > +	}
> >  	local_irq_restore(flags);
> 
> Please, what is the exact reason to call the above stuff before
> we release IRQs here? I guess that it is related to the discussions
> about possible lock debugging, infinite loops, ...
> 
> I wonder how the disabled IRQs help here. It is very likely that I
> miss something.

with IRQs enabled we have preemption enabled, so this thing

        __this_cpu_or(printk_pending,
                        PRINTK_PENDING_OUTPUT);
        irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));

can set pending and queue irq_work on different CPUs.

using "this_cpu = smp_processor_id()" which is taken right after
local_irq_save(flags) at the beginning of vprintk_emit() is not an
option - once we enable preemption CPUs are free to go offline. so
this thing wants to be under preemption disable(), and local_irq_save()
gives us it.

well, I can do

        + preempt_disable()
        + local_irq_restore()

        if (!sync_print) {
        ...
                __this_cpu_or()
                irq_work_queue()
        ...
        }
        - local_irq_restore()
        + preempt_enable()

but

> In each case, irq_work_queue() is lock-less and was used with IRQs
> enabled before.
> 
> So, it might be related to wake_up_process(). It takes a lock but
> using
> 
>        raw_spin_lock_irqsave(&p->pi_lock, flags);

wake_up_process disables IRQs in the beginning anyway.
so we have

        local_irq_restore()
        local_irq_save()

which is sort of nasty. disabling IRQs can be a bit expensive, not
that printk is that hot path, but I wanted to avoid additional latencies
that can happen due to IRQ enable-disable ping-pong.

> , so it disables IRQs in the critical section. Do we need to guard
> it in between?
> 
> I think that you actually wanted to disable lockdep or any other lock
> debugging, instead.

preemption.

well, disabling lockdep is may be a good thing to do as well...

> 	if (in_sched) {
> 		/*
> 		 * @in_sched messages may come too early, when we don't
> 		 * yet have @printk_kthread. We can't print deferred
> 		 * messages directly, because this may deadlock, route
> 		 * them via IRQ context.
> 		 */
> 		__this_cpu_or(printk_pending,
> 			      PRINTK_PENDING_OUTPUT);
> 		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> 		goto out;
> 	}
> 
> 	/* Avoid printk recursion */
> 	lockdep_off();
> 
> 	if  (printk_kthread && !in_panic) {
> 		/* Offload printing to a schedulable context. */
> 		wake_up_process(printk_kthread);
> 		goto out_lockdep;
> 	} else {
> 		/*
> 		 * Try to acquire and then immediately release the console
> 		 * semaphore.  The release will print out buffers and wake up
> 		 * /dev/kmsg and syslog() users.
> 		 */
> 		if (console_trylock())
> 			console_unlock();
> 	}
> 
> 	lockdep_on();
> 

ok, I'll take a look.

eventually (after 0003) vprintk_emit() is

	if (in_sched) {
		__this_cpu_or(printk_pending,
				PRINTK_PENDING_OUTPUT);
		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
	}
	local_irq_restore(flags);
	if (!in_sched) {
		lockdep_off();
		if (console_trylock())
			console_unlock();
		lockdep_on();
	}

> I do not say that it is a "dream-of-like" code. One important thing for
> me is that it does not use "sync_printk" variable.
> 
> You original code modified "sync_printk" according to "in_sched" and
> "in_panic" variables earlier in vprintk_emit. Then it again checked
> all three variables here which produced strange twists in my head ;-)

yeah, I can see your point. a bunch of goto-s can probably help here.

	-ss