Re: [PATCH v5 0/2] printk: Console owner and waiter logic cleanup

[Steven Rostedt <rostedt@goodmis.org>]

On Sat, 13 Jan 2018 16:28:34 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> On (01/12/18 07:21), Steven Rostedt wrote:
> [..]
> > Yep, but I'm still not convinced you are seeing an issue with a single
> > printk.  
> 
> what do you mean by this?

I'm not sure your issues happen because a single printk is locked up,
but you have many printks in one area.

> 
> > An OOM does not do everything in one printk, it calls hundreds.
> > Having hundreds of printks is an issue, especially in critical sections.  
> 
> unless your console_sem owner is preempted. as long as it is preempted
> it doesn't really matter how many times we call printk from which CPUs
> and from which sections, but what matters - who is going to print that all
> out when console_sem is running again and how much time will it take.
> that's what I'm saying.

OK, if this is an issue, then we could do:

	preempt_disable();
	if (console_trylock_spinning())
		console_unlock();
	preempt_enable();

Which would prevent any printks from being preempted, but allow for
other console_lock owners to be so.


> 
> [..]
> > > with slow serial console, call_console_drivers() takes enough time to
> > > to make preemption of a current console_sem owner right after it irqrestore()
> > > highly possible; unless there is a spinning console_waiter. which easily may
> > > not be there; but can come in while current console_sem is preempted, why not.
> > > so when preempted console_sem owner comes back - it suddenly has a whole bunch
> > > of new messages to print and on one to hand off printing to. in a super
> > > imperfect and ugly world, BTW, this is how console_unlock() still can be
> > > O(infinite): schedule between the printed lines [even !PREEMPT kernel tries  
> > 
> > I'm not fixing console_unlock(), I'm fixing printk().  
> 
> I know. I'm fixing console_unlock(). because console_unlock() is its own
> thing.
> 
> > > 4) the interesting thing here is that call_console_drivers() can
> > >    cause console_sem owner to schedule even if it has handed off the
> > >    ownership. because waiting CPU has to spin with local IRQs disabled
> > >    as long as call_console_drivers() prints its message. so if consoles
> > >    are slow, then the first thing the waiter will face after it receives
> > >    the console_sem ownership and enables the IRQs is - preemption.  
> > 
> > If the waiter is preempted, that means its not in a critical section.
> > Isn't that what you want?  
> 
> see below.
> 
> > >    so hand off is not immediate. there is a possibility of re-scheduling
> > >    between hand off and actual printing. so that "there is always an active
> > >    printing CPU" is not quite true.
> > > 
> > > vprintk_emit()
> > > {
> > > 
> > > 	console_trylock_spinning(void)
> > > 	{
> > > 	   printk_safe_enter_irqsave(flags);
> > > 	   while (READ_ONCE(console_waiter))       // spins as long as call_console_drivers() on other CPU
> > > 	        cpu_relax();
> > > 	   printk_safe_exit_irqrestore(flags);  
> > > --->	}    
> > > |						   // preemptible up until printk_safe_enter_irqsave() in console_unlock()  
> > 
> > Again, this means the waiter is not in a critical section. Why do we
> > care?  
> 
> which is not what I was talking about. the point was that you said

And would be fixed with the preempt_disable() I added above.

> 
> 
>  :                                                .... and what about the
>  : printks that haven't gotten out yet? Delay them to something else, and
>  : if the machine were to crash in the transfer, we lost all that data.
>  :
>  : My method, there's really no delay between a hand off. There's always
>  : an active CPU doing printing. It matches the current method which works
>  : well for getting information out. A delayed approach will break that
> 
> 
> that is not true. we can have preemption "during" hand off. hand off,
> thus, is a "delayed approach", by definition. so if you consider the
> possibility of "if the machine were to crash in the transfer, we lost
> all that data" and if you consider this to be important [otherwise you
> wouldn't bring that up, would you] then the reality is that your patch
> has the same problem as printk_kthread.

With the preempt_disable() there really isn't a delay. I agree, we
shouldn't let printk preempt (unless we have CONFIG_PREEMPT_RT enabled,
but that's another story).

> 
> so very schematically, for hand-off it's something like
> 
> 	if (... console_trylock_spinning()) // grabbed the ownership
> 
> 		<< ... preempted ... >>
> 
> 		console_unlock();

Which I think we should stop, with the preempt_disable().

> 
> 
> for printk_kthread it's something like
> 
> 		wake_up_process(printk_kthread);
> 		up(console_sem);
> 
> 
> in the later case we at least have console_sem unlocked. so any other CPU
> that might do printk() can grab the lock and emit the logbuf messages. but
> in case on hand-off, we have console_sem locked, so no printk() will be
> able to emit the messages, we need that specific task to become running.
> 
> 
> hence the following:
> 
> [..]
> > > reverting 6b97a20d3a7909daa06625d4440c2c52d7bf08d7 may be the right
> > > thing after all.  
> 
> this was cryptic and misleading. sorry.
> some clarifications.
> 
> what I meant was that with 6b97a20d3a7909daa06625d4440c2c52d7bf08d7
> I think I badly broke printk() [some of paths]. I know what I tried

I think adding the preempt_disable() would fix printk() but let non
printk console_unlock() still preempt.

> to fix (and you don't have to explain to me what a lock up is) with
> that patch, but I don't think the patch ended up to be a clear win.
> a very simple explanation would be:
> 
> instead of having a direct nonpreemptible path
> 
> 	logbuf -> for(;;) call_console_drivers -> happy user
> 
> we now have
> 
> 	logbuf -> for(;;) { call_console_drivers, scheduler ... ???} -> happy user
> 
> which is a big change. with a non-zero potential for regressions.
> and it didn't take long to find out that not all "happy users" were
> exactly happy with the new scheme of things. glance through Tetsuo's
> emails [see links in my another email], Tetsuo reported that printk can
> stall for minutes now. basically, the worse the system state is the lower
> printk throughput can be [down to zero chars in the worst case]. that's
> why I think that my patch was a mistake. and that's why in my out-of-tree
> patches I'm moving towards the non-preemptible path from logbuf through
> console to a happy user [just like it used to be]. but, obviously, I can't
> just restore preempt_disable()/preempt_enable() in vprintk_emit(). that's
> why I bound console_unlock() to watchdog threshold and move towards the
> batched non-preemptible print outs (enabling preemption and up()-ing the
> console_sem at the end of each print out batch). this is not super good,
> preemption is still here, but at least not after every line console_unlock()
> prints. up() console_sem also increases chances that, for instance, systemd
> or any other task that is sleeping in TASK_UNINTERRUPTIBLE on console_sem
> now has a chance to be woken up sooner (not only after we flush all pending
> logbuf messages and finally up() the console_sem).

I rather try simpler approaches first (like adding the preempt_disable()
on top of my patch) than an elaborate scheme of printk_kthreads.

-- Steve