[linux-dvb] Locking problem in dvb_demux?

Johannes Stezenbach js at linuxtv.org
Thu Jan 24 14:27:38 CET 2008


On Wed, Jan 23, 2008 at 10:46:30AM +0100, peter at naiadhome.com wrote:
> 
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547515] =================================
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547519] [ INFO: inconsistent lock state ]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547521] 2.6.23.14 #5
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547523] ---------------------------------
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547525] inconsistent {softirq-on-W} -> {in-softirq-W} usage.
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547527] startup1.pl/13742 [HC0[0]:SC1[1]:HE1:SE0] takes:
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547532] (&dvbdemux->lock){-+..}, at: [<f0a10df9>] dvb_dmx_swfilter_packets+0x1f/0x49 [dvb_core]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547590] {softirq-on-W} state was registered at:
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547598]   [<c0440eb7>] __lock_acquire+0x4aa/0xc1a
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547615]   [<c04416a1>] lock_acquire+0x7a/0x94
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547682]   [<c06339bd>] _spin_lock+0x2e/0x58
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547712]   [<f0a10c8b>] dvb_dmx_swfilter+0x21/0x104 [dvb_core]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547737]   [<f0d22383>] videobuf_dvb_thread+0x83/0x105 [video_buf_dvb]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547752]   [<c0435b9c>] kthread+0x3b/0x63
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547804]   [<c0405b9f>] kernel_thread_helper+0x7/0x10
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547874]   [<ffffffff>] 0xffffffff
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547888] irq event stamp: 22178648
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547889] hardirqs last  enabled at (22178648): [<c04298e8>] tasklet_action+0x26/0xa8
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547893] hardirqs last disabled at (22178647): [<c04298cd>] tasklet_action+0xb/0xa8
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547896] softirqs last  enabled at (22178536): [<c0429889>] __do_softirq+0xe3/0xe9
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547899] softirqs last disabled at (22178645): [<c0407046>] do_softirq+0x61/0xc7
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547903]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547903] other info that might help us debug this:
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547904] no locks held by startup1.pl/13742.
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547906]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547906] stack backtrace:
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547908]  [<c0405f18>] show_trace_log_lvl+0x1a/0x2f
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547911]  [<c040690a>] show_trace+0x12/0x14
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547914]  [<c0406922>] dump_stack+0x16/0x18
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547916]  [<c043f3b9>] print_usage_bug+0x140/0x14a
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547919]  [<c0440070>] mark_lock+0x12e/0x45b
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547921]  [<c0440e47>] __lock_acquire+0x43a/0xc1a
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547923]  [<c04416a1>] lock_acquire+0x7a/0x94
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547926]  [<c06339bd>] _spin_lock+0x2e/0x58
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547928]  [<f0a10df9>] dvb_dmx_swfilter_packets+0x1f/0x49 [dvb_core]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547937]  [<f091f73a>] vpeirq+0xc0/0x130 [budget_core]
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547941]  [<c0429915>] tasklet_action+0x53/0xa8
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547943]  [<c0429815>] __do_softirq+0x6f/0xe9
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547946]  [<c0407046>] do_softirq+0x61/0xc7
> Jan 22 11:00:17 TEMERAIRE kernel: [  218.547948]  =======================
> Jan 22 11:00:18 TEMERAIRE kernel: [  219.745305] saa7146_i2c_writeout: timed out waiting for end of xfer
...
> Now, I am interpreting this as saying that the demux->lock used in
> dvb_dxm_swfilter and dvb_dmx_swfilter_packets has become inconsistent.
> I think this has happened because one of the locks was taken from a
> soft IRQ.
> 
> Changing the spinlocks to spin_lock_irqsave/restore on that lock
> object in dvb_demux.c has stopped that error message.


I think the lockdep warning is bogus.

Disabling interrupts for extended periods of time
would cause latency problems for the rest of the
system, so spin_lock_irqsave is the wrong solution.


The problem is you have two different cards, one calling
dvb_dmx_swfilter from a kthread, and one calling it
from a softirq. But each card has its own demux->lock,
and the usage of these locks is consistent for each card.


dvb_dmx_swfilter was written to be used from hardirq
or softirq context. If it is called from a kernel thread,
the use of a spinlock is somewhat inappropriate.

Maybe you should talk to the lockdep guys to find out
what to do about this warning. Maybe a version of dvb_dmx_swfilter()
which uses demux->mutex for use by kthreads, and then
use this in videobuf-dvb.c, would solve it?


HTH,
Johannes



More information about the linux-dvb mailing list