Re: [RFC][PATCHv6 00/12] printk: introduce printing kernel thread

[Steven Rostedt]

On Fri, 15 Dec 2017 14:06:07 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@xxxxxxxxx> wrote:

> Hello,
> 
> On (12/14/17 22:18), Steven Rostedt wrote:
> > > Steven, your approach works ONLY when we have the following preconditions:
> > > 
> > >  a) there is a CPU that is calling printk() from the 'safe' (non-atomic,
> > >     etc) context
> > > 
> > >         what does guarantee that? what happens if there is NO non-atomic
> > >         CPU or that non-atomic simplky missses the console_owner != false
> > >         point? we are going to conclude
> > > 
> > >         "if printk() doesn't work for you, it's because you are holding it wrong"?
> > > 
> > > 
> > >         what if that non-atomic CPU does not call printk(), but instead
> > >         it does console_lock()/console_unlock()? why there is no handoff?

The case here, you are talking about a CPU doing console_lock() from a
non printk() case. Which is what I was asking about how often this
happens.

As for why there's no handoff. Does the non printk()
console_lock/unlock ever happen from a critical location? I don't think
it does (but I haven't checked). Then it is the perfect candidate to do
all the printing.


> > > 
> > >         CPU0				CPU1 ~ CPU10
> > > 					in atomic contexts [!]. ping-ponging console_sem
> > > 					ownership to each other. while what they really
> > > 					need to do is to simply up() and let CPU0 to
> > > 					handle it.
> > > 					printk
> > > 	console_lock()
> > > 	 schedule()
> > > 					...
> > > 					printk
> > > 					printk
> > > 					...
> > > 					printk
> > > 					printk
> > > 
> > > 					up()
> > > 
> > > 	// woken up
> > > 	console_unlock()
> > > 
> > >         why do we make an emphasis on fixing vprintk_printk()?  
> > 
> > Where do we do the above? And has this been proven to be an issue?  
> 
> um... hundreds of cases.

I was asking about doing the console_unlock from not printk case.

> 
> deep-stack spin_lock_irqsave() lockup reports from multiple CPUs (3 cpus)
> happening at the same moment + NMI backtraces from all the CPUs (more
> than 3 cpus) that follows the lockups, over not-so-fast serial console.
> exactly the bug report I received two days ago. so which one of the CPUs
> here is a good candidate to successfully emit all of the pending logbuf
> entries? none. all of them either have local IRQs disabled, or dump_stack()
> from either backtrace IPI or backtrace NMI (depending on the configuration).
> 

Is the above showing an issue of console_lock happening in the non
printk() case?

> 
> do we periodically do console_lock() on a running system? yes, we do.
> add to console_unlock()

Right, and the non printk() console_lock() should be fine to do all
printing when it unlocks.

> 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index b9006617710f..1c811f6d94bf 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2143,6 +2143,10 @@ void console_unlock(void)
>         bool wake_klogd = false;
>         bool do_cond_resched, retry;
>  
> +       if (!(current->flags & PF_KTHREAD))
> +               dump_stack();
> +
> +
>         if (console_suspended) {
>                 up_console_sem();
>                 return;
> 
> ---
> 
> and just boot the system.
> 
> 
> I work for a company that has several thousand engineers spread
> across the globe. and people do use printk(), and issues do happen.

Sure, and I still think my patch is good enough.

> 
> the scenarios that Tejun and I talk about are not theoretical. if those
> scenarios are completely theoretical, as you suggest, - then, OK, what
> exactly guarantees that

And I still think my patch is good enough.

> 
> 	whenever atomic CPUs printk there is always a non-atomic
> 	CPU to take over the printing?

No, and I don't think it has to.

> 
> 
> 
> > >  b) non-atomic CPU sees console_owner set (which is set for a very short
> > >     period of time)
> > > 
> > >         again. what if that non-atomic CPU does not see console_owner?
> > >         "don't use printk()"?  
> > 
> > May I ask, why are we doing the printk in the first place?  
> 
> this argument is really may be applied against your patch as well. I
> really don't want us to have this type of "technical" discussion.

Sure, but my patch fixes the unfair approach that printk currently does.

> 
> printk() is a tool for developers. but developers can't use.
> 
> 
> > >  c) the task that is looping in console_unlock() sees non-atomic CPU when
> > >     console_owner is set.  
> > 
> > I haven't looked at the latest code, but my last patch didn't care
> > about "atomic" and "non-atomic"  
> 
> I know. and I think it is sort of a problem.

Please show me the case that it is. And don't explain where it is.
Please apply the patch and have the problem occur and show it to me.
That's all that I'm asking for.

> 
> lots of printk-s are happening from IRQs / softirqs and so on.
> take a look at CONFIG_IP_ROUTE_VERBOSE, for example.

Yep, understood.

> 
> do_softirq() -> ip_handle_martian_source() and a bunch of other
> places. 
> these irq->printk-s can "steal" the console_sem and go to
> console_unlock().
> 
> "don't use printk() then" type of argument does not really help
> to a guy who reports the lockup.

Heh, one argument at a time. The "don't use printk" comes later. Right
now, I want to see the problem that is not fixed by my patch.


> 
> 
> > > Steven, I thought we reached the agreement [**] that the solution we should
> > > be working on is a combination of prinkt_kthread and console_sem hand
> > > off. Simply because it adds the missing "there is a non-atomic CPU wishing
> > > to console_unlock()" thing.
> > > 
> > > 	lkml.kernel.org/r/20171108162813.GA983427@xxxxxxxxxxxxxxxxxxxxxxxxxxx
> > > 
> > > 	https://marc.info/?l=linux-kernel&m=151011840830776&w=2
> > > 	https://marc.info/?l=linux-kernel&m=151015141407368&w=2
> > > 	https://marc.info/?l=linux-kernel&m=151018900919386&w=2
> > > 	https://marc.info/?l=linux-kernel&m=151019815721161&w=2
> > > 	https://marc.info/?l=linux-kernel&m=151020275921953&w=2
> > > **	https://marc.info/?l=linux-kernel&m=151020404622181&w=2
> > > **	https://marc.info/?l=linux-kernel&m=151020565222469&w=2  
> > 
> > I'm still fine with the hybrid approach, but I want to see a problem
> > first before we fix it.
> >   
> > > 
> > > 
> > > what am I missing?  
> > 
> > The reproducer.  
> 
> will that printk_test module
> 
>   lkml.kernel.org/r/20171204135314.9122-2-sergey.senozhatsky@xxxxxxxxx
> 
> suffice?

No, because it is unrealistic. For example:

+static void test_noirq_console_unlock(void)
+{
+       unsigned long flags;
+       unsigned long num_messages = 0;
+
+       pr_err("=== TEST %s\n", __func__);
+
+       num_messages = 0;
+       console_lock();
+       while (num_messages++ < max_num_messages)
+               pr_info("=== %s Append message %lu out of %lu\n",
+                               __func__,
+                               num_messages,
+                               max_num_messages);
+
+       local_irq_save(flags);
+       console_unlock();

Where in the kernel do we do this?

Where do we take console_lock() under preemptible context and then
release it under non preemptible context besides in printk?

You just manufactured a scenario that my patch does not cover, because
it only covers printk() console lock an unlock because that printk is a
known state.

I'm looking for real scenarios in a production kernel.

-- Steve




+       local_irq_restore(flags);
+}