[PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Julien Grall]

At the moment show_lock is implemented using spin_lock_t and called from
an interrupt context on Arm64. The following backtrace was triggered by:

42sh# echo l > /proc/sysrq-trigger

[ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
[ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
[ 4432.403424] sysrq: CPU6:
[ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2

[...]

[ 4432.403581] Call trace:
[ 4432.403584]  dump_backtrace+0x0/0x148
[ 4432.403586]  show_stack+0x14/0x20
[ 4432.403588]  dump_stack+0x9c/0xd4
[ 4432.403592]  ___might_sleep+0x1cc/0x298
[ 4432.403595]  rt_spin_lock+0x5c/0x70
[ 4432.403596]  showacpu+0x34/0x68
[ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
[ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
[ 4432.403605]  handle_IPI+0x26c/0x668
[ 4432.403607]  gic_handle_irq+0x9c/0xa0
[ 4432.403609]  el1_irq+0xb4/0x13c

With RT-patches, spin_lock can now sleep and therefore cannot be used from
interrupt context. Use a raw_spin_lock instead to prevent the lock to
sleep.

Signed-off-by: Julien Grall <julien.grall@arm.com>
---
 drivers/tty/sysrq.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 1f03078ec352..8473557c7ab2 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -208,7 +208,7 @@ static struct sysrq_key_op sysrq_showlocks_op = {
 #endif
 
 #ifdef CONFIG_SMP
-static DEFINE_SPINLOCK(show_lock);
+static DEFINE_RAW_SPINLOCK(show_lock);
 
 static void showacpu(void *dummy)
 {
@@ -218,10 +218,10 @@ static void showacpu(void *dummy)
 	if (idle_cpu(smp_processor_id()))
 		return;
 
-	spin_lock_irqsave(&show_lock, flags);
+	raw_spin_lock_irqsave(&show_lock, flags);
 	pr_info("CPU%d:\n", smp_processor_id());
 	show_stack(NULL, NULL);
-	spin_unlock_irqrestore(&show_lock, flags);
+	raw_spin_unlock_irqrestore(&show_lock, flags);
 }
 
 static void sysrq_showregs_othercpus(struct work_struct *dummy)
-- 
2.11.0

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Julien Grall]

(CC correctly linux-rt-users)

On 04/03/2019 17:20, Julien Grall wrote:
> At the moment show_lock is implemented using spin_lock_t and called from
> an interrupt context on Arm64. The following backtrace was triggered by:
> 
> 42sh# echo l > /proc/sysrq-trigger
> 
> [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
> [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
> [ 4432.403424] sysrq: CPU6:
> [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
> 
> [...]
> 
> [ 4432.403581] Call trace:
> [ 4432.403584]  dump_backtrace+0x0/0x148
> [ 4432.403586]  show_stack+0x14/0x20
> [ 4432.403588]  dump_stack+0x9c/0xd4
> [ 4432.403592]  ___might_sleep+0x1cc/0x298
> [ 4432.403595]  rt_spin_lock+0x5c/0x70
> [ 4432.403596]  showacpu+0x34/0x68
> [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
> [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
> [ 4432.403605]  handle_IPI+0x26c/0x668
> [ 4432.403607]  gic_handle_irq+0x9c/0xa0
> [ 4432.403609]  el1_irq+0xb4/0x13c
> 
> With RT-patches, spin_lock can now sleep and therefore cannot be used from
> interrupt context. Use a raw_spin_lock instead to prevent the lock to
> sleep.
> 
> Signed-off-by: Julien Grall <julien.grall@arm.com>
> ---
>   drivers/tty/sysrq.c | 6 +++---
>   1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
> index 1f03078ec352..8473557c7ab2 100644
> --- a/drivers/tty/sysrq.c
> +++ b/drivers/tty/sysrq.c
> @@ -208,7 +208,7 @@ static struct sysrq_key_op sysrq_showlocks_op = {
>   #endif
>   
>   #ifdef CONFIG_SMP
> -static DEFINE_SPINLOCK(show_lock);
> +static DEFINE_RAW_SPINLOCK(show_lock);
>   
>   static void showacpu(void *dummy)
>   {
> @@ -218,10 +218,10 @@ static void showacpu(void *dummy)
>   	if (idle_cpu(smp_processor_id()))
>   		return;
>   
> -	spin_lock_irqsave(&show_lock, flags);
> +	raw_spin_lock_irqsave(&show_lock, flags);
>   	pr_info("CPU%d:\n", smp_processor_id());
>   	show_stack(NULL, NULL);
> -	spin_unlock_irqrestore(&show_lock, flags);
> +	raw_spin_unlock_irqrestore(&show_lock, flags);
>   }
>   
>   static void sysrq_showregs_othercpus(struct work_struct *dummy)
> 

-- 
Julien Grall

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Sebastian Andrzej Siewior]

On 2019-03-04 17:21:57 [+0000], Julien Grall wrote:
> (CC correctly linux-rt-users)
> 
> On 04/03/2019 17:20, Julien Grall wrote:
> > At the moment show_lock is implemented using spin_lock_t and called from
> > an interrupt context on Arm64. The following backtrace was triggered by:
> > 
> > 42sh# echo l > /proc/sysrq-trigger
> > 
> > [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
> > [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
> > [ 4432.403424] sysrq: CPU6:
> > [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
> > 
> > [...]
> > 
> > [ 4432.403581] Call trace:
> > [ 4432.403584]  dump_backtrace+0x0/0x148
> > [ 4432.403586]  show_stack+0x14/0x20
> > [ 4432.403588]  dump_stack+0x9c/0xd4
> > [ 4432.403592]  ___might_sleep+0x1cc/0x298
> > [ 4432.403595]  rt_spin_lock+0x5c/0x70
> > [ 4432.403596]  showacpu+0x34/0x68
> > [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
> > [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
> > [ 4432.403605]  handle_IPI+0x26c/0x668
> > [ 4432.403607]  gic_handle_irq+0x9c/0xa0
> > [ 4432.403609]  el1_irq+0xb4/0x13c
> > 
> > With RT-patches, spin_lock can now sleep and therefore cannot be used from
> > interrupt context. Use a raw_spin_lock instead to prevent the lock to
> > sleep.
> > 
> > Signed-off-by: Julien Grall <julien.grall@arm.com>

I don't have to look at this properly but this looks is wrong. 
Please CC the RT developers if you plan any changes that affects primary
only the RT tree. This change is a nop for the !RT tree.

> >   drivers/tty/sysrq.c | 6 +++---
> >   1 file changed, 3 insertions(+), 3 deletions(-)
> > 
> > diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
> > index 1f03078ec352..8473557c7ab2 100644
> > --- a/drivers/tty/sysrq.c
> > +++ b/drivers/tty/sysrq.c
> > @@ -208,7 +208,7 @@ static struct sysrq_key_op sysrq_showlocks_op = {
> >   #endif
> >   #ifdef CONFIG_SMP
> > -static DEFINE_SPINLOCK(show_lock);
> > +static DEFINE_RAW_SPINLOCK(show_lock);
> >   static void showacpu(void *dummy)
> >   {
> > @@ -218,10 +218,10 @@ static void showacpu(void *dummy)
> >   	if (idle_cpu(smp_processor_id()))
> >   		return;
> > -	spin_lock_irqsave(&show_lock, flags);
> > +	raw_spin_lock_irqsave(&show_lock, flags);
> >   	pr_info("CPU%d:\n", smp_processor_id());
> >   	show_stack(NULL, NULL);
> > -	spin_unlock_irqrestore(&show_lock, flags);
> > +	raw_spin_unlock_irqrestore(&show_lock, flags);
> >   }
> >   static void sysrq_showregs_othercpus(struct work_struct *dummy)
> > 

Sebastian

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Julien Grall]

Hello Sebastian,

On 04/03/2019 22:01, Sebastian Andrzej Siewior wrote:
> On 2019-03-04 17:21:57 [+0000], Julien Grall wrote:
>> (CC correctly linux-rt-users)
>>
>> On 04/03/2019 17:20, Julien Grall wrote:
>>> At the moment show_lock is implemented using spin_lock_t and called from
>>> an interrupt context on Arm64. The following backtrace was triggered by:
>>>
>>> 42sh# echo l > /proc/sysrq-trigger
>>>
>>> [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
>>> [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
>>> [ 4432.403424] sysrq: CPU6:
>>> [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
>>>
>>> [...]
>>>
>>> [ 4432.403581] Call trace:
>>> [ 4432.403584]  dump_backtrace+0x0/0x148
>>> [ 4432.403586]  show_stack+0x14/0x20
>>> [ 4432.403588]  dump_stack+0x9c/0xd4
>>> [ 4432.403592]  ___might_sleep+0x1cc/0x298
>>> [ 4432.403595]  rt_spin_lock+0x5c/0x70
>>> [ 4432.403596]  showacpu+0x34/0x68
>>> [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
>>> [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
>>> [ 4432.403605]  handle_IPI+0x26c/0x668
>>> [ 4432.403607]  gic_handle_irq+0x9c/0xa0
>>> [ 4432.403609]  el1_irq+0xb4/0x13c
>>>
>>> With RT-patches, spin_lock can now sleep and therefore cannot be used from
>>> interrupt context. Use a raw_spin_lock instead to prevent the lock to
>>> sleep.
>>>
>>> Signed-off-by: Julien Grall <julien.grall@arm.com>
> 
> I don't have to look at this properly but this looks is wrong.

May I ask why does it look wrong? On Arm64, this code is called from an 
IRQ disabled context (see the check in flush_smp_call_function_queue).

So it seems to me that it makes sense to switch to a raw spin lock here.
I would be happy to implement differently if you have a better solution 
here.

> Please CC the RT developers if you plan any changes that affects primary
> only the RT tree. This change is a nop for the !RT tree.

Sorry, I was not sure whether CCing linux-rt-users was enough here.

> 
>>>    drivers/tty/sysrq.c | 6 +++---
>>>    1 file changed, 3 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
>>> index 1f03078ec352..8473557c7ab2 100644
>>> --- a/drivers/tty/sysrq.c
>>> +++ b/drivers/tty/sysrq.c
>>> @@ -208,7 +208,7 @@ static struct sysrq_key_op sysrq_showlocks_op = {
>>>    #endif
>>>    #ifdef CONFIG_SMP
>>> -static DEFINE_SPINLOCK(show_lock);
>>> +static DEFINE_RAW_SPINLOCK(show_lock);
>>>    static void showacpu(void *dummy)
>>>    {
>>> @@ -218,10 +218,10 @@ static void showacpu(void *dummy)
>>>    	if (idle_cpu(smp_processor_id()))
>>>    		return;
>>> -	spin_lock_irqsave(&show_lock, flags);
>>> +	raw_spin_lock_irqsave(&show_lock, flags);
>>>    	pr_info("CPU%d:\n", smp_processor_id());
>>>    	show_stack(NULL, NULL);
>>> -	spin_unlock_irqrestore(&show_lock, flags);
>>> +	raw_spin_unlock_irqrestore(&show_lock, flags);
>>>    }
>>>    static void sysrq_showregs_othercpus(struct work_struct *dummy)
>>>

Best regards,

-- 
Julien Grall

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Steven Rostedt]

On Mon, 4 Mar 2019 22:25:41 +0000
Julien Grall <Julien.Grall@arm.com> wrote:

> Hello Sebastian,
> 
> On 04/03/2019 22:01, Sebastian Andrzej Siewior wrote:
> > On 2019-03-04 17:21:57 [+0000], Julien Grall wrote:  
> >> (CC correctly linux-rt-users)
> >>
> >> On 04/03/2019 17:20, Julien Grall wrote:  
> >>> At the moment show_lock is implemented using spin_lock_t and called from
> >>> an interrupt context on Arm64. The following backtrace was triggered by:
> >>>
> >>> 42sh# echo l > /proc/sysrq-trigger
> >>>
> >>> [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
> >>> [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
> >>> [ 4432.403424] sysrq: CPU6:
> >>> [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
> >>>
> >>> [...]
> >>>
> >>> [ 4432.403581] Call trace:
> >>> [ 4432.403584]  dump_backtrace+0x0/0x148
> >>> [ 4432.403586]  show_stack+0x14/0x20
> >>> [ 4432.403588]  dump_stack+0x9c/0xd4
> >>> [ 4432.403592]  ___might_sleep+0x1cc/0x298
> >>> [ 4432.403595]  rt_spin_lock+0x5c/0x70
> >>> [ 4432.403596]  showacpu+0x34/0x68
> >>> [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
> >>> [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
> >>> [ 4432.403605]  handle_IPI+0x26c/0x668
> >>> [ 4432.403607]  gic_handle_irq+0x9c/0xa0
> >>> [ 4432.403609]  el1_irq+0xb4/0x13c
> >>>
> >>> With RT-patches, spin_lock can now sleep and therefore cannot be used from
> >>> interrupt context. Use a raw_spin_lock instead to prevent the lock to
> >>> sleep.
> >>>
> >>> Signed-off-by: Julien Grall <julien.grall@arm.com>  
> > 
> > I don't have to look at this properly but this looks is wrong.  
> 
> May I ask why does it look wrong? On Arm64, this code is called from an 
> IRQ disabled context (see the check in flush_smp_call_function_queue).

I'll answer.

It's going to call printk, and depending on consoles and such, it may
not print anything (a printk without atomic consoles shows nothing).

That said, perhaps we need to do something like the "safe printk", 
where it only loads it into the log buffers and doesn't do the actual
prints.

Hmm, do we do that now? I need to look at the latest printk code in RT.

Also, there's a big discussion going on in LKML right now about
rewriting how the printk buffers work.

-- Steve

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Julien Grall]

Hi Steve,

On 04/03/2019 23:15, Steven Rostedt wrote:
> On Mon, 4 Mar 2019 22:25:41 +0000
> Julien Grall <Julien.Grall@arm.com> wrote:
>> On 04/03/2019 22:01, Sebastian Andrzej Siewior wrote:
>>> On 2019-03-04 17:21:57 [+0000], Julien Grall wrote:
>>>> (CC correctly linux-rt-users)
>>>>
>>>> On 04/03/2019 17:20, Julien Grall wrote:
>>>>> At the moment show_lock is implemented using spin_lock_t and called from
>>>>> an interrupt context on Arm64. The following backtrace was triggered by:
>>>>>
>>>>> 42sh# echo l > /proc/sysrq-trigger
>>>>>
>>>>> [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
>>>>> [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
>>>>> [ 4432.403424] sysrq: CPU6:
>>>>> [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
>>>>>
>>>>> [...]
>>>>>
>>>>> [ 4432.403581] Call trace:
>>>>> [ 4432.403584]  dump_backtrace+0x0/0x148
>>>>> [ 4432.403586]  show_stack+0x14/0x20
>>>>> [ 4432.403588]  dump_stack+0x9c/0xd4
>>>>> [ 4432.403592]  ___might_sleep+0x1cc/0x298
>>>>> [ 4432.403595]  rt_spin_lock+0x5c/0x70
>>>>> [ 4432.403596]  showacpu+0x34/0x68
>>>>> [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
>>>>> [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
>>>>> [ 4432.403605]  handle_IPI+0x26c/0x668
>>>>> [ 4432.403607]  gic_handle_irq+0x9c/0xa0
>>>>> [ 4432.403609]  el1_irq+0xb4/0x13c
>>>>>
>>>>> With RT-patches, spin_lock can now sleep and therefore cannot be used from
>>>>> interrupt context. Use a raw_spin_lock instead to prevent the lock to
>>>>> sleep.
>>>>>
>>>>> Signed-off-by: Julien Grall <julien.grall@arm.com>
>>>
>>> I don't have to look at this properly but this looks is wrong.
>>
>> May I ask why does it look wrong? On Arm64, this code is called from an
>> IRQ disabled context (see the check in flush_smp_call_function_queue).
> 
> I'll answer.
>
> It's going to call printk, and depending on consoles and such, it may
> not print anything (a printk without atomic consoles shows nothing).
> 
> That said, perhaps we need to do something like the "safe printk",
> where it only loads it into the log buffers and doesn't do the actual
> prints.
> 
> Hmm, do we do that now? I need to look at the latest printk code in RT.

Thank you for the explanation.

I am not entirely familiar with printk, so I may have overlooked something.

Looking at the printk code (see vprintk_emit), the message will be loaded in the 
log buffer. The log buffer will be printed out by klogd if vprintk_emit were 
called from a context where IRQs or preemption is disabled.

So I think the printk should still happen from atomic context but it will get 
delayed until we are out from the atomic context.

Cheers,

-- 
Julien Grall

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Sebastian Andrzej Siewior]

On 2019-03-04 17:20:53 [+0000], Julien Grall wrote:
> At the moment show_lock is implemented using spin_lock_t and called from
> an interrupt context on Arm64. The following backtrace was triggered by:
> 
> 42sh# echo l > /proc/sysrq-trigger
> 
> [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
> [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
> [ 4432.403424] sysrq: CPU6:
> [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
> 
> [...]
> 
> [ 4432.403581] Call trace:
> [ 4432.403584]  dump_backtrace+0x0/0x148
> [ 4432.403586]  show_stack+0x14/0x20
> [ 4432.403588]  dump_stack+0x9c/0xd4
> [ 4432.403592]  ___might_sleep+0x1cc/0x298
> [ 4432.403595]  rt_spin_lock+0x5c/0x70
> [ 4432.403596]  showacpu+0x34/0x68
> [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
> [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
> [ 4432.403605]  handle_IPI+0x26c/0x668
> [ 4432.403607]  gic_handle_irq+0x9c/0xa0
> [ 4432.403609]  el1_irq+0xb4/0x13c
> 
> With RT-patches, spin_lock can now sleep and therefore cannot be used from
> interrupt context. Use a raw_spin_lock instead to prevent the lock to
> sleep.
> 
> Signed-off-by: Julien Grall <julien.grall@arm.com>

Now that I had time to look at it, for the change itself:
	Acked-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>

For the description please take into consideration to add something like
this:

 Systems which don't provide arch_trigger_cpumask_backtrace() will
 invoke showacpu() from a smp_call_function() function which is invoked
 with disabled interrupts even on -RT systems.
 The function acquires the show_lock lock which only purpose is to
 ensure that the CPUs don't print simultaneously. Otherwise the output
 would clash and it would be hard to tell the output from CPUx apart
 from CPUy.
 On -RT the spin_lock() can not be acquired from this context. A
 raw_spin_lock() is required. It will introduce the system's latency
 by performing the sysrq request and other CPUs will block on the lock
 until the request is done. This is okay because the user asked for a
 backtrace of all active CPUs and under "normal circumstances in
 production" this path should not be triggered.

Which explains *why* you do the change and *why* it is okay to do the
change. If we start changing each spin_lock() to a raw_spin_lock()
because lockdep said so then soon the RT switch will make less change
than it should.

From top of my head I think you won't see the output on -RT right away.
The output won't be printed from the non-preemptible context and will be
delayed until a printk occurs from a preemptible context. There are
printk related patches which fix that and allow a printk from a
non-preemptible context for a configured log level.

Looking at the showacpu() construct: Do you get a proper stacktrace for a
busy CPU or does it always start at el1_irq()? Because if the interrupt
always starts with its own interrupt stack then the backtrace is
useless. All you would need is the information that the CPU is alive and
a oneline printk() saying so would be enough. Or, if it starts on its
own stack but is able to unwind to the previous context *then* you gain
additional information you are looking for.

> ---
>  drivers/tty/sysrq.c | 6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
> index 1f03078ec352..8473557c7ab2 100644
> --- a/drivers/tty/sysrq.c
> +++ b/drivers/tty/sysrq.c
> @@ -208,7 +208,7 @@ static struct sysrq_key_op sysrq_showlocks_op = {
>  #endif
>  
>  #ifdef CONFIG_SMP
> -static DEFINE_SPINLOCK(show_lock);
> +static DEFINE_RAW_SPINLOCK(show_lock);
>  
>  static void showacpu(void *dummy)
>  {
> @@ -218,10 +218,10 @@ static void showacpu(void *dummy)
>  	if (idle_cpu(smp_processor_id()))
>  		return;
>  
> -	spin_lock_irqsave(&show_lock, flags);
> +	raw_spin_lock_irqsave(&show_lock, flags);
>  	pr_info("CPU%d:\n", smp_processor_id());
>  	show_stack(NULL, NULL);
> -	spin_unlock_irqrestore(&show_lock, flags);
> +	raw_spin_unlock_irqrestore(&show_lock, flags);
>  }
>  
>  static void sysrq_showregs_othercpus(struct work_struct *dummy)
> -- 
> 2.11.0
> 

Sebastian

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Julien Grall]

Hi Sebastian,

On 07/03/2019 12:38, Sebastian Andrzej Siewior wrote:
> On 2019-03-04 17:20:53 [+0000], Julien Grall wrote:
>> At the moment show_lock is implemented using spin_lock_t and called from
>> an interrupt context on Arm64. The following backtrace was triggered by:
>>
>> 42sh# echo l > /proc/sysrq-trigger
>>
>> [ 4432.073756] sysrq: SysRq : Show backtrace of all active CPUs
>> [ 4432.403422] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:974
>> [ 4432.403424] sysrq: CPU6:
>> [ 4432.403426] in_atomic(): 1, irqs_disabled(): 128, pid: 2410, name: kworker/u16:2
>>
>> [...]
>>
>> [ 4432.403581] Call trace:
>> [ 4432.403584]  dump_backtrace+0x0/0x148
>> [ 4432.403586]  show_stack+0x14/0x20
>> [ 4432.403588]  dump_stack+0x9c/0xd4
>> [ 4432.403592]  ___might_sleep+0x1cc/0x298
>> [ 4432.403595]  rt_spin_lock+0x5c/0x70
>> [ 4432.403596]  showacpu+0x34/0x68
>> [ 4432.403599]  flush_smp_call_function_queue+0xd4/0x278
>> [ 4432.403602]  generic_smp_call_function_single_interrupt+0x10/0x18
>> [ 4432.403605]  handle_IPI+0x26c/0x668
>> [ 4432.403607]  gic_handle_irq+0x9c/0xa0
>> [ 4432.403609]  el1_irq+0xb4/0x13c
>>
>> With RT-patches, spin_lock can now sleep and therefore cannot be used from
>> interrupt context. Use a raw_spin_lock instead to prevent the lock to
>> sleep.
>>
>> Signed-off-by: Julien Grall <julien.grall@arm.com>
> 
> Now that I had time to look at it, for the change itself:
> 	Acked-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> 
> For the description please take into consideration to add something like
> this:
> 
>   Systems which don't provide arch_trigger_cpumask_backtrace() will
>   invoke showacpu() from a smp_call_function() function which is invoked
>   with disabled interrupts even on -RT systems.
>   The function acquires the show_lock lock which only purpose is to
>   ensure that the CPUs don't print simultaneously. Otherwise the output
>   would clash and it would be hard to tell the output from CPUx apart
>   from CPUy.
>   On -RT the spin_lock() can not be acquired from this context. A
>   raw_spin_lock() is required. It will introduce the system's latency
>   by performing the sysrq request and other CPUs will block on the lock
>   until the request is done. This is okay because the user asked for a
>   backtrace of all active CPUs and under "normal circumstances in
>   production" this path should not be triggered.

This description looks better. I will update the commit message. Do you mind if 
I had your signed-off-by as you provided the commit message?

> 
> Which explains *why* you do the change and *why* it is okay to do the
> change. If we start changing each spin_lock() to a raw_spin_lock()
> because lockdep said so then soon the RT switch will make less change
> than it should.

I understand, I will take into account for the next RT patches I will post.

> 
>  From top of my head I think you won't see the output on -RT right away.
> The output won't be printed from the non-preemptible context and will be
> delayed until a printk occurs from a preemptible context.

FWIW, this is the behavior I saw when testing this patch.

> There are
> printk related patches which fix that and allow a printk from a
> non-preemptible context for a configured log level.
> 
> Looking at the showacpu() construct: Do you get a proper stacktrace for a
> busy CPU or does it always start at el1_irq()? Because if the interrupt
> always starts with its own interrupt stack then the backtrace is
> useless. All you would need is the information that the CPU is alive and
> a oneline printk() saying so would be enough. Or, if it starts on its
> own stack but is able to unwind to the previous context *then* you gain
> additional information you are looking for.

 From my understanding, the stack frames across exceptions are chained. So the 
stacktrace will be able to unwind to the previous context.

Actually, in my previous e-mail, I have cut down the stacktrace to el1_irq() as 
it was quite long. An example of the full stack trace:

[  516.820845] sysrq: SysRq : Show backtrace of all active CPUs
[  516.941513] sysrq: CPU0:
[  516.941515] Call trace:
[  516.941519]  dump_backtrace+0x0/0x148
[  516.941521]  show_stack+0x14/0x20
[  516.941524]  showacpu+0x58/0x70
[  516.941527]  flush_smp_call_function_queue+0xd4/0x278
[  516.941530]  generic_smp_call_function_single_interrupt+0x10/0x18
[  516.941533]  handle_IPI+0x26c/0x668
[  516.941535]  gic_handle_irq+0x9c/0xa0
[  516.941537]  el1_irq+0xb4/0x13c
[  516.941539]  generic_exec_single+0x174/0x218
[  516.941541]  smp_call_function_single+0xc4/0x280
[  516.941544]  task_function_call+0x54/0x90
[  516.941547]  event_function_call+0xa0/0x158
[  516.941549]  _perf_event_enable+0x54/0x80
[  516.941552]  perf_event_enable+0x24/0x40
[  516.941555]  kvm_pmu_enable_counter.part.0+0x64/0x90
[  516.941557]  kvm_pmu_handle_pmcr+0xc0/0xd8
[  516.941559]  access_pmcr+0x104/0x138
[  516.941561]  perform_access+0x1c/0x78
[  516.941564]  kvm_handle_sys_reg+0x144/0x4e0
[  516.941566]  handle_exit+0x13c/0x1f8
[  516.941568]  kvm_arch_vcpu_ioctl_run+0x68c/0xbe8
[  516.941571]  kvm_vcpu_ioctl+0x398/0xad8
[  516.941574]  do_vfs_ioctl+0xbc/0x910
[  516.941576]  ksys_ioctl+0x78/0xa8
[  516.941579]  __arm64_sys_ioctl+0x1c/0x28
[  516.941582]  el0_svc_common+0x90/0x118
[  516.941584]  el0_svc_handler+0x2c/0x80
[  516.941586]  el0_svc+0x8/0xc

Thank you for your acked-by and the explanation. I will resend the patch with 
the updated comment.

Best regards,

> 
>> ---
>>   drivers/tty/sysrq.c | 6 +++---
>>   1 file changed, 3 insertions(+), 3 deletions(-)
>>
>> diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
>> index 1f03078ec352..8473557c7ab2 100644
>> --- a/drivers/tty/sysrq.c
>> +++ b/drivers/tty/sysrq.c
>> @@ -208,7 +208,7 @@ static struct sysrq_key_op sysrq_showlocks_op = {
>>   #endif
>>   
>>   #ifdef CONFIG_SMP
>> -static DEFINE_SPINLOCK(show_lock);
>> +static DEFINE_RAW_SPINLOCK(show_lock);
>>   
>>   static void showacpu(void *dummy)
>>   {
>> @@ -218,10 +218,10 @@ static void showacpu(void *dummy)
>>   	if (idle_cpu(smp_processor_id()))
>>   		return;
>>   
>> -	spin_lock_irqsave(&show_lock, flags);
>> +	raw_spin_lock_irqsave(&show_lock, flags);
>>   	pr_info("CPU%d:\n", smp_processor_id());
>>   	show_stack(NULL, NULL);
>> -	spin_unlock_irqrestore(&show_lock, flags);
>> +	raw_spin_unlock_irqrestore(&show_lock, flags);
>>   }
>>   
>>   static void sysrq_showregs_othercpus(struct work_struct *dummy)
>> -- 
>> 2.11.0
>>
> 
> Sebastian
> 

-- 
Julien Grall

Re: [PATCH] tty/sysrq: Convert show_lock to raw_spinlock_t

[Sebastian Andrzej Siewior]

On 2019-03-07 18:14:46 [+0000], Julien Grall wrote:
> Hi Sebastian,
Hi,

> This description looks better. I will update the commit message. Do you mind
> if I had your signed-off-by as you provided the commit message?

Sure. However you might also want to "just" add something like
	[bigeasy@linutronix.de: commit description]

or something in plain English :)

> From my understanding, the stack frames across exceptions are chained. So
> the stacktrace will be able to unwind to the previous context.

Ah okay.

Sebastian