Re: [PATCH printk-rework 08/14] printk: add syslog_lock

Re: [PATCH printk-rework 08/14] printk: add syslog_lock

[John Ogness]

Added CC: linux-parisc@vger.kernel.org

On 2021-02-19, John Ogness <john.ogness@linutronix.de> wrote:
>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>>> index 20c21a25143d..401df370832b 100644
>>> --- a/kernel/printk/printk.c
>>> +++ b/kernel/printk/printk.c
>>> +/* Return a consistent copy of @syslog_seq. */
>>> +static u64 read_syslog_seq_irq(void)
>>> +{
>>> +	u64 seq;
>>> +
>>> +	raw_spin_lock_irq(&syslog_lock);
>>> +	seq = syslog_seq;
>>> +	raw_spin_unlock_irq(&syslog_lock);
>>
>> Is there any particular reason to disable interrupts here?
>>
>> It would make sense only when the lock could be taken in IRQ
>> context. Then we would need to always disable interrupts when
>> the lock is taken. And if it is taken in IRQ context, we would
>> need to safe flags.
>
> All other instances of locking @syslog_lock are done with interrupts
> disabled. And we have:
>
> register_console()
>   logbuf_lock_irqsave()
>     raw_spin_lock(&syslog_lock)
>
> I suppose I need to go through all the console drivers to see if any
> register in interrupt context. If not, that logbuf_lock_irqsave()
> should be replaced with logbuf_lock_irq(). And then locking
> @syslog_lock will not need to disable interrupts.

I found a possible call chain in interrupt context. From arch/parisc
there is the interrupt handler:

handle_interruption(code=1) /* High-priority machine check (HPMC) */
  pdc_console_restart()
    pdc_console_init_force()
      register_console()

All other register_console() calls in the kernel are either during init
(within __init sections and probe functions) or are clearly not in
interrupt context (using mutex, kzalloc, spin_lock_irq, etc).

I am not familiar with parisc, but I am assuming handle_interruption()
is always called with interrupts disabled (unless the HPMC interrupt is
somehow an exception).

John Ogness

Re: [PATCH printk-rework 08/14] printk: add syslog_lock

[Helge Deller]

On 2/19/21 5:33 PM, John Ogness wrote:
> Added CC: linux-parisc@vger.kernel.org
>
> On 2021-02-19, John Ogness <john.ogness@linutronix.de> wrote:
>>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>>>> index 20c21a25143d..401df370832b 100644
>>>> --- a/kernel/printk/printk.c
>>>> +++ b/kernel/printk/printk.c
>>>> +/* Return a consistent copy of @syslog_seq. */
>>>> +static u64 read_syslog_seq_irq(void)
>>>> +{
>>>> +	u64 seq;
>>>> +
>>>> +	raw_spin_lock_irq(&syslog_lock);
>>>> +	seq = syslog_seq;
>>>> +	raw_spin_unlock_irq(&syslog_lock);
>>>
>>> Is there any particular reason to disable interrupts here?
>>>
>>> It would make sense only when the lock could be taken in IRQ
>>> context. Then we would need to always disable interrupts when
>>> the lock is taken. And if it is taken in IRQ context, we would
>>> need to safe flags.
>>
>> All other instances of locking @syslog_lock are done with interrupts
>> disabled. And we have:
>>
>> register_console()
>>    logbuf_lock_irqsave()
>>      raw_spin_lock(&syslog_lock)
>>
>> I suppose I need to go through all the console drivers to see if any
>> register in interrupt context. If not, that logbuf_lock_irqsave()
>> should be replaced with logbuf_lock_irq(). And then locking
>> @syslog_lock will not need to disable interrupts.
>
> I found a possible call chain in interrupt context. From arch/parisc
> there is the interrupt handler:
>
> handle_interruption(code=1) /* High-priority machine check (HPMC) */
>    pdc_console_restart()
>      pdc_console_init_force()
>        register_console()
>
> All other register_console() calls in the kernel are either during init
> (within __init sections and probe functions) or are clearly not in
> interrupt context (using mutex, kzalloc, spin_lock_irq, etc).
>
> I am not familiar with parisc, but I am assuming handle_interruption()
> is always called with interrupts disabled (unless the HPMC interrupt is
> somehow an exception).

Yes, handle_interruption() is the irq handler, running with irqs off.
HPMC is the crash handler - it's called when the kernel will stop
anyway. pdc_console is a very basic firmware console which prints
the last messages before the machine halts on fatal errors.
So, this code it's not the typical use case....

Helge

Re: [PATCH printk-rework 08/14] printk: add syslog_lock

[Petr Mladek]

On Sun 2021-02-21 22:39:42, Helge Deller wrote:
> On 2/19/21 5:33 PM, John Ogness wrote:
> > Added CC: linux-parisc@vger.kernel.org
> > 
> > On 2021-02-19, John Ogness <john.ogness@linutronix.de> wrote:
> > > > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > > > index 20c21a25143d..401df370832b 100644
> > > > > --- a/kernel/printk/printk.c
> > > > > +++ b/kernel/printk/printk.c
> > > > > +/* Return a consistent copy of @syslog_seq. */
> > > > > +static u64 read_syslog_seq_irq(void)
> > > > > +{
> > > > > +	u64 seq;
> > > > > +
> > > > > +	raw_spin_lock_irq(&syslog_lock);
> > > > > +	seq = syslog_seq;
> > > > > +	raw_spin_unlock_irq(&syslog_lock);
> > > > 
> > > > Is there any particular reason to disable interrupts here?
> > > > 
> > > > It would make sense only when the lock could be taken in IRQ
> > > > context. Then we would need to always disable interrupts when
> > > > the lock is taken. And if it is taken in IRQ context, we would
> > > > need to safe flags.
> > > 
> > > All other instances of locking @syslog_lock are done with interrupts
> > > disabled. And we have:
> > > 
> > > register_console()
> > >    logbuf_lock_irqsave()
> > >      raw_spin_lock(&syslog_lock)
> > > 
> > > I suppose I need to go through all the console drivers to see if any
> > > register in interrupt context. If not, that logbuf_lock_irqsave()
> > > should be replaced with logbuf_lock_irq(). And then locking
> > > @syslog_lock will not need to disable interrupts.
> > 
> > I found a possible call chain in interrupt context. From arch/parisc
> > there is the interrupt handler:
> > 
> > handle_interruption(code=1) /* High-priority machine check (HPMC) */
> >    pdc_console_restart()
> >      pdc_console_init_force()
> >        register_console()
> > 
> > All other register_console() calls in the kernel are either during init
> > (within __init sections and probe functions) or are clearly not in
> > interrupt context (using mutex, kzalloc, spin_lock_irq, etc).
> > 
> > I am not familiar with parisc, but I am assuming handle_interruption()
> > is always called with interrupts disabled (unless the HPMC interrupt is
> > somehow an exception).
> 
> Yes, handle_interruption() is the irq handler, running with irqs off.
> HPMC is the crash handler - it's called when the kernel will stop
> anyway. pdc_console is a very basic firmware console which prints
> the last messages before the machine halts on fatal errors.
> So, this code it's not the typical use case....

Thanks for information.

Is this code supposed to work only during early boot or anytime,
please?

Note that it is not safe because register_console() takes
console_lock() which is a sleeping lock.

That said, we are going to rework the console handling a lot. We are
trying to remove as many locks from the printk path as possible.
I guess that the list of consoles will be synchronized using
rcu at the end. But it is still a long way to go.

Best Regards,
Petr

Re: [PATCH printk-rework 08/14] printk: add syslog_lock

[Helge Deller]

On 2/22/21 5:28 PM, Petr Mladek wrote:
> On Sun 2021-02-21 22:39:42, Helge Deller wrote:
>> On 2/19/21 5:33 PM, John Ogness wrote:
>>> Added CC: linux-parisc@vger.kernel.org
>>>
>>> On 2021-02-19, John Ogness <john.ogness@linutronix.de> wrote:
>>>>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>>>>>> index 20c21a25143d..401df370832b 100644
>>>>>> --- a/kernel/printk/printk.c
>>>>>> +++ b/kernel/printk/printk.c
>>>>>> +/* Return a consistent copy of @syslog_seq. */
>>>>>> +static u64 read_syslog_seq_irq(void)
>>>>>> +{
>>>>>> +	u64 seq;
>>>>>> +
>>>>>> +	raw_spin_lock_irq(&syslog_lock);
>>>>>> +	seq = syslog_seq;
>>>>>> +	raw_spin_unlock_irq(&syslog_lock);
>>>>>
>>>>> Is there any particular reason to disable interrupts here?
>>>>>
>>>>> It would make sense only when the lock could be taken in IRQ
>>>>> context. Then we would need to always disable interrupts when
>>>>> the lock is taken. And if it is taken in IRQ context, we would
>>>>> need to safe flags.
>>>>
>>>> All other instances of locking @syslog_lock are done with interrupts
>>>> disabled. And we have:
>>>>
>>>> register_console()
>>>>     logbuf_lock_irqsave()
>>>>       raw_spin_lock(&syslog_lock)
>>>>
>>>> I suppose I need to go through all the console drivers to see if any
>>>> register in interrupt context. If not, that logbuf_lock_irqsave()
>>>> should be replaced with logbuf_lock_irq(). And then locking
>>>> @syslog_lock will not need to disable interrupts.
>>>
>>> I found a possible call chain in interrupt context. From arch/parisc
>>> there is the interrupt handler:
>>>
>>> handle_interruption(code=1) /* High-priority machine check (HPMC) */
>>>     pdc_console_restart()
>>>       pdc_console_init_force()
>>>         register_console()
>>>
>>> All other register_console() calls in the kernel are either during init
>>> (within __init sections and probe functions) or are clearly not in
>>> interrupt context (using mutex, kzalloc, spin_lock_irq, etc).
>>>
>>> I am not familiar with parisc, but I am assuming handle_interruption()
>>> is always called with interrupts disabled (unless the HPMC interrupt is
>>> somehow an exception).
>>
>> Yes, handle_interruption() is the irq handler, running with irqs off.
>> HPMC is the crash handler - it's called when the kernel will stop
>> anyway. pdc_console is a very basic firmware console which prints
>> the last messages before the machine halts on fatal errors.
>> So, this code it's not the typical use case....
>
> Thanks for information.
>
> Is this code supposed to work only during early boot or anytime,
> please?

No.
It's only called when the kernel completely crashes, when all
spinlocks should get busted and so on.
It's the emergency way to get some info out at least.

> Note that it is not safe because register_console() takes
> console_lock() which is a sleeping lock.

As I said, in that stage the plan is to bust all spinlocks.

> That said, we are going to rework the console handling a lot. We are
> trying to remove as many locks from the printk path as possible.

That's good!

> I guess that the list of consoles will be synchronized using
> rcu at the end. But it is still a long way to go.

I'd say, that you simply should ignore this specific case here.
I'm happy to change anything there, so if you get rid of printk locks
it will benefit here too.

Helge

Re: [PATCH printk-rework 08/14] printk: add syslog_lock

[Petr Mladek]

On Tue 2021-02-23 13:22:22, Helge Deller wrote:
> On 2/22/21 5:28 PM, Petr Mladek wrote:
> > On Sun 2021-02-21 22:39:42, Helge Deller wrote:
> > > On 2/19/21 5:33 PM, John Ogness wrote:
> > > > Added CC: linux-parisc@vger.kernel.org
> > > > 
> > > > On 2021-02-19, John Ogness <john.ogness@linutronix.de> wrote:
> > > > > > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > > > > > index 20c21a25143d..401df370832b 100644
> > > > > > > --- a/kernel/printk/printk.c
> > > > > > > +++ b/kernel/printk/printk.c
> > > > > > > +/* Return a consistent copy of @syslog_seq. */
> > > > > > > +static u64 read_syslog_seq_irq(void)
> > > > > > > +{
> > > > > > > +	u64 seq;
> > > > > > > +
> > > > > > > +	raw_spin_lock_irq(&syslog_lock);
> > > > > > > +	seq = syslog_seq;
> > > > > > > +	raw_spin_unlock_irq(&syslog_lock);
> > > > > > 
> > > > > > Is there any particular reason to disable interrupts here?
> > > > > > 
> > > > I found a possible call chain in interrupt context. From arch/parisc
> > > > there is the interrupt handler:
> > > > 
> > > Yes, handle_interruption() is the irq handler, running with irqs off.
> > > HPMC is the crash handler - it's called when the kernel will stop
> > > anyway. pdc_console is a very basic firmware console which prints
> > > the last messages before the machine halts on fatal errors.
> > > So, this code it's not the typical use case....
> > 
> > Thanks for information.
> > 
> > Is this code supposed to work only during early boot or anytime,
> > please?
> 
> No.
> It's only called when the kernel completely crashes, when all
> spinlocks should get busted and so on.
> It's the emergency way to get some info out at least.

OK.

> > Note that it is not safe because register_console() takes
> > console_lock() which is a sleeping lock.
> 
> As I said, in that stage the plan is to bust all spinlocks.

Just to be sure. Note that that register_console() does not bust
console_lock in panic.

bust_spinlocks() just increments oops_in_progress counter. It has
effect only when the caller checks this variable and use trylock
when it is set. For example, see serial8250_console_write():

void serial8250_console_write(struct uart_8250_port *up, const char *s,
			      unsigned int count)
{
	int locked = 1;

	if (oops_in_progress)
		locked = spin_trylock_irqsave(&port->lock, flags);
	else
		spin_lock_irqsave(&port->lock, flags);


	...


	if (locked)
		spin_unlock_irqrestore(&port->lock, flags);
}

register_console() does not check oops_in_progress at the moment
and might get blocked on console_sem.

We could add the checks for oops_in_progress into register_console().
But I am not sure if it is worth it. It seems that you used this code
for ages. The risk of the deadlock is small. It likely works most
of the time. The upcoming printk rework should allow a cleaner
solution.

Best Regards,
Petr

Re: [PATCH printk-rework 08/14] printk: add syslog_lock

[Helge Deller]

On 2/23/21 3:23 PM, Petr Mladek wrote:
> On Tue 2021-02-23 13:22:22, Helge Deller wrote:
>> On 2/22/21 5:28 PM, Petr Mladek wrote:
>>> On Sun 2021-02-21 22:39:42, Helge Deller wrote:
>>>> On 2/19/21 5:33 PM, John Ogness wrote:
>>>>> Added CC: linux-parisc@vger.kernel.org
>>>>>
>>>>> On 2021-02-19, John Ogness <john.ogness@linutronix.de> wrote:
>>>>>>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>>>>>>>> index 20c21a25143d..401df370832b 100644
>>>>>>>> --- a/kernel/printk/printk.c
>>>>>>>> +++ b/kernel/printk/printk.c
>>>>>>>> +/* Return a consistent copy of @syslog_seq. */
>>>>>>>> +static u64 read_syslog_seq_irq(void)
>>>>>>>> +{
>>>>>>>> +	u64 seq;
>>>>>>>> +
>>>>>>>> +	raw_spin_lock_irq(&syslog_lock);
>>>>>>>> +	seq = syslog_seq;
>>>>>>>> +	raw_spin_unlock_irq(&syslog_lock);
>>>>>>>
>>>>>>> Is there any particular reason to disable interrupts here?
>>>>>>>
>>>>> I found a possible call chain in interrupt context. From arch/parisc
>>>>> there is the interrupt handler:
>>>>>
>>>> Yes, handle_interruption() is the irq handler, running with irqs off.
>>>> HPMC is the crash handler - it's called when the kernel will stop
>>>> anyway. pdc_console is a very basic firmware console which prints
>>>> the last messages before the machine halts on fatal errors.
>>>> So, this code it's not the typical use case....
>>>
>>> Thanks for information.
>>>
>>> Is this code supposed to work only during early boot or anytime,
>>> please?
>>
>> No.
>> It's only called when the kernel completely crashes, when all
>> spinlocks should get busted and so on.
>> It's the emergency way to get some info out at least.
>
> OK.
>
>>> Note that it is not safe because register_console() takes
>>> console_lock() which is a sleeping lock.
>>
>> As I said, in that stage the plan is to bust all spinlocks.
>
> Just to be sure. Note that that register_console() does not bust
> console_lock in panic.

Ok.

> bust_spinlocks() just increments oops_in_progress counter. It has
> effect only when the caller checks this variable and use trylock
> when it is set. For example, see serial8250_console_write():
>
> void serial8250_console_write(struct uart_8250_port *up, const char *s,
> 			      unsigned int count)
> {
> 	int locked = 1;
>
> 	if (oops_in_progress)
> 		locked = spin_trylock_irqsave(&port->lock, flags);
> 	else
> 		spin_lock_irqsave(&port->lock, flags);
>
>
> 	...
>
>
> 	if (locked)
> 		spin_unlock_irqrestore(&port->lock, flags);
> }
>
> register_console() does not check oops_in_progress at the moment
> and might get blocked on console_sem.
>
> We could add the checks for oops_in_progress into register_console().
> But I am not sure if it is worth it.

It's not worth it just because of parisc.
I haven't seen any such crash in years, so the current implementation
is probably untested and outdated.

> It seems that you used this code for ages. The risk of the deadlock
> is small. It likely works most of the time. The upcoming printk rework
> should allow a cleaner solution.

Yes, it would be great if you can include such a "hard-panic/crash-dump-case"
in the rework.

Helge