[alsa-devel] sound/core/timer.c: inconsistent lock state reported for tu->qlock
Hi,
I got the following log from a rarely used PC that I just updated from 2.6.34-rc4 to 2.6.34-rc5. I don't know though under which kernel I last used the soundcard of it; could have been 2.6.33, could have been a .34-rc. It is an x86 Mac mini with
00:1b.0 Audio device: Intel Corporation 82801G (ICH7 Family) High Definition Audio Controller (rev 02)
Kernel is vanilla except for various firewire patches, which should not matter to this issue.
================================= [ INFO: inconsistent lock state ] 2.6.34-rc5 #5 --------------------------------- inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. dolphin/4003 [HC1[1]:SC0[0]:HE0:SE1] takes: (&(&tu->qlock)->rlock){?.+...}, at: [<f84ec472>] snd_timer_user_tinterrupt+0x28/0x132 [snd_timer] {HARDIRQ-ON-W} state was registered at: [<c1048de9>] __lock_acquire+0x654/0x1482 [<c1049c73>] lock_acquire+0x5c/0x73 [<c125ac3e>] _raw_spin_lock+0x25/0x34 [<f84ec370>] snd_timer_user_ccallback+0x55/0x95 [snd_timer] [<f84ecc4b>] snd_timer_notify1+0x53/0xca [snd_timer] [<f84ecdbe>] _snd_timer_stop+0xfc/0x106 [snd_timer] [<f84eceab>] snd_timer_stop+0x13/0x42 [snd_timer] [<f84ee2dc>] snd_timer_user_ioctl+0xa27/0xaf5 [snd_timer] [<c1092c2f>] vfs_ioctl+0x22/0x87 [<c10931aa>] do_vfs_ioctl+0x472/0x4ac [<c1093210>] sys_ioctl+0x2c/0x45 [<c1002850>] sysenter_do_call+0x12/0x36 irq event stamp: 2042234 hardirqs last enabled at (2042233): [<c1002883>] sysenter_exit+0xf/0x18 hardirqs last disabled at (2042234): [<c1002d67>] common_interrupt+0x27/0x34 softirqs last enabled at (2042226): [<c102cfc3>] __do_softirq+0x102/0x10a softirqs last disabled at (2042221): [<c102cff6>] do_softirq+0x2b/0x43
other info that might help us debug this: 2 locks held by dolphin/4003: #0: (snd_pcm_link_rwlock){.-....}, at: [<f8eb0a35>] snd_pcm_period_elapsed+0x2a/0xaf [snd_pcm] #1: (&(&substream->self_group.lock)->rlock){-.....}, at: [<f8eb0a3f>] snd_pcm_period_elapsed+0x34/0xaf [snd_pcm]
stack backtrace: Pid: 4003, comm: dolphin Tainted: G W 2.6.34-rc5 #5 Call Trace: [<c125882d>] ? printk+0xf/0x12 [<c104761b>] print_usage_bug+0x14e/0x15a [<c10478c8>] mark_lock+0x2a1/0x4a7 [<c1048066>] ? check_usage_forwards+0x0/0xb0 [<c1048d69>] __lock_acquire+0x5d4/0x1482 [<c1049c08>] ? __lock_acquire+0x1473/0x1482 [<c1049c73>] lock_acquire+0x5c/0x73 [<f84ec472>] ? snd_timer_user_tinterrupt+0x28/0x132 [snd_timer] [<c125ac3e>] _raw_spin_lock+0x25/0x34 [<f84ec472>] ? snd_timer_user_tinterrupt+0x28/0x132 [snd_timer] [<f84ec472>] snd_timer_user_tinterrupt+0x28/0x132 [snd_timer] [<f84ec44a>] ? snd_timer_user_tinterrupt+0x0/0x132 [snd_timer] [<f84ed2e1>] snd_timer_interrupt+0x213/0x264 [snd_timer] [<c125ac45>] ? _raw_spin_lock+0x2c/0x34 [<f8eb0a7d>] snd_pcm_period_elapsed+0x72/0xaf [snd_pcm] [<f8f733bb>] azx_interrupt+0x8d/0x109 [snd_hda_intel] [<c1057fb0>] handle_IRQ_event+0x1d/0xa2 [<c105980b>] handle_fasteoi_irq+0x79/0xb2 [<c10046ff>] handle_irq+0x3b/0x48 [<c1003f3d>] do_IRQ+0x45/0x9f [<c1002d6e>] common_interrupt+0x2e/0x34 [<c1250000>] ? piix_init_one+0x1d2/0x628
We should disable irqs when we take the tu->qlock because it is used in the irq handler. The only place that doesn't is snd_timer_user_ccallback(). Most of the time snd_timer_user_ccallback() is called with interrupts disabled but the the first ti->ccallback() call in snd_timer_notify1() has interrupts enabled.
This was caught by lockdep which generates the following message:
================================= [ INFO: inconsistent lock state ] 2.6.34-rc5 #5
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. dolphin/4003 [HC1[1]:SC0[0]:HE0:SE1] takes: (&(&tu->qlock)->rlock){?.+...}, at: [<f84ec472>] snd_timer_user_tinterrupt+0x28/0x132 [snd_timer] {HARDIRQ-ON-W} state was registered at: [<c1048de9>] __lock_acquire+0x654/0x1482 [<c1049c73>] lock_acquire+0x5c/0x73 [<c125ac3e>] _raw_spin_lock+0x25/0x34 [<f84ec370>] snd_timer_user_ccallback+0x55/0x95 [snd_timer] [<f84ecc4b>] snd_timer_notify1+0x53/0xca [snd_timer]
Reported-by: Stefan Richter stefanr@s5r6.in-berlin.de Signed-off-by: Dan Carpenter error27@gmail.com
diff --git a/sound/core/timer.c b/sound/core/timer.c index 7394365..5040c7b 100644 --- a/sound/core/timer.c +++ b/sound/core/timer.c @@ -1160,6 +1160,7 @@ static void snd_timer_user_ccallback(struct snd_timer_instance *timeri, { struct snd_timer_user *tu = timeri->callback_data; struct snd_timer_tread r1; + unsigned long flags;
if (event >= SNDRV_TIMER_EVENT_START && event <= SNDRV_TIMER_EVENT_PAUSE) @@ -1169,9 +1170,9 @@ static void snd_timer_user_ccallback(struct snd_timer_instance *timeri, r1.event = event; r1.tstamp = *tstamp; r1.val = resolution; - spin_lock(&tu->qlock); + spin_lock_irqsave(&tu->qlock, flags); snd_timer_user_append_to_tqueue(tu, &r1); - spin_unlock(&tu->qlock); + spin_unlock_irqrestore(&tu->qlock, flags); kill_fasync(&tu->fasync, SIGIO, POLL_IN); wake_up(&tu->qchange_sleep); }
At Wed, 28 Apr 2010 10:29:14 +0200, Dan Carpenter wrote:
We should disable irqs when we take the tu->qlock because it is used in the irq handler. The only place that doesn't is snd_timer_user_ccallback(). Most of the time snd_timer_user_ccallback() is called with interrupts disabled but the the first ti->ccallback() call in snd_timer_notify1() has interrupts enabled.
This was caught by lockdep which generates the following message:
================================= [ INFO: inconsistent lock state ] 2.6.34-rc5 #5
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. dolphin/4003 [HC1[1]:SC0[0]:HE0:SE1] takes: (&(&tu->qlock)->rlock){?.+...}, at: [<f84ec472>] snd_timer_user_tinterrupt+0x28/0x132 [snd_timer] {HARDIRQ-ON-W} state was registered at: [<c1048de9>] __lock_acquire+0x654/0x1482 [<c1049c73>] lock_acquire+0x5c/0x73 [<c125ac3e>] _raw_spin_lock+0x25/0x34 [<f84ec370>] snd_timer_user_ccallback+0x55/0x95 [snd_timer] [<f84ecc4b>] snd_timer_notify1+0x53/0xca [snd_timer]
Reported-by: Stefan Richter stefanr@s5r6.in-berlin.de Signed-off-by: Dan Carpenter error27@gmail.com
Thanks, applied now. Will be included in the next pull request.
Takashi
diff --git a/sound/core/timer.c b/sound/core/timer.c index 7394365..5040c7b 100644 --- a/sound/core/timer.c +++ b/sound/core/timer.c @@ -1160,6 +1160,7 @@ static void snd_timer_user_ccallback(struct snd_timer_instance *timeri, { struct snd_timer_user *tu = timeri->callback_data; struct snd_timer_tread r1;
unsigned long flags;
if (event >= SNDRV_TIMER_EVENT_START && event <= SNDRV_TIMER_EVENT_PAUSE)
@@ -1169,9 +1170,9 @@ static void snd_timer_user_ccallback(struct snd_timer_instance *timeri, r1.event = event; r1.tstamp = *tstamp; r1.val = resolution;
- spin_lock(&tu->qlock);
- spin_lock_irqsave(&tu->qlock, flags); snd_timer_user_append_to_tqueue(tu, &r1);
- spin_unlock(&tu->qlock);
- spin_unlock_irqrestore(&tu->qlock, flags); kill_fasync(&tu->fasync, SIGIO, POLL_IN); wake_up(&tu->qchange_sleep);
}
participants (3)
-
Dan Carpenter -
Stefan Richter -
Takashi Iwai