Re: pcm(4) related panic

From: Artur Poplawski <artur_at_szuruburu.neostrada.pl>
Date: Tue, 25 Nov 2003 22:34:43 +0100
Artur Poplawski <artur_at_szuruburu.neostrada.pl> wrote:

> Hello,                                                                          
>                                                                                 
> On a 5.1-RELEASE and 5.2-BETA machines I have been able to cause a panic 
> like this:
>                                                                      
> (watch out for folded lines; the stack backtrace below is rewritten by
> hand from ddb)
> 
> lock order reversal
>  1st 0xc22a45ac vm object (vm object) _at_ /usr/src/sys/vm/swap_pager.c:1323
>  2nd 0xc06c0420 swap_pager swhash (swap_pager swhash) _at_ \
>         /usr/src/sys/vm/swap_pager.c:1838
>  3rd 0xc0c358c4 vm object (vm object) _at_ /usr/src/sys/vm/uma_core.c:876
> Stack backtrace:
>   backtrace
>   witness_lock
>   _mtx_lock_flags
>   obj_allock
>   slab_zalloc
>   uma_zone_slab
>   uma_zalloc_internal
>   uma_zalloc_arg
>   swp_pager_meta_build
>   swap_pager_putpages
>   default_pager_putpages
>   vm_pageout_flush
>   vm_pageout_clean
>   vm_pageout_scan
>   vm_pageout
>   fork_exit
>   fork_trampoline
> 
> Sleeping on "swread" with the following non-sleepable locks held:
> exclusive sleep mutex pcm0:play:0 (pcm channel) r = 0 (0xc1c3d740) locked _at_ \   
>         /usr/src/sys/dev/sound/pcm/dsp.c:146
> panic: sleeping thread (pid 583) owns a non-sleepable lock
> syncing disks, buffers remaining... 1410 1410 panic: mi_switch: \ 
>         switch in a critical section
> Uptime: 1m45s
> panic: msleep
> Uptime: 1m45s
> panic: msleep
> Uptime: 1m45s
> panic: msleep
> Uptime: 1m45s
> panic: msleep
> [... repeated few more times]
> Fatal double fault:
> eip = 0xc05e3916
> esp = 0xc8db8ff4
> ebp = 0xc8db9004
> panic: double fault
> Uptime: 1m45s
> panic: msleep
> Uptime: 1m45s 
> panic: msleep
> Uptime: 1m45s
> panic: msleep
> Uptime: 1m45s
> [...]
> And the machine suddenly reboots, so there is no coredump.
>  
> eip address points close to:
> c05e3910 T sc_vtb_putc
>  
> To reproduce this panic just start some audio player app (like xmms), 
> and launch countless memory-eating applications (like mozilla ;>).
> The machine starts swapping, and it panics. 
> 
> % uname -a 
> FreeBSD kaszanka.domek 5.2-BETA FreeBSD 5.2-BETA #0: Sun Nov 23 01:23:10\ 
>  CET 2003     artur_at_kaszanka.domek:/usr/obj/usr/src/sys/KASZANKA i386 
> 
> dmesg fragments:
> CPU: AMD Athlon(tm) XP 2000+ (1666.73-MHz 686-class CPU)
> pcm0: <AudioPCI ES1373-B> port 0xec00-0xec3f irq 10 at device 8.0 on pci0 
> pcm0: <Cirrus Logic CS4297A AC97 Codec>
> rl0: <RealTek 8139 10/100BaseTX> port 0xe800-0xe8ff mem \
>      0xdfffff00-0xdfffffff ir
> q 10 at device 10.0 on pci0
> miibus0: <MII bus> on rl0
> rlphy0: <RealTek internal media interface> on miibus0
> rlphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
> rl1: <RealTek 8139 10/100BaseTX> port 0xe400-0xe4ff mem \
>      0xdffffe00-0xdffffeff ir
> q 10 at device 11.0 on pci0
> rlphy1: <RealTek internal media interface> on miibus1
> rlphy1:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto



In the meantime I've managed to get a coredump, by directly calling
doadump() from ddb. Results:


root_at_kaszanka:/usr/obj/usr/src/sys/KASZANKA# gdb -k kernel.debug /var/crash/vmcore.0
GNU gdb 5.2.1 (FreeBSD)                      
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-undermydesk-freebsd"...
panic: sleeping thread (pid 568) owns a non-sleepable lock
panic messages:
---
panic: sleeping thread (pid 568) owns a non-sleepable lock

syncing disks, buffers remaining... panic: msleep
Dumping 128 MB
 16 32 48 64 80 96 112
---
Reading symbols from /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/modules/linprocfs/linprocfs.ko.debug...done.
Loaded symbols for /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/modules/linprocfs/linprocfs.ko.debug
Reading symbols from /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/modules/linux/linux.ko.debug...done.
Loaded symbols for /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/modules/linux/linux.ko.debug
Reading symbols from /boot/kernel/netgraph.ko...done.
Loaded symbols for /boot/kernel/netgraph.ko
Reading symbols from /boot/kernel/ng_ether.ko...done.
Loaded symbols for /boot/kernel/ng_ether.ko
Reading symbols from /boot/kernel/ng_pppoe.ko...done.
Loaded symbols for /boot/kernel/ng_pppoe.ko
Reading symbols from /boot/kernel/ng_socket.ko...done.
Loaded symbols for /boot/kernel/ng_socket.ko
Reading symbols from /boot/kernel/mga.ko...done.
Loaded symbols for /boot/kernel/mga.ko
#0  doadump () at /usr/src/sys/kern/kern_shutdown.c:240
240             dumping++;
(kgdb) where
#0  doadump () at /usr/src/sys/kern/kern_shutdown.c:240
#1  0xc04292cd in db_fncall (dummy1=0, dummy2=0, dummy3=0, dummy4=0xc8dba7bc "à×hÀ") at /usr/src/sys/ddb/db_command.c:548
#2  0xc042906a in db_command (last_cmdp=0xc068ce80, cmd_table=0x0, aux_cmd_tablep=0xc06480c0, aux_cmd_tablep_end=0xc06480c4)
    at /usr/src/sys/ddb/db_command.c:346
#3  0xc0429178 in db_command_loop () at /usr/src/sys/ddb/db_command.c:472
#4  0xc042beb9 in db_trap (type=3, code=0) at /usr/src/sys/ddb/db_trap.c:73
#5  0xc05f00b3 in kdb_trap (type=3, code=0, regs=0xc8dba8fc) at /usr/src/sys/i386/i386/db_interface.c:171
#6  0xc05ff9ee in trap (frame=
      {tf_fs = 24, tf_es = 16, tf_ds = 16, tf_edi = 0, tf_esi = -1067253613, tf_ebp = -925128376, tf_isp = -925128408, tf_ebx = 0, tf_edx = 0, tf_ecx = 0, tf_eax = 18, tf_trapno = 3, tf_err = 0, tf_eip = -1067515059, tf_cs = 8, tf_eflags = 134, tf_esp = -1067175921, tf_ss = -1067255602}) at /usr/src/sys/i386/i386/trap.c:580
#7  0xc05f1988 in calltrap () at {standard input}:94
#8  0xc04e76fc in panic (fmt=0xc0630093 "msleep") at /usr/src/sys/kern/kern_shutdown.c:534
#9  0xc04ee999 in msleep (ident=0xc4461408, mtx=0xc06be3a0, priority=76, wmesg=0xc0635f46 "biord", timo=0)
    at /usr/src/sys/kern/kern_synch.c:262
#10 0xc0532dd6 in bwait (bp=0xc4461408, pri=76 'L', wchan=0xc0635f46 "biord") at /usr/src/sys/kern/vfs_bio.c:3762
#11 0xc0531523 in bufwait (bp=0xc4461408) at /usr/src/sys/kern/vfs_bio.c:3044
#12 0xc052d066 in breadn (vp=0xc1cd3000, blkno=0, size=0, rablkno=0x0, rabsize=0x0, cnt=0, cred=0x0, bpp=0x0)
    at /usr/src/sys/kern/vfs_bio.c:747
#13 0xc052cd7c in bread (vp=0x0, blkno=0, size=0, cred=0x0, bpp=0x0) at /usr/src/sys/kern/vfs_bio.c:682
#14 0xc0590087 in ffs_update (vp=0xc1daf104, waitfor=0) at /usr/src/sys/ufs/ffs/ffs_inode.c:108
#15 0xc05a529f in ffs_fsync (ap=0xc8dbab68) at /usr/src/sys/ufs/ffs/ffs_vnops.c:325
#16 0xc05a4334 in ffs_sync (mp=0xc1ccc400, waitfor=2, cred=0xc0f99e80, td=0xc06922c0) at vnode_if.h:627
#17 0xc054236b in sync (td=0xc06922c0, uap=0x0) at /usr/src/sys/kern/vfs_syscalls.c:141
#18 0xc04e6f60 in boot (howto=256) at /usr/src/sys/kern/kern_shutdown.c:281
#19 0xc04e7767 in panic () at /usr/src/sys/kern/kern_shutdown.c:550
#20 0xc050b4f0 in propagate_priority (td=0xc1dc98c0) at /usr/src/sys/kern/subr_turnstile.c:176
#21 0xc050bf17 in turnstile_wait (ts=0xc0f9e1c0, lock=0xc1c3d740, owner=0xc1dc98c0) at /usr/src/sys/kern/subr_turnstile.c:509
#22 0xc04de21f in _mtx_lock_sleep (m=0xc1c3d740, opts=0, file=0xc0628d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=440)
    at /usr/src/sys/kern/kern_mutex.c:476
#23 0xc04dddd7 in _mtx_lock_flags (m=0xc1c3d740, opts=0, file=0xc0628d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=440)
    at /usr/src/sys/kern/kern_mutex.c:218
#24 0xc049258f in chn_intr (c=0xc1c3d740) at /usr/src/sys/dev/sound/pcm/channel.c:440
#25 0xc047d973 in es_intr (p=0xc1bee280) at /usr/src/sys/dev/sound/pci/es137x.c:469
#26 0xc04d42c2 in ithread_loop (arg=0xc0fa3880) at /usr/src/sys/kern/kern_intr.c:544
#27 0xc04d32d4 in fork_exit (callout=0xc04d4150 <ithread_loop>, arg=0x0, frame=0x0) at /usr/src/sys/kern/kern_fork.c:793
(kgdb) up 9
#9  0xc04ee999 in msleep (ident=0xc4461408, mtx=0xc06be3a0, priority=76, wmesg=0xc0635f46 "biord", timo=0)
    at /usr/src/sys/kern/kern_synch.c:262
262             KASSERT(TD_IS_RUNNING(td), ("running but not TDS_RUNNING"));
(kgdb) l
257             /*
258              * We're awake from voluntary sleep.
259              */
260             CTR3(KTR_PROC, "msleep resume: thread %p (pid %d, %s)", td, p->p_pid,
261                 p->p_comm);
262             KASSERT(TD_IS_RUNNING(td), ("running but not TDS_RUNNING"));
263             td->td_flags &= ~TDF_SINTR;
264             if (td->td_flags & TDF_TIMEOUT) {
265                     td->td_flags &= ~TDF_TIMEOUT;
266                     if (sig == 0)
(kgdb) up 1
#10 0xc0532dd6 in bwait (bp=0xc4461408, pri=76 'L', wchan=0xc0635f46 "biord") at /usr/src/sys/kern/vfs_bio.c:3762
3762                    msleep(bp, &bdonelock, pri, wchan, 0);
(kgdb) l
3757    void
3758    bwait(struct buf *bp, u_char pri, const char *wchan)
3759    {
3760            mtx_lock(&bdonelock);
3761            while ((bp->b_flags & B_DONE) == 0)
3762                    msleep(bp, &bdonelock, pri, wchan, 0);
3763            mtx_unlock(&bdonelock);
3764    }
3765    
3766    #include "opt_ddb.h"
(kgdb) up 8
#18 0xc04e6f60 in boot (howto=256) at /usr/src/sys/kern/kern_shutdown.c:281
281                     sync(&thread0, NULL);
(kgdb) up 2
#20 0xc050b4f0 in propagate_priority (td=0xc1dc98c0) at /usr/src/sys/kern/subr_turnstile.c:176
176                     KASSERT(!TD_IS_SLEEPING(td),
(kgdb) l
171                      * first thread to grab a slock of a sx lock.  In that case
172                      * it is possible for us to be at SSLEEP or some other
173                      * weird state.  We should probably just return if the state
174                      * isn't SRUN or SLOCK.
175                      */
176                     KASSERT(!TD_IS_SLEEPING(td),
177                         ("sleeping thread (pid %d) owns a non-sleepable lock",
178                         td->td_proc->p_pid));
179     
180                     /*
(kgdb) up 1
#21 0xc050bf17 in turnstile_wait (ts=0xc0f9e1c0, lock=0xc1c3d740, owner=0xc1dc98c0) at /usr/src/sys/kern/subr_turnstile.c:509
509             propagate_priority(td);
(kgdb) l
504     
505             /* Save who we are blocked on and switch. */
506             td->td_blocked = ts;
507             td->td_lockname = lock->lo_name;
508             TD_SET_LOCK(td);
509             propagate_priority(td);
510     
511             if (LOCK_LOG_TEST(lock, 0))
512                     CTR4(KTR_LOCK, "%s: td %p blocked on [%p] %s", __func__, td,
513                         lock, lock->lo_name);
(kgdb) up 1  
#22 0xc04de21f in _mtx_lock_sleep (m=0xc1c3d740, opts=0, file=0xc0628d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=440)
    at /usr/src/sys/kern/kern_mutex.c:476
476                     turnstile_wait(ts, &m->mtx_object, mtx_owner(m));
(kgdb) l
471     #endif
472     
473                     /*
474                      * Block on the turnstile.
475                      */
476                     turnstile_wait(ts, &m->mtx_object, mtx_owner(m));
477             }
478     
479     #ifdef KTR
480             if (cont_logged) {
(kgdb) up 1  
#23 0xc04dddd7 in _mtx_lock_flags (m=0xc1c3d740, opts=0, file=0xc0628d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=440)
    at /usr/src/sys/kern/kern_mutex.c:218
218             _get_sleep_lock(m, curthread, opts, file, line);
(kgdb) l
213     
214             MPASS(curthread != NULL);
215             KASSERT(m->mtx_object.lo_class == &lock_class_mtx_sleep,
216                 ("mtx_lock() of spin mutex %s _at_ %s:%d", m->mtx_object.lo_name,
217                 file, line));
218             _get_sleep_lock(m, curthread, opts, file, line);
219             LOCK_LOG_LOCK("LOCK", &m->mtx_object, opts, m->mtx_recurse, file,
220                 line);
221             WITNESS_LOCK(&m->mtx_object, opts | LOP_EXCLUSIVE, file, line);
222     #ifdef MUTEX_PROFILING
(kgdb) up 1
#24 0xc049258f in chn_intr (c=0xc1c3d740) at /usr/src/sys/dev/sound/pcm/channel.c:440
440             CHN_LOCK(c);
(kgdb) l
435     }
436     
437     void
438     chn_intr(struct pcm_channel *c)
439     {
440             CHN_LOCK(c);
441             c->interrupts++;
442             if (c->direction == PCMDIR_PLAY)
443                     chn_wrintr(c);
444             else
(kgdb) up 1
#25 0xc047d973 in es_intr (p=0xc1bee280) at /usr/src/sys/dev/sound/pci/es137x.c:469
469             if (intsrc & STAT_DAC2) chn_intr(es->pch.channel);
(kgdb) l
464             bus_space_write_4(es->st, es->sh, ES1370_REG_SERIAL_CONTROL, sctrl);
465             bus_space_write_4(es->st, es->sh, ES1370_REG_SERIAL_CONTROL, es->sctrl);
466     
467             if (intsrc & STAT_ADC) chn_intr(es->rch.channel);
468             if (intsrc & STAT_DAC1);
469             if (intsrc & STAT_DAC2) chn_intr(es->pch.channel);
470     }
471     
472     /* ES1370 specific */
473     static int
Received on Tue Nov 25 2003 - 12:34:04 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:37:31 UTC