2014-04-14 23:45:46

by Stanislav Meduna

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On 14.04.2014 21:24, Stanislav Meduna wrote:

> hunting another problem with AUART acting weirdly I got

okay, the AUART thing was some device tree snafu, but I have seen
the BUG a few times (but not readily reproducible). This thread
looks remotely similar https://lkml.org/lkml/2013/9/27/534 - looks
like the real bug happened somewhere else :( Any hints on how to
get more info?

Adding Cc: to linux-arm and linux-kernel

> BUG: spinlock trylock failure on UP on CPU#0, ksoftirqd/0/3
> lock: boot_tvec_bases+0x0/0x10a0, .magic: dead4ead, .owner: ksoftirqd/0/3, .owner_cpu: 0
> CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 3.12.15-rt25-00371-gfec62f5-dirty #26
> [<c00149ec>] (unwind_backtrace+0x0/0xf4) from [<c0012ab0>] (show_stack+0x10/0x14)
> [<c0012ab0>] (show_stack+0x10/0x14) from [<c01a4b80>] (do_raw_spin_trylock+0x4c/0x58)
> [<c01a4b80>] (do_raw_spin_trylock+0x4c/0x58) from [<c02ca0b4>] (_raw_spin_trylock+0x20/0x98)
> [<c02ca0b4>] (_raw_spin_trylock+0x20/0x98) from [<c02c9654>] (rt_spin_trylock+0x14/0xd0)
> [<c02c9654>] (rt_spin_trylock+0x14/0xd0) from [<c00285cc>] (run_local_timers+0x24/0x78)
> [<c00285cc>] (run_local_timers+0x24/0x78) from [<c0028654>] (update_process_times+0x34/0x68)
> [<c0028654>] (update_process_times+0x34/0x68) from [<c005f0ac>] (tick_sched_timer+0x58/0x22c)
> [<c005f0ac>] (tick_sched_timer+0x58/0x22c) from [<c003f2f8>] (__run_hrtimer+0x7c/0x2a8)
> [<c003f2f8>] (__run_hrtimer+0x7c/0x2a8) from [<c003f684>] (hrtimer_interrupt+0x104/0x30c)
> [<c003f684>] (hrtimer_interrupt+0x104/0x30c) from [<c0230a84>] (mxs_timer_interrupt+0x20/0x2c)
> [<c0230a84>] (mxs_timer_interrupt+0x20/0x2c) from [<c0051d1c>] (handle_irq_event_percpu+0x80/0x2f8)
> [<c0051d1c>] (handle_irq_event_percpu+0x80/0x2f8) from [<c0051fd0>] (handle_irq_event+0x3c/0x5c)
> [<c0051fd0>] (handle_irq_event+0x3c/0x5c) from [<c0054778>] (handle_level_irq+0x8c/0x118)
> [<c0054778>] (handle_level_irq+0x8c/0x118) from [<c0051c8c>] (generic_handle_irq+0x28/0x30)
> [<c0051c8c>] (generic_handle_irq+0x28/0x30) from [<c001009c>] (handle_IRQ+0x30/0x84)
> [<c001009c>] (handle_IRQ+0x30/0x84) from [<c0013324>] (__irq_svc+0x44/0x88)
> [<c0013324>] (__irq_svc+0x44/0x88) from [<c006a664>] (__try_to_take_rt_mutex+0x4/0x144)
> [<c006a664>] (__try_to_take_rt_mutex+0x4/0x144) from [<00000000>] ( (null))
>
>
> Linux nxt 3.12.15-rt25-00371-gfec62f5-dirty #26 PREEMPT RT Mon Apr 14 20:40:56 CEST 2014 armv5tejl GNU/Linux
>
> This is on a Freescale i.MX28, 3.12.15-rt25 with patches that do not touch
> anything related.

--
Stano


2014-04-15 22:09:04

by Stanislav Meduna

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On 15.04.2014 01:45, Stanislav Meduna wrote:

>> BUG: spinlock trylock failure on UP on CPU#0, ksoftirqd/0/3

I am now getting this quite reproducibly a few seconds into
the boot and the path is always similar. Depending on what modules
I am loading the source changes, but it is nearly always
a schedule_timeout with a following timer interrupt.

Disabling highres timers just changes the bug path but it happens
also in that case. I am using CONFIG_HZ_PERIODIC. I tried to disable
the serial console and several drivers to rule out some interference
but it did not change anything.

Freescale i.MX28, 3.12.15-rt25 + patches enabling the platform,
none of them touches anything in kernel/* or the MXS timer.
Up to now no freeze or other BUGs, it was always only this one.

I see that the relevant code was touched a few times in the last
few months, maybe there is still something lurking.

Hmm... how is it in the rt-case guaranteed that the timer interrupt
does not preempt someone trying to modify the timer? The run_local_timers
looks to have arrived via hardirq context. The spinlock in the tvec_base
is a normal one and spin_lock_irqsave does not disable interrupts
on rt, right?

[ 11.797460] BUG: spinlock trylock failure on UP on CPU#0, rcu_preempt/11
[ 11.797522] lock: boot_tvec_bases+0x0/0x10c0, .magic: dead4ead, .owner: rcu_preempt/11, .owner_cpu: 0
[ 11.797550] CPU: 0 PID: 11 Comm: rcu_preempt Not tainted 3.12.15-rt25+ #52
[ 11.797630] [<c00151bc>] (unwind_backtrace+0x0/0xf4) from [<c0012c00>] (show_stack+0x10/0x14)
[ 11.797691] [<c0012c00>] (show_stack+0x10/0x14) from [<c01b2758>] (do_raw_spin_trylock+0x4c/0x58)
[ 11.797748] [<c01b2758>] (do_raw_spin_trylock+0x4c/0x58) from [<c02e0194>] (_raw_spin_trylock+0x20/0x98)
[ 11.797792] [<c02e0194>] (_raw_spin_trylock+0x20/0x98) from [<c02df734>] (rt_spin_trylock+0x14/0xd0)
[ 11.797851] [<c02df734>] (rt_spin_trylock+0x14/0xd0) from [<c0028e7c>] (run_local_timers+0x24/0x78)
[ 11.797892] [<c0028e7c>] (run_local_timers+0x24/0x78) from [<c0028f04>] (update_process_times+0x34/0x68)
[ 11.797940] [<c0028f04>] (update_process_times+0x34/0x68) from [<c0060920>] (tick_sched_timer+0x58/0x22c)
[ 11.797990] [<c0060920>] (tick_sched_timer+0x58/0x22c) from [<c0040820>] (__run_hrtimer+0x88/0x2b8)
[ 11.798029] [<c0040820>] (__run_hrtimer+0x88/0x2b8) from [<c0040bb0>] (hrtimer_interrupt+0x104/0x30c)
[ 11.798076] [<c0040bb0>] (hrtimer_interrupt+0x104/0x30c) from [<c0246c50>] (mxs_timer_interrupt+0x20/0x2c)
[ 11.798123] [<c0246c50>] (mxs_timer_interrupt+0x20/0x2c) from [<c00534d8>] (handle_irq_event_percpu+0x80/0x2f8)
[ 11.798161] [<c00534d8>] (handle_irq_event_percpu+0x80/0x2f8) from [<c005378c>] (handle_irq_event+0x3c/0x5c)
[ 11.798201] [<c005378c>] (handle_irq_event+0x3c/0x5c) from [<c0055f68>] (handle_level_irq+0x8c/0x118)
[ 11.798239] [<c0055f68>] (handle_level_irq+0x8c/0x118) from [<c0053448>] (generic_handle_irq+0x28/0x30)
[ 11.798281] [<c0053448>] (generic_handle_irq+0x28/0x30) from [<c00101dc>] (handle_IRQ+0x30/0x84)
[ 11.798322] [<c00101dc>] (handle_IRQ+0x30/0x84) from [<c0013484>] (__irq_svc+0x44/0x88)
[ 11.798364] [<c0013484>] (__irq_svc+0x44/0x88) from [<c02deb18>] (rt_spin_lock_slowlock+0x60/0x204)
[ 11.798402] [<c02deb18>] (rt_spin_lock_slowlock+0x60/0x204) from [<c02df4d0>] (rt_spin_lock+0x28/0x60)
[ 11.798451] [<c02df4d0>] (rt_spin_lock+0x28/0x60) from [<c0028874>] (lock_timer_base+0x28/0x48)
[ 11.798494] [<c0028874>] (lock_timer_base+0x28/0x48) from [<c02dcb28>] (schedule_timeout+0x78/0x254)
[ 11.798531] [<c02dcb28>] (schedule_timeout+0x78/0x254) from [<c00763a4>] (rcu_gp_kthread+0x2d4/0x5f0)
[ 11.798578] [<c00763a4>] (rcu_gp_kthread+0x2d4/0x5f0) from [<c003cf24>] (kthread+0xa0/0xa8)
[ 11.798621] [<c003cf24>] (kthread+0xa0/0xa8) from [<c000f3e0>] (ret_from_fork+0x14/0x34)

Thanks
--
Stano

2014-04-17 16:30:14

by Stanislav Meduna

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP - reverting timer patches helps

On 16.04.2014 00:08, Stanislav Meduna wrote:

>>> BUG: spinlock trylock failure on UP on CPU#0, ksoftirqd/0/3
>
> I am now getting this quite reproducibly a few seconds into
> the boot and the path is always similar. Depending on what modules
> I am loading the source changes, but it is nearly always
> a schedule_timeout with a following timer interrupt.

Note: the bug goes away reverting the very same patches that are
helping the Jordan's problms. I did follow

http://www.spinics.net/lists/linux-rt-users/msg11639.html

and no BUG while booting anymore. I'll try to let it run some
more time.

> [ 11.797460] BUG: spinlock trylock failure on UP on CPU#0, rcu_preempt/11
> [ 11.797522] lock: boot_tvec_bases+0x0/0x10c0, .magic: dead4ead, .owner: rcu_preempt/11, .owner_cpu: 0
> [ 11.797550] CPU: 0 PID: 11 Comm: rcu_preempt Not tainted 3.12.15-rt25+ #52
> [ 11.797630] [<c00151bc>] (unwind_backtrace+0x0/0xf4) from [<c0012c00>] (show_stack+0x10/0x14)
> [ 11.797691] [<c0012c00>] (show_stack+0x10/0x14) from [<c01b2758>] (do_raw_spin_trylock+0x4c/0x58)
> [ 11.797748] [<c01b2758>] (do_raw_spin_trylock+0x4c/0x58) from [<c02e0194>] (_raw_spin_trylock+0x20/0x98)
> [ 11.797792] [<c02e0194>] (_raw_spin_trylock+0x20/0x98) from [<c02df734>] (rt_spin_trylock+0x14/0xd0)
> [ 11.797851] [<c02df734>] (rt_spin_trylock+0x14/0xd0) from [<c0028e7c>] (run_local_timers+0x24/0x78)
> [ 11.797892] [<c0028e7c>] (run_local_timers+0x24/0x78) from [<c0028f04>] (update_process_times+0x34/0x68)
> [ 11.797940] [<c0028f04>] (update_process_times+0x34/0x68) from [<c0060920>] (tick_sched_timer+0x58/0x22c)
> [ 11.797990] [<c0060920>] (tick_sched_timer+0x58/0x22c) from [<c0040820>] (__run_hrtimer+0x88/0x2b8)
> [ 11.798029] [<c0040820>] (__run_hrtimer+0x88/0x2b8) from [<c0040bb0>] (hrtimer_interrupt+0x104/0x30c)
> [ 11.798076] [<c0040bb0>] (hrtimer_interrupt+0x104/0x30c) from [<c0246c50>] (mxs_timer_interrupt+0x20/0x2c)
> [ 11.798123] [<c0246c50>] (mxs_timer_interrupt+0x20/0x2c) from [<c00534d8>] (handle_irq_event_percpu+0x80/0x2f8)
> [ 11.798161] [<c00534d8>] (handle_irq_event_percpu+0x80/0x2f8) from [<c005378c>] (handle_irq_event+0x3c/0x5c)
> [ 11.798201] [<c005378c>] (handle_irq_event+0x3c/0x5c) from [<c0055f68>] (handle_level_irq+0x8c/0x118)
> [ 11.798239] [<c0055f68>] (handle_level_irq+0x8c/0x118) from [<c0053448>] (generic_handle_irq+0x28/0x30)
> [ 11.798281] [<c0053448>] (generic_handle_irq+0x28/0x30) from [<c00101dc>] (handle_IRQ+0x30/0x84)
> [ 11.798322] [<c00101dc>] (handle_IRQ+0x30/0x84) from [<c0013484>] (__irq_svc+0x44/0x88)
> [ 11.798364] [<c0013484>] (__irq_svc+0x44/0x88) from [<c02deb18>] (rt_spin_lock_slowlock+0x60/0x204)
> [ 11.798402] [<c02deb18>] (rt_spin_lock_slowlock+0x60/0x204) from [<c02df4d0>] (rt_spin_lock+0x28/0x60)
> [ 11.798451] [<c02df4d0>] (rt_spin_lock+0x28/0x60) from [<c0028874>] (lock_timer_base+0x28/0x48)
> [ 11.798494] [<c0028874>] (lock_timer_base+0x28/0x48) from [<c02dcb28>] (schedule_timeout+0x78/0x254)
> [ 11.798531] [<c02dcb28>] (schedule_timeout+0x78/0x254) from [<c00763a4>] (rcu_gp_kthread+0x2d4/0x5f0)
> [ 11.798578] [<c00763a4>] (rcu_gp_kthread+0x2d4/0x5f0) from [<c003cf24>] (kthread+0xa0/0xa8)
> [ 11.798621] [<c003cf24>] (kthread+0xa0/0xa8) from [<c000f3e0>] (ret_from_fork+0x14/0x34)

Thanks
--
Stano

2014-04-17 22:55:34

by Stanislav Meduna

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP - reverting timer patches helps

On 17.04.2014 18:29, Stanislav Meduna wrote:

> Note: the bug goes away reverting the very same patches that are
> helping the Jordan's problms. I did follow
>
> http://www.spinics.net/lists/linux-rt-users/msg11639.html
>
> and no BUG while booting anymore. I'll try to let it run some
> more time.

Erm.. nope

# (cat /proc/meminfo ; cat /proc/meminfo) | grep KernelStack
KernelStack: 5920 kB
KernelStack: 5928 kB

# (cat /proc/meminfo ; cat /proc/meminfo) | grep KernelStack
KernelStack: 5952 kB
KernelStack: 5960 kB

maybe interrupt nesting ad nauseum? How does one debug
such issues?

It is possible that my previous posting was also caused by this -
disregard, I'll post again if the problem persists.

Jordan, could you check whether your kernel stack remains
stable with only the 3 patches reverted?

Thanks
--
Stano

2014-04-17 23:10:19

by jordan

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP - reverting timer patches helps

Hey Stano,

On Thu, Apr 17, 2014 at 6:55 PM, Stanislav Meduna <[email protected]> wrote:
> On 17.04.2014 18:29, Stanislav Meduna wrote:
>
>> Note: the bug goes away reverting the very same patches that are
>> helping the Jordan's problms. I did follow
>>
>> http://www.spinics.net/lists/linux-rt-users/msg11639.html
>>
>> and no BUG while booting anymore. I'll try to let it run some
>> more time.

Yeah, i know a handful of people [amd users] that have now reported
success booting into 3.14-rt1 reverting those patches. Personally, I
have disabled NO_HZ_FULL and have switched back to 'old tick' method
in kconfig. I don't think the latest no_hz stuff is stable enough...

> Erm.. nope
>
> # (cat /proc/meminfo ; cat /proc/meminfo) | grep KernelStack
> KernelStack: 5920 kB
> KernelStack: 5928 kB
>
> # (cat /proc/meminfo ; cat /proc/meminfo) | grep KernelStack
> KernelStack: 5952 kB
> KernelStack: 5960 kB
>
> maybe interrupt nesting ad nauseum? How does one debug
> such issues?
>
> It is possible that my previous posting was also caused by this -
> disregard, I'll post again if the problem persists.
>
> Jordan, could you check whether your kernel stack remains
> stable with only the 3 patches reverted?

I'll have to re-install that kernel and get back to you [ give me an
hour or so. i desperately need to eat some food ;) ]. My current
kernel differs in a couple of ways [ but yes, the KernelStack is
stable]. My running/installed rt-kernel is using the 'threadsirq'
patch for linux-rt and isn't vanilla linux-rt anyway, as i patch in
UKSM [in-kernel memory deduplication and BFQ [is scheduler]... but
yes, I'm still reverting those 3 timer[s] patches, since my machine
[and other users i know] won't boot without doing that. Here's my
running kernel's kstack;

[ninez@localhost ~]$ (cat /proc/meminfo ; cat /proc/meminfo) | grep
KernelStack
KernelStack: 3728 kB
KernelStack: 3728 kB
[ninez@localhost ~]$ (cat /proc/meminfo ; cat /proc/meminfo) | grep
KernelStack
KernelStack: 3696 kB
KernelStack: 3696 kB

I'll post from my old kernel in a bit.

> Thanks

No problem

Jordan

2014-04-18 01:17:04

by jordan

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP - reverting timer patches helps

Hey again,

> [ninez@localhost ~]$ (cat /proc/meminfo ; cat /proc/meminfo) | grep
> KernelStack
> KernelStack: 3728 kB
> KernelStack: 3728 kB
> [ninez@localhost ~]$ (cat /proc/meminfo ; cat /proc/meminfo) | grep
> KernelStack
> KernelStack: 3696 kB
> KernelStack: 3696 kB
>
> I'll post from my old kernel in a bit.

my other machines all report kstack as being stable/consistent - I
also had an Archlinux user of my kernel check his box - his was
consistent too. [all of those boxes reverted those timer patches].

cheerz

Jordan

2014-04-18 14:45:33

by Stanislav Meduna

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP - reverting timer patches helps

On 18.04.2014 01:10, jordan wrote:

Hi Jordan,

many thanks for the tests. I probably botched something during
the reverting - I now tried some more experiments and the system
now runs without BUGs and without kernel leak - of course
it needs some more uptime to be really sure.

My combined revert patch from 3.12.15-rt25 is at
http://pastebin.com/MYLqbmZw
That was all that was needed.

> Yeah, i know a handful of people [amd users] that have now reported
> success booting into 3.14-rt1 reverting those patches. Personally, I
> have disabled NO_HZ_FULL and have switched back to 'old tick' method
> in kconfig. I don't think the latest no_hz stuff is stable enough...

My problems were with periodic timers (I am on an embedded system
that runs things periodically anyway and I have also my doubts
regarding the stability), so the latest code did not break
only NO_HZ_FULL.

Thanks
--
Stano

2014-04-18 15:09:22

by jordan

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP - reverting timer patches helps

Hey slavo

> many thanks for the tests. I probably botched something during
> the reverting - I now tried some more experiments and the system
> now runs without BUGs and without kernel leak - of course
> it needs some more uptime to be really sure.

No problem. It's good to hear that is working. My AMD Phenom II 965
has 1day, 10hours uptime. Hopefully that foreshadows your system
running well.

> My combined revert patch from 3.12.15-rt25 is at
> http://pastebin.com/MYLqbmZw
> That was all that was needed.

Yup. I suggest anyone from the list who can't get their machines to
boot with those commits applied, test that patch.

>> Yeah, i know a handful of people [amd users] that have now reported
>> success booting into 3.14-rt1 reverting those patches. Personally, I
>> have disabled NO_HZ_FULL and have switched back to 'old tick' method
>> in kconfig. I don't think the latest no_hz stuff is stable enough...
>
> My problems were with periodic timers (I am on an embedded system
> that runs things periodically anyway and I have also my doubts
> regarding the stability), so the latest code did not break
> only NO_HZ_FULL.

ah, thanks for the clarification [ i must have missed that bit - i was
just glad someone else had verified on the list that those commits
were problematic, as i hadn't gotten any response]. NO_HZ_FULL had
been alright for me, for a while - so i didn't really notice the
breakage with periodic timers, but that is good to know.

I think periodic timers + reverting those patches + resurrecting sirq
threads on seems to be the best on 3.14-rt, afaict.

Jordan

> Thanks
> --
> Stano
>

Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

* Stanislav Meduna | 2014-04-16 00:08:49 [+0200]:

>Hmm... how is it in the rt-case guaranteed that the timer interrupt
>does not preempt someone trying to modify the timer? The run_local_timers
>looks to have arrived via hardirq context. The spinlock in the tvec_base
>is a normal one and spin_lock_irqsave does not disable interrupts
>on rt, right?

this is, erm, harmless. We grab the timer lock via trylock in hardirq
context. If the lock is already taken then we fail to get it we go for
plan B. According to lockdep a trylock should not fail on UP. This is
true in general except for this timer case. I was thinking abour
disabling this lockdep check…

Sebastian

2014-04-22 13:47:06

by Steven Rostedt

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

[ added Peter ]

On Tue, 22 Apr 2014 13:54:39 +0200
Sebastian Andrzej Siewior <[email protected]> wrote:

> this is, erm, harmless. We grab the timer lock via trylock in hardirq
> context. If the lock is already taken then we fail to get it we go for
> plan B. According to lockdep a trylock should not fail on UP. This is
> true in general except for this timer case. I was thinking abour
> disabling this lockdep check…

trylock not failing on UP, can that be an issue? I mean, if a hardirq
does a trylock to see if it can grab a lock that is not protected by
disabling irqs, and will go to plan B if it fails, on UP, it will
always get it. But the issue is still there. That would mean that a
hardirq could have preempted a critical section and doing a trylock
here would succeed when it really should have failed.

-- Steve

Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On 04/22/2014 03:46 PM, Steven Rostedt wrote:
> [ added Peter ]
>
> On Tue, 22 Apr 2014 13:54:39 +0200
> Sebastian Andrzej Siewior <[email protected]> wrote:
>
>> this is, erm, harmless. We grab the timer lock via trylock in hardirq
>> context. If the lock is already taken then we fail to get it we go for
>> plan B. According to lockdep a trylock should not fail on UP. This is
>> true in general except for this timer case. I was thinking abour
>> disabling this lockdep check…
>
> trylock not failing on UP, can that be an issue? I mean, if a hardirq
> does a trylock to see if it can grab a lock that is not protected by
> disabling irqs, and will go to plan B if it fails, on UP, it will
> always get it. But the issue is still there. That would mean that a
> hardirq could have preempted a critical section and doing a trylock
> here would succeed when it really should have failed.

If you take a lock with irqs enabled and disabled then lockdep should
complain about it.

This is the ->wait_lock of the timer base lock. This (sleeping) lock is
usually taken with interrupts enabled. Except here, in the timer
callback, we check if the lock is available or not. And this lock may
be a) taken (and the ->wait_lock unlocked) or b) in process to be taken
but the caller only succeeded to acquire the ->wait_lock before the
interrupt occurred. This is the case here and we can't acquire the
->wait_lock a second time the check if the lock is really taken. But
since the wait_lock is occupied it is likely that the lock itself is
occupied as well.

>
> -- Steve

Sebastian

2014-04-22 17:48:08

by Steven Rostedt

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On Tue, 22 Apr 2014 18:51:17 +0200
Sebastian Andrzej Siewior <[email protected]> wrote:

> On 04/22/2014 03:46 PM, Steven Rostedt wrote:
> > [ added Peter ]
> >
> > On Tue, 22 Apr 2014 13:54:39 +0200
> > Sebastian Andrzej Siewior <[email protected]> wrote:
> >
> >> this is, erm, harmless. We grab the timer lock via trylock in hardirq
> >> context. If the lock is already taken then we fail to get it we go for
> >> plan B. According to lockdep a trylock should not fail on UP. This is
> >> true in general except for this timer case. I was thinking abour
> >> disabling this lockdep check…
> >
> > trylock not failing on UP, can that be an issue? I mean, if a hardirq
> > does a trylock to see if it can grab a lock that is not protected by
> > disabling irqs, and will go to plan B if it fails, on UP, it will
> > always get it. But the issue is still there. That would mean that a
> > hardirq could have preempted a critical section and doing a trylock
> > here would succeed when it really should have failed.
>
> If you take a lock with irqs enabled and disabled then lockdep should
> complain about it.

There's nothing wrong with taking locks with irqs enabled and disabled.
It's only wrong if that lock (or a lock that is held when the lock is
taken) is also taking in interrupt *context*.

>
> This is the ->wait_lock of the timer base lock. This (sleeping) lock is
> usually taken with interrupts enabled. Except here, in the timer
> callback, we check if the lock is available or not. And this lock may
> be a) taken (and the ->wait_lock unlocked) or b) in process to be taken
> but the caller only succeeded to acquire the ->wait_lock before the
> interrupt occurred. This is the case here and we can't acquire the
> ->wait_lock a second time the check if the lock is really taken. But
> since the wait_lock is occupied it is likely that the lock itself is
> occupied as well.

I need to take a deeper look into the actual code. But as trylocks on
UP are nops (always succeed), and if it expects to be able to do
something in a critical section that is protected by spinlocks (again
nops on UP), this would be broken for UP.

-- Steve

2014-04-22 18:16:55

by Steven Rostedt

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On Tue, 22 Apr 2014 13:48:02 -0400
Steven Rostedt <[email protected]> wrote:

> I need to take a deeper look into the actual code. But as trylocks on
> UP are nops (always succeed), and if it expects to be able to do
> something in a critical section that is protected by spinlocks (again
> nops on UP), this would be broken for UP.

Reading the code, I see it's broken. We should add something like this:

Signed-off-by: Steven Rostedt <[email protected]>
---
diff --git a/kernel/timer.c b/kernel/timer.c
index cc34e42..a03164a 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -1447,6 +1447,12 @@ static void run_timer_softirq(struct softirq_action *h)
__run_timers(base);
}

+#ifdef CONFIG_SMP
+#define timer_should_raise_softirq(lock) !spin_do_trylock(lock)
+#else
+#define timer_should_raise_softirq(lock) 1
+#endif
+
/*
* Called by the local, per-CPU timer interrupt on SMP.
*/
@@ -1467,7 +1473,7 @@ void run_local_timers(void)
return;
}

- if (!spin_do_trylock(&base->lock)) {
+ if (timer_should_raise_softirq(&base->lock)) {
raise_softirq(TIMER_SOFTIRQ);
return;
}

2014-04-22 19:58:53

by Peter Zijlstra

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On Tue, Apr 22, 2014 at 09:46:57AM -0400, Steven Rostedt wrote:
> > According to lockdep a trylock should not fail on UP.

Oh!? Where does it say that? A trylock can fail at all times.

Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On 04/22/2014 08:16 PM, Steven Rostedt wrote:
> --- a/kernel/timer.c
> +++ b/kernel/timer.c
> @@ -1447,6 +1447,12 @@ static void run_timer_softirq(struct softirq_action *h)
> __run_timers(base);
> }
>
> +#ifdef CONFIG_SMP
> +#define timer_should_raise_softirq(lock) !spin_do_trylock(lock)
> +#else
> +#define timer_should_raise_softirq(lock) 1
> +#endif
> +

No. The lock may be taken but it also may be available no matter if UP
or not. With this patch applied the lockdep splat will go away but the
FULL_NO_HZ people will come back because the timer softirq is scheduled
even if no timer has expired.

Sebastian

Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On 04/22/2014 04:09 PM, Peter Zijlstra wrote:
> On Tue, Apr 22, 2014 at 09:46:57AM -0400, Steven Rostedt wrote:
>>> According to lockdep a trylock should not fail on UP.
>
> Oh!? Where does it say that? A trylock can fail at all times.

kernel/locking/spinlock_debug.c:

int do_raw_spin_trylock(raw_spinlock_t *lock)
{
int ret = arch_spin_trylock(&lock->raw_lock);

if (ret)
debug_spin_lock_after(lock);
#ifndef CONFIG_SMP
/*
* Must not happen on UP:
*/
SPIN_BUG_ON(!ret, lock, "trylock failure on UP");
#endif
return ret;
}

How can a trylock (spinlock, not mutex) fail on UP? That would mean the
lock is not interrupt safe.
Unless, you attempt to take the lock from interrupt context via trylock
while in general you take the spinlock in process context with
interrupts enabled.

Sebastian

2014-04-23 08:49:47

by Peter Zijlstra

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On Wed, Apr 23, 2014 at 09:14:33AM +0200, Sebastian Andrzej Siewior wrote:
> On 04/22/2014 08:16 PM, Steven Rostedt wrote:
> > --- a/kernel/timer.c
> > +++ b/kernel/timer.c
> > @@ -1447,6 +1447,12 @@ static void run_timer_softirq(struct softirq_action *h)
> > __run_timers(base);
> > }
> >
> > +#ifdef CONFIG_SMP
> > +#define timer_should_raise_softirq(lock) !spin_do_trylock(lock)
> > +#else
> > +#define timer_should_raise_softirq(lock) 1
> > +#endif
> > +
>
> No. The lock may be taken but it also may be available no matter if UP
> or not. With this patch applied the lockdep splat will go away but the
> FULL_NO_HZ people will come back because the timer softirq is scheduled
> even if no timer has expired.

You can do FULL_NO_HZ on UP ? That seems rather pointless, as there
isn't a 'spare' CPU to do all the timekeeping on.

2014-04-23 08:50:40

by Peter Zijlstra

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On Wed, Apr 23, 2014 at 10:10:01AM +0200, Sebastian Andrzej Siewior wrote:
> On 04/22/2014 04:09 PM, Peter Zijlstra wrote:
> > On Tue, Apr 22, 2014 at 09:46:57AM -0400, Steven Rostedt wrote:
> >>> According to lockdep a trylock should not fail on UP.
> >
> > Oh!? Where does it say that? A trylock can fail at all times.
>
> kernel/locking/spinlock_debug.c:
>
> int do_raw_spin_trylock(raw_spinlock_t *lock)
> {
> int ret = arch_spin_trylock(&lock->raw_lock);
>
> if (ret)
> debug_spin_lock_after(lock);
> #ifndef CONFIG_SMP
> /*
> * Must not happen on UP:
> */
> SPIN_BUG_ON(!ret, lock, "trylock failure on UP");
> #endif
> return ret;
> }
>
> How can a trylock (spinlock, not mutex) fail on UP? That would mean the
> lock is not interrupt safe.
> Unless, you attempt to take the lock from interrupt context via trylock
> while in general you take the spinlock in process context with
> interrupts enabled.

But that's not lockdep. That's the spinlock debugging code, entirely
different beasts.

2014-04-23 12:15:33

by Steven Rostedt

[permalink] [raw]
Subject: Re: BUG: spinlock trylock failure on UP, i.MX28 3.12.15-rt25

On Wed, 23 Apr 2014 09:14:33 +0200
Sebastian Andrzej Siewior <[email protected]> wrote:

> On 04/22/2014 08:16 PM, Steven Rostedt wrote:
> > --- a/kernel/timer.c
> > +++ b/kernel/timer.c
> > @@ -1447,6 +1447,12 @@ static void run_timer_softirq(struct softirq_action *h)
> > __run_timers(base);
> > }
> >
> > +#ifdef CONFIG_SMP
> > +#define timer_should_raise_softirq(lock) !spin_do_trylock(lock)
> > +#else
> > +#define timer_should_raise_softirq(lock) 1
> > +#endif
> > +
>
> No. The lock may be taken but it also may be available no matter if UP
> or not. With this patch applied the lockdep splat will go away but the
> FULL_NO_HZ people will come back because the timer softirq is scheduled
> even if no timer has expired.

Although, as Peter said FULL_NO_HZ is pretty pointless on UP, but I've
been thinking this from a non PREEMPT_RT viewpoint. In non PREEMPT_RT,
spin_locks() are nops, where this is an issue, but in PREEMPT_RT, they
are mutexes, BUT!

The rt_mutex use wait_lock to protect its internal state, which is a raw
spinlock, and in UP it's a nop. That means there's nothing preventing
an interrupt here from corrupting the rtmutex's internal state. I see
this is still an issue, and the warning is still valid.

-- Steve