Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

[Sergey Senozhatsky]

On (10/05/16 11:50), Petr Mladek wrote:
[..]
> > well, it solves a number of problems that the existing implementation
> > cannot handle.
> 
> Please, provide a summary. I wonder if these are real life problems.

anything that starts from printk().
I'm trying to address printk() recursion only, by handling the top-most
recursion - printk -> printk, which causes all of the dependent recursions:
	printk -> spin_lock(logbuf) -> printk() -> spin_lock(logbuf)
	printk -> sem->lock() -> printk() -> sem->lock()
and so on.

I'm not building a lock dependency graph/etc.


the existing recursion detection logic is racy and quite limited in
scope: not only it protects only a tiny bit of printk, but it doesn't
even protect it fully. the very moment we do `logbuf_cpu = UINT_MAX;'
it's over - we still own the lock, but we don't remember it anymore.
a spin_dump() from raw_spin_unlock(&logbuf_lock) will kill us.


** a very quick list **
// a mixed list of theoretical and real problems can also be found
// in the patch set cover letter.


public reports:

1) some pathces/reports from Byungchul Park

the first one in my mailbox (seems to be)
https://marc.info/?l=linux-kernel&m=145406977822244
20160129121545.GH31266@X58A-UD3R

or here
https://marc.info/?l=linux-kernel&m=145570036513749

in his case, I believe, the lock was fine (not corrupted). it just he had
a spin_lock lockup on console semaphore spin_lock coming from:

static void __spin_lock_debug(raw_spinlock_t *lock)
{
	u64 i;
	u64 loops = loops_per_jiffy * HZ;

	for (i = 0; i < loops; i++) {
		if (arch_spin_trylock(&lock->raw_lock))
			return;
		__delay(1);
	}
	/* lockup suspected: */
	spin_dump(lock, "lockup suspected");


which ended up in an infinite recursion.

https://marc.info/?l=linux-kernel&m=145449014308161



2) a report from Viresh Kumar.

frankly, we were lucky to have Viresh on this: a less experienced developer
would probably give up. So would probably do a developer with no appropriate
hardware: jtag debugger/serial console/etc. and I don't know how much would
we spend on meditations to figure out it was a WARN from timekeeping. we
better be 'more prepared'.


=======
reports (unique occurrences only) that I have in internal bugzilla

4) sleeping function called from inside logbuf lock
   which resulted in spin_dump() call from spin_unlock(&logbuf_lock)
   when:
	a) we still owned the logbuf_lock
	b) yet logbuf_cpu was already reset, so printk recursion
	detection was helpless

   'a + b' leave us no chances to survive.

5) ARM specific
   an imprecise abort (http://infocenter.arm.com/help/topic/com.arm.doc.faqs/14809.html)
   hit the CPU while it was holding the printk-related spin-lock.
   that deadlocked the system, because abort handler attempted to
   printk() a message.


6) logbuf_lock corruption
   well, no cookies for us. un-fixable at the moment. we can probably
   do something about it. have a spinlock-debug bool function that would
   tell us whether the lock is corrupted, so we can re-init logbuf_lock,
   perhaps.


> Note that we need to put aside all problems that are solvable
> with printk_deferred(). It seems that printk_deferred() will
> need to stay because it avoids the deadlock caused by
> scheduler/timekeeping code locks.

agree. printk_deferred() takes only one lock and avoids console_unlock()
loop. as long as logbuf_lock is not on it's way printk_deferred() may be
helpful.

> By other words, if there is a missing printk_deferred() we
> need to put it there anyway because the same code might get
> first called outside printk().

right. and I'm not addressing this. there are just too many locks
that can be acquired out of order. not only timekeeping and sched
locks, but any of serial console locks adn so on. we need something
like lockdep locks graph here that would not report the issues (any
printk() can result in deadlock when we detect that at least one of
printk related locks was acquired out of order), but instead would
somehow selectively fix/workaround them.


can we somehow transparently for the rest of the system (just in
printk()) detect that we are in a potentially risky situation? hmm,
I don't know...

something *very* radical?

	vprintk_func()
	{
		if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_NMI_CONTEXT_MASK)
		return vprintk_nmi(fmt, args);

		if (in_atomic() ||
		/* ^^^^^^^^^^^^ */
			this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK)
			return vprintk_alt(fmt, args);

		return vprintk_default(fmt, args);
	}

	-ss