2010-02-12 19:49:55

by Linus Torvalds

[permalink] [raw]
Subject: Linux 2.6.33-rc8


I think this is going to be the last -rc of the series, so please do test
it out. A number of regressions should be fixed, and while the regression
list doesn't make me _happy_, we didn't have the kind of nasty things that
went on before -rc7 and made me worried.

Some of the highlights inclure a netfilter/namespace bugfix, which
apparently got visibility now that a number of distributions seem to have
turned on the network namespace code. And more KMS regression fixes for
all the usual suspects - intel, nouveau, radeon (hopefully not causing
anything new).

The rest is random stuff all over. Mostly one-liners, except for a
defconfig update for mips (that also show up in the dirstat).

Linus

---
17.3% arch/mips/configs/
17.8% arch/mips/
22.9% arch/
2.4% drivers/char/tpm/
2.5% drivers/char/
13.7% drivers/gpu/drm/i915/
11.4% drivers/gpu/drm/nouveau/
3.9% drivers/gpu/drm/radeon/
2.0% drivers/gpu/drm/vmwgfx/
31.1% drivers/gpu/drm/
31.2% drivers/gpu/
43.0% drivers/
6.3% fs/ocfs2/dlm/
12.7% fs/ocfs2/
18.4% fs/
3.9% net/netfilter/
9.0% net/
3.4% security/integrity/ima/
3.4% security/


---
Aaro Koskinen (1):
OMAP: hsmmc: fix memory leak

Abhijith Das (1):
GFS2: Fix error code

Al Viro (3):
befs: fix leak
Take ima_path_check() in nfsd past dentry_open() in nfsd_open()
Take ima_file_free() to proper place.

Alexander Duyck (1):
igb: make certain to reassign legacy interrupt vectors after reset

Alexey Dobriyan (4):
af_key: fix netns ops ordering on module load/unload
netlink: fix for too early rmmod
netfilter: nf_conntrack: restrict runtime expect hashsize modifications
netfilter: xtables: compat out of scope fix

Amit Kumar Salecha (2):
netxen: fix tx timeout recovery for NX2031 chip
netxen: protect resource cleanup by rtnl lock

Anatolij Gustschin (1):
dmaengine: fix memleak in dma_async_device_unregister

Andreas Schwab (1):
compat_ioctl: add compat handler for TIOCGSID ioctl

Andy Getzendanner (1):
vgaarb: fix incorrect dereference of userspace pointer.

Andy Shevchenko (1):
x86, doc: Fix minor spelling error in arch/x86/mm/gup.c

Aneesh Kumar K.V (1):
9p: Fix the kernel crash on a failed mount

Anirban Chakraborty (1):
[SCSI] qla2xxx: Obtain proper host structure during response-queue processing.

Anton Blanchard (1):
ixgbe: Fix ixgbe_tx_map error path

Arnd Bergmann (1):
compat_ioctl: ignore RAID_VERSION ioctl

Ben Skeggs (5):
drm/nouveau: fix non-vram notifier blocks
drm/nv40: make INIT_COMPUTE_MEM a NOP, just like nv50
drm/nouveau: make dp auxch xfer len check for reads only
drm/nv50: prevent multiple init tables being parsed at the same time
drm/nv50: disregard dac outputs in nv50_sor_dpms()

Borislav Petkov (1):
amd64_edac: Do not falsely trigger kerneloops

Chris Wilson (1):
drm/i915: Increase fb alignment to 64k

Dan Williams (1):
ioat: fix infinite timeout checking in ioat2_quiesce

Daniel Vetter (1):
drm/i915: Update write_domains on active list after flush.

Dave Airlie (5):
drm/radeon/kms: change Kconfig text to reflect the new option.
drm/radeon/kms: don't crash if no DDC bus on VGA/DVI connector.
drm/radeon/kms: add quirk for VGA without DDC on rv730 XFX card.
drm/radeon/kms: fix screen clearing before fbcon.
drm/radeon/kms: retry auxch on 0x20 timeout value.

David Daney (2):
MIPS: Fix __devinit __cpuinit confusion in cpu_cache_init
MIPS: Don't probe reserved EntryHi bits.

David Gibson (1):
powerpc: Fix address masking bug in hpte_need_flush()

David S. Miller (2):
sparc: Align clone and signal stacks to 16 bytes.
sparc32: Fix thinko in previous change.

Divy Le Ray (1):
cxgb3: fix GRO checksum check

Dmitry Torokhov (1):
Input: psmouse - make sure we don't schedule reconnects after cleanup

Eric Dumazet (2):
netfilter: nf_conntrack: per netns nf_conntrack_cachep
dst: call cond_resched() in dst_gc_task()

Eric Paris (1):
ima: initialize ima before inodes can be allocated

Eric Van Hensbergen (6):
net/9p: fix virtio transport to correctly update status on connect
net/9p: fail when user specifies a transport which we can't find
net/9p: fix statsize inside twstat
9p: fix option parsing
9p: fix memory leak in v9fs_parse_options()
9p: fix p9_client_destroy unconditional calling v9fs_put_trans

FUJITA Tomonori (2):
x86/agp: Fix amd64-agp module initialization regression
[SCSI] compat_ioct: fix bsg SG_IO

Francesco Lavra (1):
V4L/DVB: dvb-core: fix initialization of feeds list in demux filter

Francisco Jerez (1):
drm/nouveau: Fixup semaphores on pre-nv50 cards.

Gerrit Renker (2):
dccp: fix bug in cache allocation
dccp: fix auto-loading of dccp(_probe)

Guennadi Liakhovetski (1):
async-tx: fix buffer submission error handling in ipu_idma.c

Hans-Christian Egtvedt (1):
avr32: clean up memory allocation in at32_add_device_mci

Heiko Carstens (1):
[S390] Fix struct _lowcore layout.

J. Bruce Fields (1):
Revert "nfsd4: fix error return when pseudoroot missing"

Jakob Bornecrantz (2):
drm/vmwgfx: Report propper framebuffer_{max|min}_{width|height}
drm/vmwgfx: Drop scanout flag compat and add execbuf ioctl parameter members. Bumps major.

Jan Glauber (1):
[S390] qdio: prevent call trace if CHPID is offline

Jan Luebbe (1):
net/sched: Fix module name in Kconfig

Jason Wang (2):
Export the symbol of getboottime and mmonotonic_to_bootbased
kvmclock: count total_sleep_time when updating guest clock

Jean Delvare (1):
i2c-tiny-usb: Fix on big-endian systems

Jeff Layton (2):
cifs: fix length calculation for converted unicode readdir names
cifs: fix dentry hash calculation for case-insensitive mounts

Jesse Barnes (3):
drm/i915: handle FBC and self-refresh better
drm/i915: untangle page flip completion
drm/i915: hold ref on flip object until it completes

Jody Bruchon (1):
ALSA: hda-intel: Avoid divide by zero crash

Joe Perches (1):
MAINTAINERS: networking drivers - Add git net-next tree

Johan Kristell (1):
mmc_test: block addressed cards

Julia Lawall (4):
drivers/gpu/drm/nouveau/nouveau_grctx.c: correct NULL test
drivers/net: Correct NULL test
drivers/dma: Correct NULL test
MIPS: SNI: Correct NULL test

Jun'ichi Nomura (1):
freeze_bdev: don't deactivate successfully frozen MS_RDONLY sb

Kashyap, Desai (1):
[SCSI] mptfusion : mptscsih_abort return value should be SUCCESS instead of value 0.

Krishna Kumar (1):
ixgbe: Fix return of invalid txq

Kyle McMartin (1):
parisc: fix tracing of signals

Linus Torvalds (2):
Fix race in tty_fasync() properly
Linux 2.6.33-rc8

Luca Barbieri (1):
drm/nouveau: call ttm_bo_wait with the bo lock held to prevent hang

M. Mohan Kumar (1):
9p: Include fsync support for 9p client

Maarten Maathuis (4):
drm/nv50: align size of buffer object to the right boundaries.
drm/nv50: avoid unloading pgraph context when ctxprog is running
drm/nv50: delete ramfc object after disabling fifo, not before
drm/nv50: make the pgraph irq handler loop like the pre-nv50 version

Marcel Holtmann (1):
Bluetooth: Fix sleeping function in RFCOMM within invalid context

Marcel Selhorst (1):
tpm_infineon: fix suspend/resume handler for pnp_driver

Marcelo Tosatti (1):
KVM: PIT: control word is write-only

Marcin Ko?cielnicki (4):
drm/nouveau: Add module options to disable acceleration.
drm/nouveau: Add getparam to get available PGRAPH units.
drm/nouveau: Fix fbcon on mixed pre-NV50 + NV50 multicard.
drm/nouveau: Add proper vgaarb support.

Marcin Slusarz (1):
drm/nouveau: move dereferences after null checks

Mark Brown (2):
wm97xx_battery: Handle missing platform data gracefully
regulator: Fix display of null constraints for regulators

Mark Nelson (1):
powerpc/pseries: Fix kexec regression caused by CPPR tracking

Matt Fleming (4):
sh: Correct the offset of the return address in ret_from_exception
sh: Setup frame pointer in handle_exception path
sh: Don't continue unwinding across interrupts
sh: Remove superfluous setup_frame_reg call

Matthew Garrett (1):
nouveau: fix state detection with switchable graphics

Mauro Carvalho Chehab (2):
V4L/DVB: Fix the risk of an oops at dvb_dmx_release
V4L/DVB: dvb_demux: Don't use vmalloc at dvb_dmx_swfilter_packet

Michael Neuling (1):
fs/exec.c: restrict initial stack space expansion to rlimit

Michael Poole (1):
Bluetooth: Keep a copy of each HID device's report descriptor

Michal Simek (1):
microblaze: Invalidate dcache before enabling it

Mike Frysinger (1):
[CPUFREQ] fix default value for ondemand governor

Mimi Zohar (3):
fix ima breakage
ima: rename ima_path_check to ima_file_check
ima: rename PATH_CHECK to FILE_CHECK

[email protected] (1):
[CPUFREQ] Fix ondemand to not request targets outside policy limits

NeilBrown (2):
md: fix 'degraded' calculation when starting a reshape.
md: fix some lockdep issues between md and sysfs.

Nick Pelly (3):
Bluetooth: Fallback eSCO to SCO on error 0x1a (Unsupported Remote Feature)
Bluetooth: Do not call rfcomm_session_put() for RFCOMM UA on closed socket
Bluetooth: Enter active mode before establishing a SCO link.

OGAWA Hirofumi (1):
ocfs2: Fix refcnt leak on ocfs2_fast_follow_link() error path

Owain Ainsworth (1):
drm/i915: Correctly return -ENOMEM on allocation failure in cmdbuf ioctls.

Patrick McHardy (2):
netfilter: nf_conntrack: fix memory corruption with multiple namespaces
netfilter: nf_conntrack: fix hash resizing with namespaces

Paul Mundt (2):
usb: r8a66597-hcd: Flush the D-cache for the pipe-in transfer buffers.
usb: r8a66597-hcd: Fix up spinlock recursion in root hub polling.

Pauli Nieminen (1):
drm/radeon: Skip dma copy test in benchmark if card doesn't have dma engine.

Peter Huewe (1):
arch/avr32: Fix build failure for avr32 caused by typo

Peter Tyser (2):
edac: mpc85xx fix bad page calculation
edac: mpc85xx fix build regression by removing unused debug code

Rafael J. Wysocki (2):
pktgen: Fix freezing problem
drm/i915: Fix crash while aborting hibernation

Rafa? Mi?ecki (1):
drm/radeon/kms: suspend and resume audio stuff

Ralf Baechle (1):
MIPS: IP27: Make defconfig useful again.

Rishikesh (1):
MAINTAINERS: changed LTP maintainership responsibilities

Roel Kluin (2):
ocfs2: Fix contiguousness check in ocfs2_try_to_merge_extent_map()
regulator/lp3971: vol_map out of bounds in lp3971_{ldo,dcdc}_set_voltage()

Sean Hefty (1):
RDMA/cm: Revert association of an RDMA device when binding to loopback

Serge E. Hallyn (1):
x86-32: Make AT_VECTOR_SIZE_ARCH=2

Shaohua Li (1):
cfq-iosched: split seeky coop queues after one slice

Stephen M. Cameron (1):
cciss: Make cciss_seq_show handle holes in the h->drv[] array

Steve French (3):
[CIFS] Add support for TCP_NODELAY
[CIFS] Maximum username length check in session setup does not match
[CIFS] Don't cache timestamps on utimes due to coarse granularity

Steven Whitehouse (1):
GFS2: Fix bmap allocation corner-case bug

Sunil Mushran (11):
ocfs2/trivial: Remove trailing whitespaces
ocfs2/dlm: Ignore LVBs of locks in the Blocked list
ocfs2/dlm: Print more messages during lock migration
ocfs2/dlm: Handle EAGAIN for compatibility - v2
ocfs2: Prevent a livelock in dlmglue
ocfs2: Do not downconvert if the lock level is already compatible
ocfs2: Remove overzealous BUG_ON during blocked lock processing
ocfs2: Plugs race between the dc thread and an unlock ast message
ocfs2/dlm: Remove BUG_ON in dlm recovery when freeing locks of a dead node
ocfs2/dlm: Fix printing of lockname
ocfs2/cluster: Make o2net connect messages KERN_NOTICE

Suresh Siddha (1):
x86, apic: Don't use logical-flat mode when CPU hotplug may exceed 8 CPUs

Swen Schillig (1):
[SCSI] zfcp: Report FC BSG errors in correct field

Takashi Iwai (1):
ALSA: hda - use WARN_ON_ONCE() for zero-division detection

Tao Ma (5):
ocfs2: Sync max_inline_data_with_xattr from tools.
ocfs2: Fix memory overflow in cow_by_page.
ocfs2: Only bug out when page size is larger than cluster size.
ocfs2: Add parenthesis to wrap the check for O_DIRECT.
ocfs2: Use compat_ptr in reflink_arguments.

Thadeu Lima de Souza Cascardo (2):
irda: unbalanced lock_kernel in irnet_ppp
irda: add missing BKL in irnet_ppp ioctl

Thomas Hellstrom (2):
drm/vmwgfx: Update the user-space interface.
drm/vmwgfx: Fix a circular locking dependency bug.

Thomas Renninger (1):
[CPUFREQ] Fix use after free of struct powernow_k8_data

Trond Myklebust (3):
NFS: Fix a bug in nfs_fscache_release_page()
NFS: Remove a redundant check for PageFsCache in nfs_migrate_page()
NFS: Fix the mapping of the NFSERR_SERVERFAULT error

Ursula Braun (1):
[S390] qdio: continue polling for buffer state ERROR

Wengang Wang (2):
ocfs2: fix a misleading variable name
ocfs2: Fix setting of OCFS2_LOCK_BLOCKED during bast

Wu Zhangjin (1):
MIPS: Fixup of the r4k timer

Xiaotian Feng (1):
[SCSI] qla2xxx: make msix interrupt handler safe for irq

Yoichi Yuasa (1):
Bluetooth: Fix memory leak in Marvell BT-over-SDIO driver

Yong Zhang (1):
dmaengine: correct onstack wait_queue_head declaration

Zhenyu Wang (3):
drm/i915: Rework DPLL calculation parameters for Ironlake
drm/i915: fix flip done interrupt on Ironlake
drm/i915: fix pipe source image setting in flip command

stephen hemminger (1):
sky2: fix transmit DMA map leakage


2010-02-12 20:11:12

by Thomas Backlund

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

12.02.2010 21:49, Linus Torvalds skrev:
>
> I think this is going to be the last -rc of the series, so please do test
> it out. A number of regressions should be fixed, and while the regression
> list doesn't make me _happy_, we didn't have the kind of nasty things that
> went on before -rc7 and made me worried.
>
> Some of the highlights inclure a netfilter/namespace bugfix, which
> apparently got visibility now that a number of distributions seem to have
> turned on the network namespace code. And more KMS regression fixes for
> all the usual suspects - intel, nouveau, radeon (hopefully not causing
> anything new).
>
> The rest is random stuff all over. Mostly one-liners, except for a
> defconfig update for mips (that also show up in the dirstat).
>
> Linus
>


Has the mirroring broken down ?

last thing I get out of git is:

commit 676ad585531e965416fd958747894541dabcec96
Merge: ffaa60d cab4d27
Author: Linus Torvalds <[email protected]>
Date: Thu Feb 11 14:07:13 2010 -0800

Merge branch 'for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/bp/bp

* 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/bp/bp:
amd64_edac: Do not falsely trigger kerneloops


And the same thing is shown on:
http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=summary

I'm in Finland, so I assume the European mirrors are responding,
but trying to use master.kernel.org or git.us.kernel.org shows the same...

--
Thomas

2010-02-12 20:27:57

by Paul Rolland

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

Hello,

On Fri, 12 Feb 2010 22:11:04 +0200
Thomas Backlund <[email protected]> wrote:

> 12.02.2010 21:49, Linus Torvalds skrev:
> >
> > I think this is going to be the last -rc of the series, so please do
> > test it out. A number of regressions should be fixed, and while the
> > regression list doesn't make me _happy_, we didn't have the kind of
> > nasty things that went on before -rc7 and made me worried.
> >
> Has the mirroring broken down ?

-ECANTDOWNLOAD

+1 from France using ftp.kernel.org :
ftp> dir linux-2.6.33-rc7*
227 Entering Passive Mode (199,6,1,164,158,19).
150 Here comes the directory listing.
-rw-rw-r-- 1 536 536 66191954 Feb 06 22:27 linux-2.6.33-rc7.tar.bz2
-rw-rw-r-- 1 536 536 248 Feb 06 22:27 linux-2.6.33-rc7.tar.bz2.sign
-rw-rw-r-- 1 536 536 84523618 Feb 06 22:27 linux-2.6.33-rc7.tar.gz
-rw-rw-r-- 1 536 536 248 Feb 06 22:27 linux-2.6.33-rc7.tar.gz.sign
-rw-rw-r-- 1 536 536 248 Feb 06 22:27 linux-2.6.33-rc7.tar.sign
226 Directory send OK.
ftp> dir linux-2.6.33-rc8*
227 Entering Passive Mode (199,6,1,164,203,16).
150 Here comes the directory listing.
226 Directory send OK.
ftp> quit

and http://www.kernel.org doesn't contain reference to -rc8 yet.

Paul


2010-02-12 20:39:23

by Thomas Backlund

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

12.02.2010 22:26, Paul Rolland skrev:
> Hello,
>
> On Fri, 12 Feb 2010 22:11:04 +0200
> Thomas Backlund<[email protected]> wrote:
>
>> 12.02.2010 21:49, Linus Torvalds skrev:
>>>
>>> I think this is going to be the last -rc of the series, so please do
>>> test it out. A number of regressions should be fixed, and while the
>>> regression list doesn't make me _happy_, we didn't have the kind of
>>> nasty things that went on before -rc7 and made me worried.
>>>
>> Has the mirroring broken down ?
>
> -ECANTDOWNLOAD
>
> +1 from France using ftp.kernel.org :
> ftp> dir linux-2.6.33-rc7*
> 227 Entering Passive Mode (199,6,1,164,158,19).
> 150 Here comes the directory listing.
> -rw-rw-r-- 1 536 536 66191954 Feb 06 22:27 linux-2.6.33-rc7.tar.bz2
> -rw-rw-r-- 1 536 536 248 Feb 06 22:27 linux-2.6.33-rc7.tar.bz2.sign
> -rw-rw-r-- 1 536 536 84523618 Feb 06 22:27 linux-2.6.33-rc7.tar.gz
> -rw-rw-r-- 1 536 536 248 Feb 06 22:27 linux-2.6.33-rc7.tar.gz.sign
> -rw-rw-r-- 1 536 536 248 Feb 06 22:27 linux-2.6.33-rc7.tar.sign
> 226 Directory send OK.
> ftp> dir linux-2.6.33-rc8*
> 227 Entering Passive Mode (199,6,1,164,203,16).
> 150 Here comes the directory listing.
> 226 Directory send OK.
> ftp> quit
>
> and http://www.kernel.org doesn't contain reference to -rc8 yet.
>


I _know_ that, that's why I ask !

Point is that I see -rc8 on git changelog on gmane,
but not on git.kernel.org, git.us.kernel.org, or ...

This has never happend before...
I usually see the -rcX tag on git.kernel.org _before_ Linus announces
this...

So I ask if the mirroring has broken for some reason...
For example the tests with XZ migration ...

--
Thomas

2010-02-12 22:24:43

by Stephen Rothwell

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

On Fri, 12 Feb 2010 11:49:33 -0800 (PST) Linus Torvalds <[email protected]> wrote:
>
> I think this is going to be the last -rc of the series, so please do test
> it out. A number of regressions should be fixed, and while the regression
> list doesn't make me _happy_, we didn't have the kind of nasty things that
> went on before -rc7 and made me worried.

Well, if http://neuling.org/linux-next-linus.png is anything to go by, we
should be having a very quiet 2.6.34 merge window, so there will be lots
of time for fixing any left over mess. :-)

--
Cheers,
Stephen Rothwell [email protected]
http://www.canb.auug.org.au/~sfr/


Attachments:
(No filename) (667.00 B)
(No filename) (198.00 B)
Download all attachments

2010-02-13 00:30:06

by Justin P. Mattock

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

On 02/12/10 14:24, Stephen Rothwell wrote:
> On Fri, 12 Feb 2010 11:49:33 -0800 (PST) Linus Torvalds<[email protected]> wrote:
>>
>> I think this is going to be the last -rc of the series, so please do test
>> it out. A number of regressions should be fixed, and while the regression
>> list doesn't make me _happy_, we didn't have the kind of nasty things that
>> went on before -rc7 and made me worried.
>
> Well, if http://neuling.org/linux-next-linus.png is anything to go by, we
> should be having a very quiet 2.6.34 merge window, so there will be lots
> of time for fixing any left over mess. :-)
>

working on bugs over here
(although walking away from
the screen is healthy).

As for the png. If I was an investor
this looks almost like all of the
pickings in the market(defiantly
can see a recession).

In any case hope people work on these
bugs.. I will be.

Justin P. Mattock

2010-02-13 09:16:21

by Geert Uytterhoeven

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

On Fri, Feb 12, 2010 at 23:24, Stephen Rothwell <[email protected]> wrote:
> On Fri, 12 Feb 2010 11:49:33 -0800 (PST) Linus Torvalds <[email protected]> wrote:
>>
>> I think this is going to be the last -rc of the series, so please do test
>> it out. A number of regressions should be fixed, and while the regression
>> list doesn't make me _happy_, we didn't have the kind of nasty things that
>> went on before -rc7 and made me worried.
>
> Well, if http://neuling.org/linux-next-linus.png is anything to go by, we
> should be having a very quiet 2.6.34 merge window, so there will be lots
> of time for fixing any left over mess. :-)

Interestingly, there's also a dip around 2.6.27, which was chosen as a
longer term stable release...

Gr{oetje,eeting}s,

Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- [email protected]

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds

2010-02-13 12:44:08

by Stephen Rothwell

[permalink] [raw]
Subject: Re: Linux 2.6.33-rc8

Hi Geert,

On Sat, 13 Feb 2010 10:16:16 +0100 Geert Uytterhoeven <[email protected]> wrote:
>
> Interestingly, there's also a dip around 2.6.27, which was chosen as a
> longer term stable release...

At the time of 2.6.27 I was in the middle of three weeks leave (and
linux-next was not being produced), so that could be an alternate
explanation :-)

--
Cheers,
Stephen Rothwell [email protected]
http://www.canb.auug.org.au/~sfr/


Attachments:
(No filename) (457.00 B)
(No filename) (198.00 B)
Download all attachments

2010-02-13 17:17:20

by Ed Tomlinson

[permalink] [raw]
Subject: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

Hi,

Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.

---
pcm.pulse {
type pulse
}

ctl.pulse {
type pulse
}

pcm.!default {
type pulse
}
ctl.!default {
type pulse
---

Try #1
Starting as root if I do:
su - <id>
aplay sound.wav
<traceback inlined below>
aplay sound.wav
(silence)
killall pulseaudio
aplay sound.wav
(works as expected now going thru pulseaudio)

Try #2
Starting as root if I do:
aplay sound.wav
(works as expected using alsa alone)
su - <id>
aplay sound.wav
<another lockdep traceback>
aplay sound.wav
(works as expected now going thru pulseaudio)

With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.

Ideas?
Ed Tomlinson

aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
Subdevices: 0/1
Subdevice #0: subdevice #0
card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
Subdevices: 1/1
Subdevice #0: subdevice #0
card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
Subdevices: 1/1
Subdevice #0: subdevice #0

"ALC1200 Analog" is what has speakers connected

The em28xx in the traceback is an input source from a usb hdtv dongle.

pavucontrol setup has been verified.

[ 91.070620]
[ 91.070621] =======================================================
[ 91.071378] [ INFO: possible circular locking dependency detected ]
[ 91.071378] 2.6.33-rc8-crc #106
[ 91.071378] -------------------------------------------------------
[ 91.071378] pulseaudio/2717 is trying to acquire lock:
[ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 91.071378]
[ 91.071378] but task is already holding lock:
[ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
[ 91.071378]
[ 91.071378] which lock already depends on the new lock.
[ 91.071378]
[ 91.071378]
[ 91.071378] the existing dependency chain (in reverse order) is:
[ 91.071378]
[ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
[ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
[ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
[ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
[ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
[ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
[ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
[ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
[ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 91.071378]
[ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
[ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
[ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
[ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
[ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
[ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
[ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
[ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 91.071378]
[ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
[ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
[ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
[ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
[ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
[ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
[ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
[ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
[ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
[ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
[ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
[ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
[ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
[ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
[ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
[ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
[ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
[ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
[ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
[ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
[ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
[ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
[ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
[ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
[ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
[ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 91.514885]
[ 91.514885] -> #0 (&dev->lock){+.+.+.}:
[ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
[ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
[ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
[ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
[ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
[ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
[ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
[ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
[ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
[ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
[ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
[ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 91.514885]
[ 91.514885] other info that might help us debug this:
[ 91.514885]
[ 91.514885] 1 lock held by pulseaudio/2717:
[ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
[ 91.514885]
[ 91.514885] stack backtrace:
[ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
[ 91.514885] Call Trace:
[ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
[ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
[ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
[ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
[ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
[ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
[ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
[ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
[ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
[ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
[ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
[ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
[ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
[ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
[ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
[ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
[ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
[ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
[ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
[ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
[ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
[ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.




2010-02-13 19:18:37

by Ed Tomlinson

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

On Saturday 13 February 2010 12:17:10 Ed Tomlinson wrote:

Looks like can also trigger an opps that force me to reboot. I tried
su - <id>
pulseaudio -D

and got the following lockdep traceback followed by an opps

This is grover.unknown_domain (Linux x86_64 2.6.33-rc8-crc) 13:53:37

grover login: [ 87.254950]
[ 87.254952] =======================================================
[ 87.255252] [ INFO: possible circular locking dependency detected ]
[ 87.255252] 2.6.33-rc8-crc #106
[ 87.255252] -------------------------------------------------------
[ 87.255252] pulseaudio/2800 is trying to acquire lock:
[ 87.255252] (&dev->lock){+.+.+.}, at: [<ffffffffa027d7f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 87.336024]
[ 87.336024] but task is already holding lock:
[ 87.336024] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa00ffcd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
[ 87.336024]
[ 87.336024] which lock already depends on the new lock.
[ 87.336024]
[ 87.336024]
[ 87.336024] the existing dependency chain (in reverse order) is:
[ 87.336024]
[ 87.336024] -> #3 (&pcm->open_mutex){+.+.+.}:
[ 87.336024] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
[ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 87.336024] [<ffffffffa00fbd32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
[ 87.336024] [<ffffffff8112115d>] __fput+0x15d/0x290
[ 87.336024] [<ffffffff811212ad>] fput+0x1d/0x30
[ 87.336024] [<ffffffff810fe001>] remove_vma+0x51/0x80
[ 87.336024] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
[ 87.336024] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
[ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 87.336024]
[ 87.336024] -> #2 (&mm->mmap_sem){++++++}:
[ 87.336024] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
[ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 87.336024] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
[ 87.336024] [<ffffffff8113102b>] filldir+0x7b/0xe0
[ 87.336024] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
[ 87.336024] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
[ 87.336024] [<ffffffff8113144d>] sys_getdents+0xad/0x110
[ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 87.336024]
[ 87.336024] -> #1 (sysfs_mutex){+.+.+.}:
[ 87.336024] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
[ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 87.336024] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
[ 87.336024] [<ffffffff8118bc58>] create_dir+0x58/0xb0
[ 87.336024] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
[ 87.336024] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
[ 87.336024] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
[ 87.336024] [<ffffffff8123eee4>] kobject_add+0x44/0x70
[ 87.336024] [<ffffffff81392510>] device_add+0xb0/0x5e0
[ 87.336024] [<ffffffff81392a5e>] device_register+0x1e/0x30
[ 87.336024] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
[ 87.336024] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
[ 87.336024] [<ffffffffa0207ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
[ 87.336024] [<ffffffffa0209daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
[ 87.336024] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
[ 87.336024] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
[ 87.336024] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
[ 87.336024] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
[ 87.336024] [<ffffffff8139535e>] driver_attach+0x1e/0x20
[ 87.336024] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
[ 87.336024] [<ffffffff81395a58>] driver_register+0x98/0x140
[ 87.336024] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
[ 87.336024] [<ffffffffa021e023>] 0xffffffffa021e023
[ 87.336024] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
[ 87.336024] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
[ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 87.336024]
[ 87.336024] -> #0 (&dev->lock){+.+.+.}:
[ 87.336024] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
[ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 87.336024] [<ffffffffa027d7f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 87.336024] [<ffffffffa00fbdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
[ 87.336024] [<ffffffffa00ffce9>] snd_pcm_open+0x199/0x450 [snd_pcm]
[ 87.336024] [<ffffffffa00fffd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
[ 87.336024] [<ffffffffa00da778>] snd_open+0x198/0x4e0 [snd]
[ 87.336024] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
[ 87.336024] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
[ 87.336024] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
[ 87.336024] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
[ 87.336024] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
[ 87.336024] [<ffffffff8111ea70>] sys_open+0x20/0x30
[ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 87.336024]
[ 87.336024] other info that might help us debug this:
[ 87.336024]
[ 87.336024] 1 lock held by pulseaudio/2800:
[ 87.336024] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa00ffcd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
[ 87.336024]
[ 87.336024] stack backtrace:
[ 87.336024] Pid: 2800, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
[ 87.336024] Call Trace:
[ 87.336024] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
[ 87.336024] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
[ 87.336024] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
[ 87.336024] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
[ 87.336024] [<ffffffffa027d7f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 87.336024] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
[ 87.336024] [<ffffffffa027d7f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 87.336024] [<ffffffffa027d7f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 87.336024] [<ffffffffa00fac70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
[ 87.336024] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
[ 87.336024] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
[ 87.336024] [<ffffffffa027d7f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
[ 87.336024] [<ffffffffa00fbdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
[ 87.336024] [<ffffffffa00ffce9>] snd_pcm_open+0x199/0x450 [snd_pcm]
[ 87.336024] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
[ 87.336024] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
[ 87.336024] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
[ 87.336024] [<ffffffffa00fffd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
[ 87.336024] [<ffffffffa00da778>] snd_open+0x198/0x4e0 [snd]
[ 87.336024] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
[ 87.336024] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
[ 87.336024] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
[ 87.336024] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
[ 87.336024] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
[ 87.336024] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
[ 87.336024] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
[ 87.336024] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
[ 87.336024] [<ffffffff8111ea70>] sys_open+0x20/0x30
[ 87.336024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 89.153381] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
[ 89.402672] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 89.403537] IP: [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0
[ 89.403537] PGD 16c019067 PUD 16c01a067 PMD 0
[ 89.403537] Oops: 0000 [#1] PREEMPT SMP
[ 89.403537] last sysfs file: /sys/devices/pci0000:00/0000:00:14.2/sound/card0/uevent
[ 89.403537] CPU 1
[ 89.403537] Pid: 2813, comm: console-kit-dae Not tainted 2.6.33-rc8-crc #106 M3A78-T/System Product Name
[ 89.403537] RIP: 0010:[<ffffffff8104dfe6>] [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0
[ 89.403537] RSP: 0018:ffff88016dfcfe88 EFLAGS: 00010293
[ 89.403537] RAX: ffff88016d29c318 RBX: fffffffffffffcf8 RCX: ffff88016b77d800
[ 89.403537] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff81a7f4c8
[ 89.403537] RBP: ffff88016dfcfee8 R08: 0000000000000002 R09: 0000000000000000
[ 89.403537] R10: 0000000000000000 R11: 0000000000000246 R12: ffff88016dfcff08
[ 89.403537] R13: ffff88016d29c020 R14: ffff88016bd38000 R15: ffff88016bd38000
[ 89.403537] FS: 00007f7fd4a7b700(0000) GS:ffff880028280000(0000) knlGS:0000000000000000
[ 89.403537] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 89.403537] CR2: 0000000000000000 CR3: 000000016b12e000 CR4: 00000000000006e0
[ 89.403537] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 89.600024] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 89.600024] Process console-kit-dae (pid: 2813, threadinfo ffff88016dfce000, task ffff88016bd38000)
[ 89.600024] Stack:
[ 89.600024] ffff88016bd38000 ffff88016bd38000 ffff88016dfcff30 ffff88016d29c318
[ 89.600024] <0> ffff88016dfcfee8 0000000000000000 ffffffff81069880 00007fff88aaff4c
[ 89.600024] <0> ffff88016b77d880 0000000000000000 000000000061ea60 00007fff88aaff9c
[ 89.600024] Call Trace:
[ 89.600024] [<ffffffff81069880>] ? find_get_pid+0x0/0x80
[ 89.600024] [<ffffffff8104e169>] sys_wait4+0x89/0xf0
[ 89.600024] [<ffffffff8104b650>] ? child_wait_callback+0x0/0x80
[ 89.600024] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 89.600024] Code: eb 29 0f 1f 00 48 89 da be 01 00 00 00 4c 89 e7 e8 f0 f1 ff ff 85 c0 0f 85 d0 00 00 00 48 8b 9b 08 03 00 00 48 81 eb 08 03 00 00 <48> 8b 83 08 03 00 00 0f 18 08 48 8d 83 08 03 00 00 48 39 45 b8
[ 89.600024] RIP [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0
[ 89.600024] RSP <ffff88016dfcfe88>
[ 89.600024] CR2: 0000000000000000
[ 89.600489] ---[ end trace 3efd4205cd3392b3 ]---
[ 89.600492] note: console-kit-dae[2813] exited with preempt_count 1

> Hi,
>
> Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
>
> ---
> pcm.pulse {
> type pulse
> }
>
> ctl.pulse {
> type pulse
> }
>
> pcm.!default {
> type pulse
> }
> ctl.!default {
> type pulse
> ---
>
> Try #1
> Starting as root if I do:
> su - <id>
> aplay sound.wav
> <traceback inlined below>
> aplay sound.wav
> (silence)
> killall pulseaudio
> aplay sound.wav
> (works as expected now going thru pulseaudio)
>
> Try #2
> Starting as root if I do:
> aplay sound.wav
> (works as expected using alsa alone)
> su - <id>
> aplay sound.wav
> <another lockdep traceback>
> aplay sound.wav
> (works as expected now going thru pulseaudio)
>
> With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
>
> Ideas?
> Ed Tomlinson
>
> aplay -l
> **** List of PLAYBACK Hardware Devices ****
> card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> Subdevices: 0/1
> Subdevice #0: subdevice #0
> card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> Subdevices: 1/1
> Subdevice #0: subdevice #0
> card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> Subdevices: 1/1
> Subdevice #0: subdevice #0
>
> "ALC1200 Analog" is what has speakers connected
>
> The em28xx in the traceback is an input source from a usb hdtv dongle.
>
> pavucontrol setup has been verified.
>
> [ 91.070620]
> [ 91.070621] =======================================================
> [ 91.071378] [ INFO: possible circular locking dependency detected ]
> [ 91.071378] 2.6.33-rc8-crc #106
> [ 91.071378] -------------------------------------------------------
> [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.071378]
> [ 91.071378] but task is already holding lock:
> [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> [ 91.071378]
> [ 91.071378] which lock already depends on the new lock.
> [ 91.071378]
> [ 91.071378]
> [ 91.071378] the existing dependency chain (in reverse order) is:
> [ 91.071378]
> [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.071378]
> [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.071378]
> [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.514885]
> [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.514885]
> [ 91.514885] other info that might help us debug this:
> [ 91.514885]
> [ 91.514885] 1 lock held by pulseaudio/2717:
> [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> [ 91.514885]
> [ 91.514885] stack backtrace:
> [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> [ 91.514885] Call Trace:
> [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
>
>
>
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
>

2010-02-15 19:20:26

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Sat, 13 Feb 2010 12:17:10 -0500,
Ed Tomlinson wrote:
>
> Hi,
>
> Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
>
> ---
> pcm.pulse {
> type pulse
> }
>
> ctl.pulse {
> type pulse
> }
>
> pcm.!default {
> type pulse
> }
> ctl.!default {
> type pulse
> ---
>
> Try #1
> Starting as root if I do:
> su - <id>
> aplay sound.wav
> <traceback inlined below>
> aplay sound.wav
> (silence)
> killall pulseaudio
> aplay sound.wav
> (works as expected now going thru pulseaudio)
>
> Try #2
> Starting as root if I do:
> aplay sound.wav
> (works as expected using alsa alone)
> su - <id>
> aplay sound.wav
> <another lockdep traceback>
> aplay sound.wav
> (works as expected now going thru pulseaudio)
>
> With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
>
> Ideas?
> Ed Tomlinson
>
> aplay -l
> **** List of PLAYBACK Hardware Devices ****
> card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> Subdevices: 0/1
> Subdevice #0: subdevice #0
> card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> Subdevices: 1/1
> Subdevice #0: subdevice #0
> card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> Subdevices: 1/1
> Subdevice #0: subdevice #0
>
> "ALC1200 Analog" is what has speakers connected
>
> The em28xx in the traceback is an input source from a usb hdtv dongle.
>
> pavucontrol setup has been verified.
>
> [ 91.070620]
> [ 91.070621] =======================================================
> [ 91.071378] [ INFO: possible circular locking dependency detected ]
> [ 91.071378] 2.6.33-rc8-crc #106
> [ 91.071378] -------------------------------------------------------
> [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.071378]
> [ 91.071378] but task is already holding lock:
> [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> [ 91.071378]
> [ 91.071378] which lock already depends on the new lock.
> [ 91.071378]
> [ 91.071378]
> [ 91.071378] the existing dependency chain (in reverse order) is:
> [ 91.071378]
> [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.071378]
> [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.071378]
> [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.514885]
> [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 91.514885]
> [ 91.514885] other info that might help us debug this:
> [ 91.514885]
> [ 91.514885] 1 lock held by pulseaudio/2717:
> [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> [ 91.514885]
> [ 91.514885] stack backtrace:
> [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> [ 91.514885] Call Trace:
> [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.

It looks rather a bug of em28xx driver. Changing dev->lock with an
individual one that is only for audio instance should fix the
problem.


Takashi

2010-02-15 19:21:58

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Mon, 15 Feb 2010 20:20:22 +0100,
I wrote:
>
> At Sat, 13 Feb 2010 12:17:10 -0500,
> Ed Tomlinson wrote:
> >
> > Hi,
> >
> > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
> >
> > ---
> > pcm.pulse {
> > type pulse
> > }
> >
> > ctl.pulse {
> > type pulse
> > }
> >
> > pcm.!default {
> > type pulse
> > }
> > ctl.!default {
> > type pulse
> > ---
> >
> > Try #1
> > Starting as root if I do:
> > su - <id>
> > aplay sound.wav
> > <traceback inlined below>
> > aplay sound.wav
> > (silence)
> > killall pulseaudio
> > aplay sound.wav
> > (works as expected now going thru pulseaudio)
> >
> > Try #2
> > Starting as root if I do:
> > aplay sound.wav
> > (works as expected using alsa alone)
> > su - <id>
> > aplay sound.wav
> > <another lockdep traceback>
> > aplay sound.wav
> > (works as expected now going thru pulseaudio)
> >
> > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
> >
> > Ideas?
> > Ed Tomlinson
> >
> > aplay -l
> > **** List of PLAYBACK Hardware Devices ****
> > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> > Subdevices: 0/1
> > Subdevice #0: subdevice #0
> > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> > Subdevices: 1/1
> > Subdevice #0: subdevice #0
> > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> > Subdevices: 1/1
> > Subdevice #0: subdevice #0
> >
> > "ALC1200 Analog" is what has speakers connected
> >
> > The em28xx in the traceback is an input source from a usb hdtv dongle.
> >
> > pavucontrol setup has been verified.
> >
> > [ 91.070620]
> > [ 91.070621] =======================================================
> > [ 91.071378] [ INFO: possible circular locking dependency detected ]
> > [ 91.071378] 2.6.33-rc8-crc #106
> > [ 91.071378] -------------------------------------------------------
> > [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > [ 91.071378]
> > [ 91.071378] but task is already holding lock:
> > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > [ 91.071378]
> > [ 91.071378] which lock already depends on the new lock.
> > [ 91.071378]
> > [ 91.071378]
> > [ 91.071378] the existing dependency chain (in reverse order) is:
> > [ 91.071378]
> > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > [ 91.071378]
> > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > [ 91.071378]
> > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > [ 91.514885]
> > [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > [ 91.514885]
> > [ 91.514885] other info that might help us debug this:
> > [ 91.514885]
> > [ 91.514885] 1 lock held by pulseaudio/2717:
> > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > [ 91.514885]
> > [ 91.514885] stack backtrace:
> > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> > [ 91.514885] Call Trace:
> > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
>
> It looks rather a bug of em28xx driver. Changing dev->lock with an
> individual one that is only for audio instance should fix the
> problem.

And, I believe this is no regression but a long-standing problem.
It hits just occasionally by an app like pulseauiod which loves
tight races.


Takashi

2010-02-15 22:25:01

by Ed Tomlinson

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

On Monday 15 February 2010 14:21:55 Takashi Iwai wrote:
> At Mon, 15 Feb 2010 20:20:22 +0100,
> I wrote:
> >
> > At Sat, 13 Feb 2010 12:17:10 -0500,
> > Ed Tomlinson wrote:
> > >
> > > Hi,
> > >
> > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
> > >
> > > ---
> > > pcm.pulse {
> > > type pulse
> > > }
> > >
> > > ctl.pulse {
> > > type pulse
> > > }
> > >
> > > pcm.!default {
> > > type pulse
> > > }
> > > ctl.!default {
> > > type pulse
> > > ---
> > >
> > > Try #1
> > > Starting as root if I do:
> > > su - <id>
> > > aplay sound.wav
> > > <traceback inlined below>
> > > aplay sound.wav
> > > (silence)
> > > killall pulseaudio
> > > aplay sound.wav
> > > (works as expected now going thru pulseaudio)
> > >
> > > Try #2
> > > Starting as root if I do:
> > > aplay sound.wav
> > > (works as expected using alsa alone)
> > > su - <id>
> > > aplay sound.wav
> > > <another lockdep traceback>
> > > aplay sound.wav
> > > (works as expected now going thru pulseaudio)
> > >
> > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
> > >
> > > Ideas?
> > > Ed Tomlinson
> > >
> > > aplay -l
> > > **** List of PLAYBACK Hardware Devices ****
> > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> > > Subdevices: 0/1
> > > Subdevice #0: subdevice #0
> > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> > > Subdevices: 1/1
> > > Subdevice #0: subdevice #0
> > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> > > Subdevices: 1/1
> > > Subdevice #0: subdevice #0
> > >
> > > "ALC1200 Analog" is what has speakers connected
> > >
> > > The em28xx in the traceback is an input source from a usb hdtv dongle.
> > >
> > > pavucontrol setup has been verified.
> > >
> > > [ 91.070620]
> > > [ 91.070621] =======================================================
> > > [ 91.071378] [ INFO: possible circular locking dependency detected ]
> > > [ 91.071378] 2.6.33-rc8-crc #106
> > > [ 91.071378] -------------------------------------------------------
> > > [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > [ 91.071378]
> > > [ 91.071378] but task is already holding lock:
> > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > [ 91.071378]
> > > [ 91.071378] which lock already depends on the new lock.
> > > [ 91.071378]
> > > [ 91.071378]
> > > [ 91.071378] the existing dependency chain (in reverse order) is:
> > > [ 91.071378]
> > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > [ 91.071378]
> > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > [ 91.071378]
> > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > [ 91.514885]
> > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > [ 91.514885]
> > > [ 91.514885] other info that might help us debug this:
> > > [ 91.514885]
> > > [ 91.514885] 1 lock held by pulseaudio/2717:
> > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > [ 91.514885]
> > > [ 91.514885] stack backtrace:
> > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> > > [ 91.514885] Call Trace:
> > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
> >
> > It looks rather a bug of em28xx driver. Changing dev->lock with an
> > individual one that is only for audio instance should fix the
> > problem.
>
> And, I believe this is no regression but a long-standing problem.
> It hits just occasionally by an app like pulseauiod which loves
> tight races.

I guess it depends on how you define a regression. From my POV it worked
in all three cases on .32, its failing in .33-rc and in one case is oppsing. In
my books thats a regression. There may have been races in .32 but they
did not trigger lockdep and never oppsed.

In any case, the real question is how do we fix the problem?

Ed

2010-02-15 22:35:29

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Mon, 15 Feb 2010 17:24:54 -0500,
Ed Tomlinson wrote:
>
> On Monday 15 February 2010 14:21:55 Takashi Iwai wrote:
> > At Mon, 15 Feb 2010 20:20:22 +0100,
> > I wrote:
> > >
> > > At Sat, 13 Feb 2010 12:17:10 -0500,
> > > Ed Tomlinson wrote:
> > > >
> > > > Hi,
> > > >
> > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
> > > >
> > > > ---
> > > > pcm.pulse {
> > > > type pulse
> > > > }
> > > >
> > > > ctl.pulse {
> > > > type pulse
> > > > }
> > > >
> > > > pcm.!default {
> > > > type pulse
> > > > }
> > > > ctl.!default {
> > > > type pulse
> > > > ---
> > > >
> > > > Try #1
> > > > Starting as root if I do:
> > > > su - <id>
> > > > aplay sound.wav
> > > > <traceback inlined below>
> > > > aplay sound.wav
> > > > (silence)
> > > > killall pulseaudio
> > > > aplay sound.wav
> > > > (works as expected now going thru pulseaudio)
> > > >
> > > > Try #2
> > > > Starting as root if I do:
> > > > aplay sound.wav
> > > > (works as expected using alsa alone)
> > > > su - <id>
> > > > aplay sound.wav
> > > > <another lockdep traceback>
> > > > aplay sound.wav
> > > > (works as expected now going thru pulseaudio)
> > > >
> > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
> > > >
> > > > Ideas?
> > > > Ed Tomlinson
> > > >
> > > > aplay -l
> > > > **** List of PLAYBACK Hardware Devices ****
> > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> > > > Subdevices: 0/1
> > > > Subdevice #0: subdevice #0
> > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> > > > Subdevices: 1/1
> > > > Subdevice #0: subdevice #0
> > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> > > > Subdevices: 1/1
> > > > Subdevice #0: subdevice #0
> > > >
> > > > "ALC1200 Analog" is what has speakers connected
> > > >
> > > > The em28xx in the traceback is an input source from a usb hdtv dongle.
> > > >
> > > > pavucontrol setup has been verified.
> > > >
> > > > [ 91.070620]
> > > > [ 91.070621] =======================================================
> > > > [ 91.071378] [ INFO: possible circular locking dependency detected ]
> > > > [ 91.071378] 2.6.33-rc8-crc #106
> > > > [ 91.071378] -------------------------------------------------------
> > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > [ 91.071378]
> > > > [ 91.071378] but task is already holding lock:
> > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > [ 91.071378]
> > > > [ 91.071378] which lock already depends on the new lock.
> > > > [ 91.071378]
> > > > [ 91.071378]
> > > > [ 91.071378] the existing dependency chain (in reverse order) is:
> > > > [ 91.071378]
> > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > [ 91.071378]
> > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > [ 91.071378]
> > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > [ 91.514885]
> > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > [ 91.514885]
> > > > [ 91.514885] other info that might help us debug this:
> > > > [ 91.514885]
> > > > [ 91.514885] 1 lock held by pulseaudio/2717:
> > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > [ 91.514885]
> > > > [ 91.514885] stack backtrace:
> > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> > > > [ 91.514885] Call Trace:
> > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
> > >
> > > It looks rather a bug of em28xx driver. Changing dev->lock with an
> > > individual one that is only for audio instance should fix the
> > > problem.
> >
> > And, I believe this is no regression but a long-standing problem.
> > It hits just occasionally by an app like pulseauiod which loves
> > tight races.
>
> I guess it depends on how you define a regression. From my POV it worked
> in all three cases on .32, its failing in .33-rc and in one case is oppsing. In
> my books thats a regression. There may have been races in .32 but they
> did not trigger lockdep and never oppsed.

Is the kernel config really identical? Is only the kernel replaced?

I haven't followed em28xx development, so it's possible that the bug
came from that side, though. But, in the PCM core, there is no
fundamental change that may trigger this bug during 2.6.33
development.

> In any case, the real question is how do we fix the problem?

As I mentioned, replace the mutex in em28xx code.


Takashi

2010-02-15 23:21:21

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Mon, 15 Feb 2010 23:35:26 +0100,
I wrote:
>
> At Mon, 15 Feb 2010 17:24:54 -0500,
> Ed Tomlinson wrote:
> >
> > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote:
> > > At Mon, 15 Feb 2010 20:20:22 +0100,
> > > I wrote:
> > > >
> > > > At Sat, 13 Feb 2010 12:17:10 -0500,
> > > > Ed Tomlinson wrote:
> > > > >
> > > > > Hi,
> > > > >
> > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
> > > > >
> > > > > ---
> > > > > pcm.pulse {
> > > > > type pulse
> > > > > }
> > > > >
> > > > > ctl.pulse {
> > > > > type pulse
> > > > > }
> > > > >
> > > > > pcm.!default {
> > > > > type pulse
> > > > > }
> > > > > ctl.!default {
> > > > > type pulse
> > > > > ---
> > > > >
> > > > > Try #1
> > > > > Starting as root if I do:
> > > > > su - <id>
> > > > > aplay sound.wav
> > > > > <traceback inlined below>
> > > > > aplay sound.wav
> > > > > (silence)
> > > > > killall pulseaudio
> > > > > aplay sound.wav
> > > > > (works as expected now going thru pulseaudio)
> > > > >
> > > > > Try #2
> > > > > Starting as root if I do:
> > > > > aplay sound.wav
> > > > > (works as expected using alsa alone)
> > > > > su - <id>
> > > > > aplay sound.wav
> > > > > <another lockdep traceback>
> > > > > aplay sound.wav
> > > > > (works as expected now going thru pulseaudio)
> > > > >
> > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
> > > > >
> > > > > Ideas?
> > > > > Ed Tomlinson
> > > > >
> > > > > aplay -l
> > > > > **** List of PLAYBACK Hardware Devices ****
> > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> > > > > Subdevices: 0/1
> > > > > Subdevice #0: subdevice #0
> > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> > > > > Subdevices: 1/1
> > > > > Subdevice #0: subdevice #0
> > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> > > > > Subdevices: 1/1
> > > > > Subdevice #0: subdevice #0
> > > > >
> > > > > "ALC1200 Analog" is what has speakers connected
> > > > >
> > > > > The em28xx in the traceback is an input source from a usb hdtv dongle.
> > > > >
> > > > > pavucontrol setup has been verified.
> > > > >
> > > > > [ 91.070620]
> > > > > [ 91.070621] =======================================================
> > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ]
> > > > > [ 91.071378] 2.6.33-rc8-crc #106
> > > > > [ 91.071378] -------------------------------------------------------
> > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > [ 91.071378]
> > > > > [ 91.071378] but task is already holding lock:
> > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > > [ 91.071378]
> > > > > [ 91.071378] which lock already depends on the new lock.
> > > > > [ 91.071378]
> > > > > [ 91.071378]
> > > > > [ 91.071378] the existing dependency chain (in reverse order) is:
> > > > > [ 91.071378]
> > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > [ 91.071378]
> > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > [ 91.071378]
> > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > [ 91.514885]
> > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > [ 91.514885]
> > > > > [ 91.514885] other info that might help us debug this:
> > > > > [ 91.514885]
> > > > > [ 91.514885] 1 lock held by pulseaudio/2717:
> > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > > [ 91.514885]
> > > > > [ 91.514885] stack backtrace:
> > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> > > > > [ 91.514885] Call Trace:
> > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
> > > >
> > > > It looks rather a bug of em28xx driver. Changing dev->lock with an
> > > > individual one that is only for audio instance should fix the
> > > > problem.
> > >
> > > And, I believe this is no regression but a long-standing problem.
> > > It hits just occasionally by an app like pulseauiod which loves
> > > tight races.
> >
> > I guess it depends on how you define a regression. From my POV it worked
> > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In
> > my books thats a regression. There may have been races in .32 but they
> > did not trigger lockdep and never oppsed.
>
> Is the kernel config really identical? Is only the kernel replaced?
>
> I haven't followed em28xx development, so it's possible that the bug
> came from that side, though. But, in the PCM core, there is no
> fundamental change that may trigger this bug during 2.6.33
> development.
>
> > In any case, the real question is how do we fix the problem?
>
> As I mentioned, replace the mutex in em28xx code.

I mean, something like below (totally untested).


Takashi

---
diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c
index bd78338..c2632c4 100644
--- a/drivers/media/video/em28xx/em28xx-audio.c
+++ b/drivers/media/video/em28xx/em28xx-audio.c
@@ -301,9 +301,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
/* Sets volume, mute, etc */

dev->mute = 0;
- mutex_lock(&dev->lock);
+ mutex_lock(&dev->adev.mutex);
ret = em28xx_audio_analog_set(dev);
- mutex_unlock(&dev->lock);
+ mutex_unlock(&dev->adev.mutex);
if (ret < 0)
goto err;

@@ -315,9 +315,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
dprintk("changing alternate number to 7\n");
}

- mutex_lock(&dev->lock);
+ mutex_lock(&dev->adev.mutex);
dev->adev.users++;
- mutex_unlock(&dev->lock);
+ mutex_unlock(&dev->adev.mutex);

snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
dev->adev.capture_pcm_substream = substream;
@@ -336,7 +336,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
dprintk("closing device\n");

dev->mute = 1;
- mutex_lock(&dev->lock);
+ mutex_lock(&dev->adev.mutex);
dev->adev.users--;
em28xx_audio_analog_set(dev);
if (substream->runtime->dma_area) {
@@ -344,7 +344,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
vfree(substream->runtime->dma_area);
substream->runtime->dma_area = NULL;
}
- mutex_unlock(&dev->lock);
+ mutex_unlock(&dev->adev.mutex);

return 0;
}
@@ -479,6 +479,7 @@ static int em28xx_audio_init(struct em28xx *dev)
return err;

spin_lock_init(&adev->slock);
+ mutex_init(&adev->mutex);
err = snd_pcm_new(card, "Em28xx Audio", 0, 0, 1, &pcm);
if (err < 0) {
snd_card_free(card);
diff --git a/drivers/media/video/em28xx/em28xx.h b/drivers/media/video/em28xx/em28xx.h
index 80d9b4f..bb1d754 100644
--- a/drivers/media/video/em28xx/em28xx.h
+++ b/drivers/media/video/em28xx/em28xx.h
@@ -461,6 +461,7 @@ struct em28xx_audio {
int users;
enum em28xx_stream_state capture_stream;
spinlock_t slock;
+ struct mutex mutex;
};

struct em28xx;

2010-02-16 13:19:36

by Ed Tomlinson

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

On Monday 15 February 2010 18:21:17 Takashi Iwai wrote:
> At Mon, 15 Feb 2010 23:35:26 +0100,
> I wrote:
> >
> > At Mon, 15 Feb 2010 17:24:54 -0500,
> > Ed Tomlinson wrote:
> > >
> > > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote:
> > > > At Mon, 15 Feb 2010 20:20:22 +0100,
> > > > I wrote:
> > > > >
> > > > > At Sat, 13 Feb 2010 12:17:10 -0500,
> > > > > Ed Tomlinson wrote:
> > > > > >
> > > > > > Hi,
> > > > > >
> > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
> > > > > >
> > > > > > ---
> > > > > > pcm.pulse {
> > > > > > type pulse
> > > > > > }
> > > > > >
> > > > > > ctl.pulse {
> > > > > > type pulse
> > > > > > }
> > > > > >
> > > > > > pcm.!default {
> > > > > > type pulse
> > > > > > }
> > > > > > ctl.!default {
> > > > > > type pulse
> > > > > > ---
> > > > > >
> > > > > > Try #1
> > > > > > Starting as root if I do:
> > > > > > su - <id>
> > > > > > aplay sound.wav
> > > > > > <traceback inlined below>
> > > > > > aplay sound.wav
> > > > > > (silence)
> > > > > > killall pulseaudio
> > > > > > aplay sound.wav
> > > > > > (works as expected now going thru pulseaudio)
> > > > > >
> > > > > > Try #2
> > > > > > Starting as root if I do:
> > > > > > aplay sound.wav
> > > > > > (works as expected using alsa alone)
> > > > > > su - <id>
> > > > > > aplay sound.wav
> > > > > > <another lockdep traceback>
> > > > > > aplay sound.wav
> > > > > > (works as expected now going thru pulseaudio)
> > > > > >
> > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
> > > > > >
> > > > > > Ideas?
> > > > > > Ed Tomlinson
> > > > > >
> > > > > > aplay -l
> > > > > > **** List of PLAYBACK Hardware Devices ****
> > > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> > > > > > Subdevices: 0/1
> > > > > > Subdevice #0: subdevice #0
> > > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> > > > > > Subdevices: 1/1
> > > > > > Subdevice #0: subdevice #0
> > > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> > > > > > Subdevices: 1/1
> > > > > > Subdevice #0: subdevice #0
> > > > > >
> > > > > > "ALC1200 Analog" is what has speakers connected
> > > > > >
> > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle.
> > > > > >
> > > > > > pavucontrol setup has been verified.
> > > > > >
> > > > > > [ 91.070620]
> > > > > > [ 91.070621] =======================================================
> > > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ]
> > > > > > [ 91.071378] 2.6.33-rc8-crc #106
> > > > > > [ 91.071378] -------------------------------------------------------
> > > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> > > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > [ 91.071378]
> > > > > > [ 91.071378] but task is already holding lock:
> > > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > > > [ 91.071378]
> > > > > > [ 91.071378] which lock already depends on the new lock.
> > > > > > [ 91.071378]
> > > > > > [ 91.071378]
> > > > > > [ 91.071378] the existing dependency chain (in reverse order) is:
> > > > > > [ 91.071378]
> > > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> > > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> > > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> > > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> > > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> > > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > [ 91.071378]
> > > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> > > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> > > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> > > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> > > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > [ 91.071378]
> > > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> > > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> > > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> > > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> > > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> > > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> > > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> > > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> > > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> > > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> > > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> > > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> > > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> > > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> > > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> > > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> > > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> > > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> > > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> > > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> > > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> > > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> > > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > [ 91.514885]
> > > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > [ 91.514885]
> > > > > > [ 91.514885] other info that might help us debug this:
> > > > > > [ 91.514885]
> > > > > > [ 91.514885] 1 lock held by pulseaudio/2717:
> > > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > > > [ 91.514885]
> > > > > > [ 91.514885] stack backtrace:
> > > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> > > > > > [ 91.514885] Call Trace:
> > > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> > > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> > > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> > > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
> > > > >
> > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an
> > > > > individual one that is only for audio instance should fix the
> > > > > problem.
> > > >
> > > > And, I believe this is no regression but a long-standing problem.
> > > > It hits just occasionally by an app like pulseauiod which loves
> > > > tight races.
> > >
> > > I guess it depends on how you define a regression. From my POV it worked
> > > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In
> > > my books thats a regression. There may have been races in .32 but they
> > > did not trigger lockdep and never oppsed.
> >
> > Is the kernel config really identical? Is only the kernel replaced?
> >
> > I haven't followed em28xx development, so it's possible that the bug
> > came from that side, though. But, in the PCM core, there is no
> > fundamental change that may trigger this bug during 2.6.33
> > development.
> >
> > > In any case, the real question is how do we fix the problem?
> >
> > As I mentioned, replace the mutex in em28xx code.
>
> I mean, something like below (totally untested).
>
>
> Takashi
>
> ---
> diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c
> index bd78338..c2632c4 100644
> --- a/drivers/media/video/em28xx/em28xx-audio.c
> +++ b/drivers/media/video/em28xx/em28xx-audio.c
> @@ -301,9 +301,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
> /* Sets volume, mute, etc */
>
> dev->mute = 0;
> - mutex_lock(&dev->lock);
> + mutex_lock(&dev->adev.mutex);
> ret = em28xx_audio_analog_set(dev);
> - mutex_unlock(&dev->lock);
> + mutex_unlock(&dev->adev.mutex);
> if (ret < 0)
> goto err;
>
> @@ -315,9 +315,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
> dprintk("changing alternate number to 7\n");
> }
>
> - mutex_lock(&dev->lock);
> + mutex_lock(&dev->adev.mutex);
> dev->adev.users++;
> - mutex_unlock(&dev->lock);
> + mutex_unlock(&dev->adev.mutex);
>
> snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
> dev->adev.capture_pcm_substream = substream;
> @@ -336,7 +336,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> dprintk("closing device\n");
>
> dev->mute = 1;
> - mutex_lock(&dev->lock);
> + mutex_lock(&dev->adev.mutex);
> dev->adev.users--;
> em28xx_audio_analog_set(dev);
> if (substream->runtime->dma_area) {
> @@ -344,7 +344,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> vfree(substream->runtime->dma_area);
> substream->runtime->dma_area = NULL;
> }
> - mutex_unlock(&dev->lock);
> + mutex_unlock(&dev->adev.mutex);
>
> return 0;
> }
> @@ -479,6 +479,7 @@ static int em28xx_audio_init(struct em28xx *dev)
> return err;
>
> spin_lock_init(&adev->slock);
> + mutex_init(&adev->mutex);
> err = snd_pcm_new(card, "Em28xx Audio", 0, 0, 1, &pcm);
> if (err < 0) {
> snd_card_free(card);
> diff --git a/drivers/media/video/em28xx/em28xx.h b/drivers/media/video/em28xx/em28xx.h
> index 80d9b4f..bb1d754 100644
> --- a/drivers/media/video/em28xx/em28xx.h
> +++ b/drivers/media/video/em28xx/em28xx.h
> @@ -461,6 +461,7 @@ struct em28xx_audio {
> int users;
> enum em28xx_stream_state capture_stream;
> spinlock_t slock;
> + struct mutex mutex;
> };
>
> struct em28xx;
> --

Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails.
Here is the new traceback.

Feb 16 07:55:23 grover kernel: [ 110.920632]
Feb 16 07:55:23 grover kernel: [ 110.920634] =======================================================
Feb 16 07:55:23 grover kernel: [ 110.921571] [ INFO: possible circular locking dependency detected ]
Feb 16 07:55:23 grover kernel: [ 110.921571] 2.6.33-rc8-crc #109
Feb 16 07:55:23 grover kernel: [ 110.921571] -------------------------------------------------------
Feb 16 07:55:23 grover kernel: [ 110.921571] pulseaudio/2713 is trying to acquire lock:
Feb 16 07:55:23 grover kernel: [ 110.921571] (sysfs_mutex){+.+.+.}, at: [<ffffffff8118b900>] sysfs_get_dirent+0x20/0xa0
Feb 16 07:55:23 grover kernel: [ 110.921571]
Feb 16 07:55:23 grover kernel: [ 110.921571] but task is already holding lock:
Feb 16 07:55:23 grover kernel: [ 110.921571] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa0103cd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 110.921571]
Feb 16 07:55:23 grover kernel: [ 110.921571] which lock already depends on the new lock.
Feb 16 07:55:23 grover kernel: [ 110.921571]
Feb 16 07:55:23 grover kernel: [ 110.921571]
Feb 16 07:55:23 grover kernel: [ 110.921571] the existing dependency chain (in reverse order) is:
Feb 16 07:55:23 grover kernel: [ 110.921571]
Feb 16 07:55:23 grover kernel: [ 110.921571] -> #2 (&pcm->open_mutex){+.+.+.}:
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffffa00ffd32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff8112115d>] __fput+0x15d/0x290
Feb 16 07:55:23 grover kernel: [ 110.921571] [<ffffffff811212ad>] fput+0x1d/0x30
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810fe001>] remove_vma+0x51/0x80
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
Feb 16 07:55:23 grover kernel: [ 111.114188]
Feb 16 07:55:23 grover kernel: [ 111.114188] -> #1 (&mm->mmap_sem){++++++}:
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8113102b>] filldir+0x7b/0xe0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8113144d>] sys_getdents+0xad/0x110
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
Feb 16 07:55:23 grover kernel: [ 111.114188]
Feb 16 07:55:23 grover kernel: [ 111.114188] -> #0 (sysfs_mutex){+.+.+.}:
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8118b900>] sysfs_get_dirent+0x20/0xa0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8118d280>] sysfs_remove_group+0x30/0x140
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff81399e09>] dpm_sysfs_remove+0x19/0x20
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff8139206c>] device_del+0x4c/0x1a0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813921d6>] device_unregister+0x16/0x30
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813ef533>] usb_remove_ep_devs+0x23/0x40
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813e6d4a>] remove_intf_ep_devs+0x4a/0x70
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffff813e84d7>] usb_set_interface+0x167/0x2a0
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffffa027c8cd>] snd_em28xx_capture_open+0x11d/0x190 [em28xx_alsa]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00ffdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.114188] [<ffffffffa027c8cd>] snd_em28xx_capture_open+0x11d/0x190 [em28xx_alsa]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00ffdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103ce9>] snd_pcm_open+0x199/0x450 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103fd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00a0778>] snd_open+0x198/0x4e0 [snd]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111ea70>] sys_open+0x20/0x30
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
Feb 16 07:55:23 grover kernel: [ 111.397291]
Feb 16 07:55:23 grover kernel: [ 111.397291] other info that might help us debug this:
Feb 16 07:55:23 grover kernel: [ 111.397291]
Feb 16 07:55:23 grover kernel: [ 111.397291] 1 lock held by pulseaudio/2713:
Feb 16 07:55:23 grover kernel: [ 111.397291] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa0103cd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291]
Feb 16 07:55:23 grover kernel: [ 111.397291] stack backtrace:
Feb 16 07:55:23 grover kernel: [ 111.397291] Pid: 2713, comm: pulseaudio Not tainted 2.6.33-rc8-crc #109
Feb 16 07:55:23 grover kernel: [ 111.397291] Call Trace:
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] ? sysfs_get_dirent+0x20/0xa0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] ? sysfs_get_dirent+0x20/0xa0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] ? sysfs_get_dirent+0x20/0xa0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff810819ce>] ? mark_held_locks+0x6e/0xa0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bbc50>] ? _raw_spin_unlock_irq+0x30/0x80
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118b900>] sysfs_get_dirent+0x20/0xa0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8118d280>] sysfs_remove_group+0x30/0x140
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81399e09>] dpm_sysfs_remove+0x19/0x20
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8139206c>] device_del+0x4c/0x1a0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813921d6>] device_unregister+0x16/0x30
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813ef533>] usb_remove_ep_devs+0x23/0x40
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813e6d4a>] remove_intf_ep_devs+0x4a/0x70
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff813e84d7>] usb_set_interface+0x167/0x2a0
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa027c8cd>] snd_em28xx_capture_open+0x11d/0x190 [em28xx_alsa]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00ffdee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103ce9>] snd_pcm_open+0x199/0x450 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa0103fd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffffa00a0778>] snd_open+0x198/0x4e0 [snd]
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff8111ea70>] sys_open+0x20/0x30
Feb 16 07:55:23 grover kernel: [ 111.397291] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b

Hope this helps,
Ed

2010-02-16 13:37:49

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Tue, 16 Feb 2010 08:19:21 -0500,
Ed Tomlinson wrote:
>
> On Monday 15 February 2010 18:21:17 Takashi Iwai wrote:
> > At Mon, 15 Feb 2010 23:35:26 +0100,
> > I wrote:
> > >
> > > At Mon, 15 Feb 2010 17:24:54 -0500,
> > > Ed Tomlinson wrote:
> > > >
> > > > On Monday 15 February 2010 14:21:55 Takashi Iwai wrote:
> > > > > At Mon, 15 Feb 2010 20:20:22 +0100,
> > > > > I wrote:
> > > > > >
> > > > > > At Sat, 13 Feb 2010 12:17:10 -0500,
> > > > > > Ed Tomlinson wrote:
> > > > > > >
> > > > > > > Hi,
> > > > > > >
> > > > > > > Inorder to get skype working with linux I have the following in .asoundrc for my normal userid.
> > > > > > >
> > > > > > > ---
> > > > > > > pcm.pulse {
> > > > > > > type pulse
> > > > > > > }
> > > > > > >
> > > > > > > ctl.pulse {
> > > > > > > type pulse
> > > > > > > }
> > > > > > >
> > > > > > > pcm.!default {
> > > > > > > type pulse
> > > > > > > }
> > > > > > > ctl.!default {
> > > > > > > type pulse
> > > > > > > ---
> > > > > > >
> > > > > > > Try #1
> > > > > > > Starting as root if I do:
> > > > > > > su - <id>
> > > > > > > aplay sound.wav
> > > > > > > <traceback inlined below>
> > > > > > > aplay sound.wav
> > > > > > > (silence)
> > > > > > > killall pulseaudio
> > > > > > > aplay sound.wav
> > > > > > > (works as expected now going thru pulseaudio)
> > > > > > >
> > > > > > > Try #2
> > > > > > > Starting as root if I do:
> > > > > > > aplay sound.wav
> > > > > > > (works as expected using alsa alone)
> > > > > > > su - <id>
> > > > > > > aplay sound.wav
> > > > > > > <another lockdep traceback>
> > > > > > > aplay sound.wav
> > > > > > > (works as expected now going thru pulseaudio)
> > > > > > >
> > > > > > > With .32 there were no tracebacks (lockdep was enabled) and try #1 would work where I now get silence.
> > > > > > >
> > > > > > > Ideas?
> > > > > > > Ed Tomlinson
> > > > > > >
> > > > > > > aplay -l
> > > > > > > **** List of PLAYBACK Hardware Devices ****
> > > > > > > card 0: SB [HDA ATI SB], device 0: ALC1200 Analog [ALC1200 Analog]
> > > > > > > Subdevices: 0/1
> > > > > > > Subdevice #0: subdevice #0
> > > > > > > card 0: SB [HDA ATI SB], device 1: ALC1200 Digital [ALC1200 Digital]
> > > > > > > Subdevices: 1/1
> > > > > > > Subdevice #0: subdevice #0
> > > > > > > card 1: HDMI [HDA ATI HDMI], device 3: ATI HDMI [ATI HDMI]
> > > > > > > Subdevices: 1/1
> > > > > > > Subdevice #0: subdevice #0
> > > > > > >
> > > > > > > "ALC1200 Analog" is what has speakers connected
> > > > > > >
> > > > > > > The em28xx in the traceback is an input source from a usb hdtv dongle.
> > > > > > >
> > > > > > > pavucontrol setup has been verified.
> > > > > > >
> > > > > > > [ 91.070620]
> > > > > > > [ 91.070621] =======================================================
> > > > > > > [ 91.071378] [ INFO: possible circular locking dependency detected ]
> > > > > > > [ 91.071378] 2.6.33-rc8-crc #106
> > > > > > > [ 91.071378] -------------------------------------------------------
> > > > > > > [ 91.071378] pulseaudio/2717 is trying to acquire lock:
> > > > > > > [ 91.071378] (&dev->lock){+.+.+.}, at: [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378] but task is already holding lock:
> > > > > > > [ 91.071378] (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378] which lock already depends on the new lock.
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378] the existing dependency chain (in reverse order) is:
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378] -> #3 (&pcm->open_mutex){+.+.+.}:
> > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > > [ 91.071378] [<ffffffffa010ad32>] snd_pcm_release+0x42/0xb0 [snd_pcm]
> > > > > > > [ 91.071378] [<ffffffff8112115d>] __fput+0x15d/0x290
> > > > > > > [ 91.071378] [<ffffffff811212ad>] fput+0x1d/0x30
> > > > > > > [ 91.071378] [<ffffffff810fe001>] remove_vma+0x51/0x80
> > > > > > > [ 91.071378] [<ffffffff810ffa1d>] do_munmap+0x2fd/0x390
> > > > > > > [ 91.071378] [<ffffffff810ffb06>] sys_munmap+0x56/0x80
> > > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378] -> #2 (&mm->mmap_sem){++++++}:
> > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > > [ 91.071378] [<ffffffff810f62c7>] might_fault+0xa7/0xd0
> > > > > > > [ 91.071378] [<ffffffff8113102b>] filldir+0x7b/0xe0
> > > > > > > [ 91.071378] [<ffffffff8118aa21>] sysfs_readdir+0xf1/0x1b0
> > > > > > > [ 91.071378] [<ffffffff81131268>] vfs_readdir+0xb8/0xe0
> > > > > > > [ 91.071378] [<ffffffff8113144d>] sys_getdents+0xad/0x110
> > > > > > > [ 91.071378] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > > [ 91.071378]
> > > > > > > [ 91.071378] -> #1 (sysfs_mutex){+.+.+.}:
> > > > > > > [ 91.071378] [<ffffffff81083215>] __lock_acquire+0xfc5/0x1550
> > > > > > > [ 91.071378] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > > [ 91.071378] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > > [ 91.071378] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > > [ 91.071378] [<ffffffff8118b082>] sysfs_addrm_start+0x22/0x30
> > > > > > > [ 91.071378] [<ffffffff8118bc58>] create_dir+0x58/0xb0
> > > > > > > [ 91.514885] [<ffffffff8118bd0a>] sysfs_create_dir+0x5a/0x70
> > > > > > > [ 91.514885] [<ffffffff8123ebbd>] kobject_add_internal+0xbd/0x1f0
> > > > > > > [ 91.514885] [<ffffffff8123ee08>] kobject_add_varg+0x38/0x60
> > > > > > > [ 91.514885] [<ffffffff8123eee4>] kobject_add+0x44/0x70
> > > > > > > [ 91.514885] [<ffffffff81392510>] device_add+0xb0/0x5e0
> > > > > > > [ 91.514885] [<ffffffff81392a5e>] device_register+0x1e/0x30
> > > > > > > [ 91.514885] [<ffffffff8140a50d>] i2c_register_adapter+0x12d/0x250
> > > > > > > [ 91.514885] [<ffffffff8140a7f1>] i2c_add_adapter+0xb1/0xd0
> > > > > > > [ 91.514885] [<ffffffffa0231ba4>] em28xx_i2c_register+0x104/0x520 [em28xx]
> > > > > > > [ 91.514885] [<ffffffffa0233daa>] em28xx_usb_probe+0x68a/0xb90 [em28xx]
> > > > > > > [ 91.514885] [<ffffffff813eb4ab>] usb_probe_interface+0xeb/0x1b0
> > > > > > > [ 91.514885] [<ffffffff81395546>] driver_probe_device+0xc6/0x1d0
> > > > > > > [ 91.514885] [<ffffffff813956eb>] __driver_attach+0x9b/0xa0
> > > > > > > [ 91.514885] [<ffffffff8139492c>] bus_for_each_dev+0x6c/0xa0
> > > > > > > [ 91.514885] [<ffffffff8139535e>] driver_attach+0x1e/0x20
> > > > > > > [ 91.514885] [<ffffffff81394c11>] bus_add_driver+0xe1/0x280
> > > > > > > [ 91.514885] [<ffffffff81395a58>] driver_register+0x98/0x140
> > > > > > > [ 91.514885] [<ffffffff813ea06c>] usb_register_driver+0xdc/0x1a0
> > > > > > > [ 91.514885] [<ffffffffa0248023>] 0xffffffffa0248023
> > > > > > > [ 91.514885] [<ffffffff810001dc>] do_one_initcall+0x3c/0x1d0
> > > > > > > [ 91.514885] [<ffffffff81092d75>] sys_init_module+0xe5/0x250
> > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > > [ 91.514885]
> > > > > > > [ 91.514885] -> #0 (&dev->lock){+.+.+.}:
> > > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > > [ 91.514885]
> > > > > > > [ 91.514885] other info that might help us debug this:
> > > > > > > [ 91.514885]
> > > > > > > [ 91.514885] 1 lock held by pulseaudio/2717:
> > > > > > > [ 91.514885] #0: (&pcm->open_mutex){+.+.+.}, at: [<ffffffffa010ecd2>] snd_pcm_open+0x182/0x450 [snd_pcm]
> > > > > > > [ 91.514885]
> > > > > > > [ 91.514885] stack backtrace:
> > > > > > > [ 91.514885] Pid: 2717, comm: pulseaudio Not tainted 2.6.33-rc8-crc #106
> > > > > > > [ 91.514885] Call Trace:
> > > > > > > [ 91.514885] [<ffffffff81080fd9>] print_circular_bug+0xe9/0xf0
> > > > > > > [ 91.514885] [<ffffffff81083668>] __lock_acquire+0x1418/0x1550
> > > > > > > [ 91.514885] [<ffffffff81081dc8>] ? debug_check_no_locks_freed+0xc8/0x150
> > > > > > > [ 91.514885] [<ffffffff8108383c>] lock_acquire+0x9c/0x140
> > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > > [ 91.514885] [<ffffffff814b96c1>] __mutex_lock_common+0x61/0x610
> > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > > [ 91.514885] [<ffffffffa02797f1>] ? snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > > [ 91.514885] [<ffffffffa0109c70>] ? snd_pcm_hw_rule_muldivk+0x0/0xa0 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffff8107fd54>] ? lockdep_init_map+0x44/0x130
> > > > > > > [ 91.514885] [<ffffffff814b9d53>] mutex_lock_nested+0x43/0x50
> > > > > > > [ 91.514885] [<ffffffffa02797f1>] snd_em28xx_capture_open+0x61/0x190 [em28xx_alsa]
> > > > > > > [ 91.514885] [<ffffffffa010adee>] snd_pcm_open_substream+0x4e/0x90 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffffa010ece9>] snd_pcm_open+0x199/0x450 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffff81081cfd>] ? trace_hardirqs_on+0xd/0x10
> > > > > > > [ 91.514885] [<ffffffff810434f0>] ? default_wake_function+0x0/0x20
> > > > > > > [ 91.514885] [<ffffffff814b965e>] ? mutex_unlock+0xe/0x10
> > > > > > > [ 91.514885] [<ffffffffa010efd4>] snd_pcm_capture_open+0x34/0x40 [snd_pcm]
> > > > > > > [ 91.514885] [<ffffffffa00c5778>] snd_open+0x198/0x4e0 [snd]
> > > > > > > [ 91.514885] [<ffffffff8112384d>] chrdev_open+0x17d/0x320
> > > > > > > [ 91.514885] [<ffffffff8111d358>] __dentry_open+0x1a8/0x400
> > > > > > > [ 91.514885] [<ffffffff811236d0>] ? chrdev_open+0x0/0x320
> > > > > > > [ 91.514885] [<ffffffff8111d6b4>] nameidata_to_filp+0x54/0x70
> > > > > > > [ 91.514885] [<ffffffff8112e7f1>] do_filp_open+0x841/0xc00
> > > > > > > [ 91.514885] [<ffffffff814bf981>] ? sub_preempt_count+0x51/0x60
> > > > > > > [ 91.514885] [<ffffffff814bbb7c>] ? _raw_spin_unlock+0x5c/0x70
> > > > > > > [ 91.514885] [<ffffffff8111e954>] do_sys_open+0xa4/0x180
> > > > > > > [ 91.514885] [<ffffffff8111ea70>] sys_open+0x20/0x30
> > > > > > > [ 91.514885] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
> > > > > > > [ 92.643423] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
> > > > > >
> > > > > > It looks rather a bug of em28xx driver. Changing dev->lock with an
> > > > > > individual one that is only for audio instance should fix the
> > > > > > problem.
> > > > >
> > > > > And, I believe this is no regression but a long-standing problem.
> > > > > It hits just occasionally by an app like pulseauiod which loves
> > > > > tight races.
> > > >
> > > > I guess it depends on how you define a regression. From my POV it worked
> > > > in all three cases on .32, its failing in .33-rc and in one case is oppsing. In
> > > > my books thats a regression. There may have been races in .32 but they
> > > > did not trigger lockdep and never oppsed.
> > >
> > > Is the kernel config really identical? Is only the kernel replaced?
> > >
> > > I haven't followed em28xx development, so it's possible that the bug
> > > came from that side, though. But, in the PCM core, there is no
> > > fundamental change that may trigger this bug during 2.6.33
> > > development.
> > >
> > > > In any case, the real question is how do we fix the problem?
> > >
> > > As I mentioned, replace the mutex in em28xx code.
> >
> > I mean, something like below (totally untested).
> >
> >
> > Takashi
> >
> > ---
> > diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c
> > index bd78338..c2632c4 100644
> > --- a/drivers/media/video/em28xx/em28xx-audio.c
> > +++ b/drivers/media/video/em28xx/em28xx-audio.c
> > @@ -301,9 +301,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
> > /* Sets volume, mute, etc */
> >
> > dev->mute = 0;
> > - mutex_lock(&dev->lock);
> > + mutex_lock(&dev->adev.mutex);
> > ret = em28xx_audio_analog_set(dev);
> > - mutex_unlock(&dev->lock);
> > + mutex_unlock(&dev->adev.mutex);
> > if (ret < 0)
> > goto err;
> >
> > @@ -315,9 +315,9 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
> > dprintk("changing alternate number to 7\n");
> > }
> >
> > - mutex_lock(&dev->lock);
> > + mutex_lock(&dev->adev.mutex);
> > dev->adev.users++;
> > - mutex_unlock(&dev->lock);
> > + mutex_unlock(&dev->adev.mutex);
> >
> > snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
> > dev->adev.capture_pcm_substream = substream;
> > @@ -336,7 +336,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> > dprintk("closing device\n");
> >
> > dev->mute = 1;
> > - mutex_lock(&dev->lock);
> > + mutex_lock(&dev->adev.mutex);
> > dev->adev.users--;
> > em28xx_audio_analog_set(dev);
> > if (substream->runtime->dma_area) {
> > @@ -344,7 +344,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> > vfree(substream->runtime->dma_area);
> > substream->runtime->dma_area = NULL;
> > }
> > - mutex_unlock(&dev->lock);
> > + mutex_unlock(&dev->adev.mutex);
> >
> > return 0;
> > }
> > @@ -479,6 +479,7 @@ static int em28xx_audio_init(struct em28xx *dev)
> > return err;
> >
> > spin_lock_init(&adev->slock);
> > + mutex_init(&adev->mutex);
> > err = snd_pcm_new(card, "Em28xx Audio", 0, 0, 1, &pcm);
> > if (err < 0) {
> > snd_card_free(card);
> > diff --git a/drivers/media/video/em28xx/em28xx.h b/drivers/media/video/em28xx/em28xx.h
> > index 80d9b4f..bb1d754 100644
> > --- a/drivers/media/video/em28xx/em28xx.h
> > +++ b/drivers/media/video/em28xx/em28xx.h
> > @@ -461,6 +461,7 @@ struct em28xx_audio {
> > int users;
> > enum em28xx_stream_state capture_stream;
> > spinlock_t slock;
> > + struct mutex mutex;
> > };
> >
> > struct em28xx;
> > --
>
> Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails.
> Here is the new traceback.

Hmm, fixing this isn't so trivial. The same problem occurs on other
subsystems like NFS over years. And it's still there, AFAIK.
The mmap mutex appears suddenly in the strange code path at close.

The patch below might fix, but I'm not 100% sure whether this has no
side effect.

Anyway, I doubt very much it being a regression. There is no change
in ALSA core side, and also in V4L em28xx code. Maybe the lockdep
wasn't triggered by some reason. And, this lockdep warning is almost
harmless...


thanks,

Takashi

---
diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c
index bd78338..1759e1f 100644
--- a/drivers/media/video/em28xx/em28xx-audio.c
+++ b/drivers/media/video/em28xx/em28xx-audio.c
@@ -301,23 +301,12 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
/* Sets volume, mute, etc */

dev->mute = 0;
- mutex_lock(&dev->lock);
ret = em28xx_audio_analog_set(dev);
- mutex_unlock(&dev->lock);
if (ret < 0)
goto err;

runtime->hw = snd_em28xx_hw_capture;
- if (dev->alt == 0 && dev->adev.users == 0) {
- int errCode;
- dev->alt = 7;
- errCode = usb_set_interface(dev->udev, 0, 7);
- dprintk("changing alternate number to 7\n");
- }
-
- mutex_lock(&dev->lock);
dev->adev.users++;
- mutex_unlock(&dev->lock);

snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
dev->adev.capture_pcm_substream = substream;
@@ -336,7 +325,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
dprintk("closing device\n");

dev->mute = 1;
- mutex_lock(&dev->lock);
dev->adev.users--;
em28xx_audio_analog_set(dev);
if (substream->runtime->dma_area) {
@@ -344,7 +332,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
vfree(substream->runtime->dma_area);
substream->runtime->dma_area = NULL;
}
- mutex_unlock(&dev->lock);

return 0;
}
@@ -366,6 +353,14 @@ static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream,
/* TODO: set up em28xx audio chip to deliver the correct audio format,
current default is 48000hz multiplexed => 96000hz mono
which shouldn't matter since analogue TV only supports mono */
+
+ if (dev->alt == 0 && dev->adev.users == 1) {
+ int errCode;
+ dev->alt = 7;
+ errCode = usb_set_interface(dev->udev, 0, 7);
+ dprintk("changing alternate number to 7\n");
+ }
+
return 0;
}

2010-02-17 13:16:39

by Ed Tomlinson

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote:
> > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails.
> > Here is the new traceback.
>
> Hmm, fixing this isn't so trivial. The same problem occurs on other
> subsystems like NFS over years. And it's still there, AFAIK.
> The mmap mutex appears suddenly in the strange code path at close.
>
> The patch below might fix, but I'm not 100% sure whether this has no
> side effect.
>
> Anyway, I doubt very much it being a regression. There is no change
> in ALSA core side, and also in V4L em28xx code. Maybe the lockdep
> wasn't triggered by some reason. And, this lockdep warning is almost
> harmless...

Takashi,

The second patch eliminating the lock causes oppes every time (one follows just in case
its helpful). Suggest that the first patch might suffice to get rid of the opps. The only worry I
have is _once_ after getting the lockdep traceback starting X stalled the box (no opps, no
sysRQ, no log on the serial console).

Ideas?

---
[ 66.200497] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 66.201377] IP: [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0
[ 66.201377] PGD 16d25a067 PUD 16d25b067 PMD 0
[ 66.201377] Oops: 0000 [#1] PREEMPT SMP
[ 66.201377] last sysfs file: /sys/devices/pci0000:00/0000:00:14.2/sound/card0/uevent
[ 66.252431] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
[ 66.201377] CPU 3
[ 66.201377] Pid: 2816, comm: console-kit-dae Not tainted 2.6.33-rc8-crc #110 M3A78-T/System Product Name
[ 66.201377] RIP: 0010:[<ffffffff8104dfe6>] [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0
[ 66.201377] RSP: 0018:ffff88016d149e88 EFLAGS: 00010293
[ 66.201377] RAX: ffff88016b644318 RBX: fffffffffffffcf8 RCX: ffff88016d133e00
[ 66.201377] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff81a7fa88
[ 66.201377] RBP: ffff88016d149ee8 R08: ffffffff821478d0 R09: 0000000000000000
[ 66.201377] R10: 0000000000000052 R11: 0000000000000246 R12: ffff88016d149f08
[ 66.365887] R13: ffff88016b644020 R14: ffff88016c108000 R15: ffff88016c108000
[ 66.365887] FS: 00007fc780a0f700(0000) GS:ffff880028380000(0000) knlGS:0000000000000000
[ 66.365887] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 66.365887] CR2: 0000000000000000 CR3: 000000016a044000 CR4: 00000000000006e0
[ 66.365887] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 66.365887] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 66.365887] Process console-kit-dae (pid: 2816, threadinfo ffff88016d148000, task ffff88016c108000)
[ 66.365887] Stack:
[ 66.365887] ffff88016c108000 ffff88016c108000 ffff88016d149f30 ffff88016b644318
[ 66.365887] <0> ffff88016d149ee8 0000000000000000 ffffffff81069880 00007fff01e7223c
[ 66.365887] <0> ffff88016d133e80 0000000000000000 000000000061ea60 00007fff01e7228c
[ 66.365887] Call Trace:
[ 66.365887] [<ffffffff81069880>] ? find_get_pid+0x0/0x80
[ 66.365887] [<ffffffff8104e169>] sys_wait4+0x89/0xf0
[ 66.365887] [<ffffffff8104b650>] ? child_wait_callback+0x0/0x80
[ 66.365887] [<ffffffff81002adb>] system_call_fastpath+0x16/0x1b
[ 66.365887] Code: eb 29 0f 1f 00 48 89 da be 01 00 00 00 4c 89 e7 e8 f0 f1 ff ff 85 c0 0f 85 d0 00 00 00 48 8b 9b 08 03 00 00 48 81 eb 08 03 00 00 <48> 8b 83 08 03 00 00 0f 18 08 48 8d 83 08 03 00 00 48 39 45 b8
[ 66.365887] RIP [<ffffffff8104dfe6>] do_wait+0x1e6/0x2e0
[ 66.365887] RSP <ffff88016d149e88>
[ 66.365887] CR2: 0000000000000000
[ 66.610733] ---[ end trace 7b7cfa53172184c4 ]---
[ 66.620906] note: console-kit-dae[2816] exited with preempt_count 1

2010-02-17 14:29:41

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Wed, 17 Feb 2010 08:16:32 -0500,
Ed Tomlinson wrote:
>
> On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote:
> > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails.
> > > Here is the new traceback.
> >
> > Hmm, fixing this isn't so trivial. The same problem occurs on other
> > subsystems like NFS over years. And it's still there, AFAIK.
> > The mmap mutex appears suddenly in the strange code path at close.
> >
> > The patch below might fix, but I'm not 100% sure whether this has no
> > side effect.
> >
> > Anyway, I doubt very much it being a regression. There is no change
> > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep
> > wasn't triggered by some reason. And, this lockdep warning is almost
> > harmless...
>
> Takashi,
>
> The second patch eliminating the lock causes oppes every time (one follows just in case
> its helpful).

Are you sure? The patch should causes a compile error, so you must have
patched manually in a wrong place ;)

Try the patch below (again untested, though).


thanks,

Takashi

---
diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c
index bd78338..c51e623 100644
--- a/drivers/media/video/em28xx/em28xx-audio.c
+++ b/drivers/media/video/em28xx/em28xx-audio.c
@@ -301,23 +301,12 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
/* Sets volume, mute, etc */

dev->mute = 0;
- mutex_lock(&dev->lock);
ret = em28xx_audio_analog_set(dev);
- mutex_unlock(&dev->lock);
if (ret < 0)
goto err;

runtime->hw = snd_em28xx_hw_capture;
- if (dev->alt == 0 && dev->adev.users == 0) {
- int errCode;
- dev->alt = 7;
- errCode = usb_set_interface(dev->udev, 0, 7);
- dprintk("changing alternate number to 7\n");
- }
-
- mutex_lock(&dev->lock);
dev->adev.users++;
- mutex_unlock(&dev->lock);

snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
dev->adev.capture_pcm_substream = substream;
@@ -336,7 +325,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
dprintk("closing device\n");

dev->mute = 1;
- mutex_lock(&dev->lock);
dev->adev.users--;
em28xx_audio_analog_set(dev);
if (substream->runtime->dma_area) {
@@ -344,7 +332,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
vfree(substream->runtime->dma_area);
substream->runtime->dma_area = NULL;
}
- mutex_unlock(&dev->lock);

return 0;
}
@@ -352,6 +339,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream,
struct snd_pcm_hw_params *hw_params)
{
+ struct em28xx *dev = snd_pcm_substream_chip(substream);
unsigned int channels, rate, format;
int ret;

@@ -366,6 +354,14 @@ static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream,
/* TODO: set up em28xx audio chip to deliver the correct audio format,
current default is 48000hz multiplexed => 96000hz mono
which shouldn't matter since analogue TV only supports mono */
+
+ if (dev->alt == 0 && dev->adev.users == 1) {
+ int errCode;
+ dev->alt = 7;
+ errCode = usb_set_interface(dev->udev, 0, 7);
+ dprintk("changing alternate number to 7\n");
+ }
+
return 0;
}

2010-02-18 12:25:47

by Ed Tomlinson

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

On Wednesday 17 February 2010 09:29:37 Takashi Iwai wrote:
> At Wed, 17 Feb 2010 08:16:32 -0500,
> Ed Tomlinson wrote:
> >
> > On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote:
> > > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails.
> > > > Here is the new traceback.
> > >
> > > Hmm, fixing this isn't so trivial. The same problem occurs on other
> > > subsystems like NFS over years. And it's still there, AFAIK.
> > > The mmap mutex appears suddenly in the strange code path at close.
> > >
> > > The patch below might fix, but I'm not 100% sure whether this has no
> > > side effect.
> > >
> > > Anyway, I doubt very much it being a regression. There is no change
> > > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep
> > > wasn't triggered by some reason. And, this lockdep warning is almost
> > > harmless...
> >
> > Takashi,
> >
> > The second patch eliminating the lock causes oppes every time (one follows just in case
> > its helpful).
>
> Are you sure? The patch should causes a compile error, so you must have
> patched manually in a wrong place ;)

Yes I am sure. I fixed the compile error the same way it is fixed below.

Ed

> Try the patch below (again untested, though).
>
>
> thanks,
>
> Takashi
>
> ---
> diff --git a/drivers/media/video/em28xx/em28xx-audio.c b/drivers/media/video/em28xx/em28xx-audio.c
> index bd78338..c51e623 100644
> --- a/drivers/media/video/em28xx/em28xx-audio.c
> +++ b/drivers/media/video/em28xx/em28xx-audio.c
> @@ -301,23 +301,12 @@ static int snd_em28xx_capture_open(struct snd_pcm_substream *substream)
> /* Sets volume, mute, etc */
>
> dev->mute = 0;
> - mutex_lock(&dev->lock);
> ret = em28xx_audio_analog_set(dev);
> - mutex_unlock(&dev->lock);
> if (ret < 0)
> goto err;
>
> runtime->hw = snd_em28xx_hw_capture;
> - if (dev->alt == 0 && dev->adev.users == 0) {
> - int errCode;
> - dev->alt = 7;
> - errCode = usb_set_interface(dev->udev, 0, 7);
> - dprintk("changing alternate number to 7\n");
> - }
> -
> - mutex_lock(&dev->lock);
> dev->adev.users++;
> - mutex_unlock(&dev->lock);
>
> snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS);
> dev->adev.capture_pcm_substream = substream;
> @@ -336,7 +325,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> dprintk("closing device\n");
>
> dev->mute = 1;
> - mutex_lock(&dev->lock);
> dev->adev.users--;
> em28xx_audio_analog_set(dev);
> if (substream->runtime->dma_area) {
> @@ -344,7 +332,6 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> vfree(substream->runtime->dma_area);
> substream->runtime->dma_area = NULL;
> }
> - mutex_unlock(&dev->lock);
>
> return 0;
> }
> @@ -352,6 +339,7 @@ static int snd_em28xx_pcm_close(struct snd_pcm_substream *substream)
> static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream,
> struct snd_pcm_hw_params *hw_params)
> {
> + struct em28xx *dev = snd_pcm_substream_chip(substream);
> unsigned int channels, rate, format;
> int ret;
>
> @@ -366,6 +354,14 @@ static int snd_em28xx_hw_capture_params(struct snd_pcm_substream *substream,
> /* TODO: set up em28xx audio chip to deliver the correct audio format,
> current default is 48000hz multiplexed => 96000hz mono
> which shouldn't matter since analogue TV only supports mono */
> +
> + if (dev->alt == 0 && dev->adev.users == 1) {
> + int errCode;
> + dev->alt = 7;
> + errCode = usb_set_interface(dev->udev, 0, 7);
> + dprintk("changing alternate number to 7\n");
> + }
> +
> return 0;
> }
>
>
>

2010-02-18 13:21:15

by Takashi Iwai

[permalink] [raw]
Subject: Re: [LOCKDEP] 33-rc8 Running aplay with pulse as the default

At Thu, 18 Feb 2010 07:25:38 -0500,
Ed Tomlinson wrote:
>
> On Wednesday 17 February 2010 09:29:37 Takashi Iwai wrote:
> > At Wed, 17 Feb 2010 08:16:32 -0500,
> > Ed Tomlinson wrote:
> > >
> > > On Tuesday 16 February 2010 08:37:46 Takashi Iwai wrote:
> > > > > Thanks for the patch. It helps in that it eliminates the opps but lockdep still triggers and aplay still fails.
> > > > > Here is the new traceback.
> > > >
> > > > Hmm, fixing this isn't so trivial. The same problem occurs on other
> > > > subsystems like NFS over years. And it's still there, AFAIK.
> > > > The mmap mutex appears suddenly in the strange code path at close.
> > > >
> > > > The patch below might fix, but I'm not 100% sure whether this has no
> > > > side effect.
> > > >
> > > > Anyway, I doubt very much it being a regression. There is no change
> > > > in ALSA core side, and also in V4L em28xx code. Maybe the lockdep
> > > > wasn't triggered by some reason. And, this lockdep warning is almost
> > > > harmless...
> > >
> > > Takashi,
> > >
> > > The second patch eliminating the lock causes oppes every time (one follows just in case
> > > its helpful).
> >
> > Are you sure? The patch should causes a compile error, so you must have
> > patched manually in a wrong place ;)
>
> Yes I am sure. I fixed the compile error the same way it is fixed below.

But the Oops looks pretty irrelevant from the code path.


Takashi