Re: panic: sound mutex assertion failure

On  1 Mar, John Baldwin wrote:
> panic: _mtx_lock_sleep: recursed on non-recursive mutex pcm0 
> _at_ ../../../dev/sound/pcm/sound.c:395
> 
> at line 436 in file ../../../kern/kern_mutex.c
> 
> syncing disks, buffers remaining... 2169 panic: bremfree: removing a buffer 
> not on a queue
> at line 647 in file ../../../kern/vfs_bio.cUptime: 3m31s
> Dumping 1023 MB
>  16 32 48 64 80 96 112 128 144 160 176 192 208 224 240 256 272 288 304 320 336 
> 352 368 384 400 416 432 448 464 480 496 512 528 544 560 576 592 608 624 640 
> 656 672 688 704 720 736 752 768 784 800 816 832 848 864 880 896 912 928 944 
> 960 976 992 1008
> ---
> (kgdb) where
> #0  doadump () at ../../../kern/kern_shutdown.c:240
> #1  0xc0581e1c in boot (howto=260) at ../../../kern/kern_shutdown.c:374
> #2  0xc0582186 in poweroff_wait (junk=0xc074a317, howto=647)
>     at ../../../kern/kern_shutdown.c:552
> #3  0xc05c450c in bremfreel (bp=0xe7a83748) at ../../../kern/vfs_bio.c:647
> #4  0xc05c43cc in bremfree (bp=0x0) at ../../../kern/vfs_bio.c:629
> #5  0xc05c7f45 in getblk (vp=0x0, blkno=12000, size=4096, slpflag=0,
>     slptimeo=0, flags=0) at ../../../kern/vfs_bio.c:2466
> #6  0xc0687ff4 in ffs_sbupdate (mp=0xc6541500, waitfor=2)
>     at ../../../ufs/ffs/ffs_vfsops.c:1499
> #7  0xc0687990 in ffs_sync (mp=0xc654dc00, waitfor=2, cred=0xc2272e80,
>     td=0xc07c0800) at ../../../ufs/ffs/ffs_vfsops.c:1224
> #8  0xc05d9a09 in sync (td=0xc07c0800, uap=0x0)
>     at ../../../kern/vfs_syscalls.c:141
> #9  0xc0581a4b in boot (howto=256) at ../../../kern/kern_shutdown.c:306
> #10 0xc0582186 in poweroff_wait (junk=0xc0744aa9, howto=436)
>     at ../../../kern/kern_shutdown.c:552
> #11 0xc0578a3e in _mtx_lock_sleep (m=0xe7a83904, opts=0, file=0x0, line=0)
>     at ../../../kern/kern_mutex.c:479
> #12 0xc0578658 in _mtx_lock_flags (m=0x0, opts=0,
>     file=0xc0739490 "../../../dev/sound/pcm/sound.c", line=395)
>     at ../../../kern/kern_mutex.c:251
> #13 0xc051983d in pcm_chn_create (d=0xc6319800, parent=0x0, cls=0x0,
>     dir=-1066167152, devinfo=0x0) at ../../../dev/sound/pcm/sound.c:395
> #14 0xc051b26c in vchan_create (parent=0xc6300a80)
>     at ../../../dev/sound/pcm/vchan.c:265
> #15 0xc0519259 in pcm_chnalloc (d=0xc6319800, direction=1, pid=720, chnum=-1)
>     at ../../../dev/sound/pcm/sound.c:209
> #16 0xc051482c in dsp_open (i_dev=0xc07c2eb0, flags=7, mode=8192,
>     td=0xc68653f0) at ../../../dev/sound/pcm/dsp.c:274
> #17 0xc054871d in spec_open (ap=0xe7a83a64)
>     at ../../../fs/specfs/spec_vnops.c:207
> #18 0xc0548470 in spec_vnoperate (ap=0x0)
>     at ../../../fs/specfs/spec_vnops.c:122
> #19 0xc05e1a4e in vn_open_cred (ndp=0xe7a83bdc, flagp=0xe7a83cdc, cmode=0,
>     cred=0xc68cd580, fdidx=0) at vnode_if.h:228
> #20 0xc05e1623 in vn_open (ndp=0x0, flagp=0x0, cmode=0, fdidx=0)
>     at ../../../kern/vfs_vnops.c:93
> #21 0xc05dae8b in kern_open (td=0xc68653f0, path=0x0, pathseg=UIO_USERSPACE,
>     flags=7, mode=0) at ../../../kern/vfs_syscalls.c:963
> #22 0xc05dadb7 in open (td=0x0, uap=0x0) at ../../../kern/vfs_syscalls.c:933

It's interesting that nobody has run into this before.  I suspect that
the reason is that the mutexes in the sound code used the MTX_RECURSE
flag, which I recently removed, and since that time vchans have gotten
very little use (and probably not much use before, either).

This is an area that I was planning to work on fairly soon, but in the
meantime, I think you can avoid this bug by pre-creating vchans by
setting hw.snd.pcm0.vchans.

Thanks for the bug report.  It will be helpful when I crank out my next
locking patch.  BTW, I'm now thinking it would be more better to use
some flags and msleep()/wakeup() rather than adding an sx lock for the
next step.