From owner-freebsd-current@FreeBSD.ORG Tue Nov 25 13:34:04 2003 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 947D216A4CE for ; Tue, 25 Nov 2003 13:34:04 -0800 (PST) Received: from mta1.tpinternet.pl (outgoing.tpinternet.pl [193.110.120.20]) by mx1.FreeBSD.org (Postfix) with ESMTP id 9547843F93 for ; Tue, 25 Nov 2003 13:34:00 -0800 (PST) (envelope-from artur@szuruburu.neostrada.pl) Received: from kaszanka (ad150.neoplus.adsl.tpnet.pl [80.50.149.150]) by mta1.tpinternet.pl (Postfix) with ESMTP id A1CCBAA85 for ; Tue, 25 Nov 2003 22:33:50 +0100 (CET) Date: Tue, 25 Nov 2003 22:34:43 +0100 From: Artur Poplawski To: freebsd-current@freebsd.org Message-Id: <20031125223443.45cdfae3.artur@szuruburu.neostrada.pl> In-Reply-To: <20031125161723.14260206.artur@szuruburu.neostrada.pl> References: <20031125161723.14260206.artur@szuruburu.neostrada.pl> X-Mailer: Sylpheed version 0.9.6 (GTK+ 1.2.10; i386-portbld-freebsd5.1) Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Subject: Re: pcm(4) related panic X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 25 Nov 2003 21:34:04 -0000 Artur Poplawski wrote: > Hello, = =20 > = =20 > On a 5.1-RELEASE and 5.2-BETA machines I have been able to cause a panic= =20 > like this: > =20 > (watch out for folded lines; the stack backtrace below is rewritten by > hand from ddb) >=20 > lock order reversal > 1st 0xc22a45ac vm object (vm object) @ /usr/src/sys/vm/swap_pager.c:1323 > 2nd 0xc06c0420 swap_pager swhash (swap_pager swhash) @ \ > /usr/src/sys/vm/swap_pager.c:1838 > 3rd 0xc0c358c4 vm object (vm object) @ /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 >=20 > Sleeping on "swread" with the following non-sleepable locks held: > exclusive sleep mutex pcm0:play:0 (pcm channel) r =3D 0 (0xc1c3d740) lock= ed @ \ =20 > /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: \=20 > 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 =3D 0xc05e3916 > esp =3D 0xc8db8ff4 > ebp =3D 0xc8db9004 > panic: double fault > Uptime: 1m45s > panic: msleep > Uptime: 1m45s=20 > panic: msleep > Uptime: 1m45s > panic: msleep > Uptime: 1m45s > [...] > And the machine suddenly reboots, so there is no coredump. > =20 > eip address points close to: > c05e3910 T sc_vtb_putc > =20 > To reproduce this panic just start some audio player app (like xmms),=20 > and launch countless memory-eating applications (like mozilla ;>). > The machine starts swapping, and it panics.=20 >=20 > % uname -a=20 > FreeBSD kaszanka.domek 5.2-BETA FreeBSD 5.2-BETA #0: Sun Nov 23 01:23:10\= =20 > CET 2003 artur@kaszanka.domek:/usr/obj/usr/src/sys/KASZANKA i386=20 >=20 > dmesg fragments: > CPU: AMD Athlon(tm) XP 2000+ (1666.73-MHz 686-class CPU) > pcm0: port 0xec00-0xec3f irq 10 at device 8.0 on pci0= =20 > pcm0: > rl0: port 0xe800-0xe8ff mem \ > 0xdfffff00-0xdfffffff ir > q 10 at device 10.0 on pci0 > miibus0: on rl0 > rlphy0: on miibus0 > rlphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto > rl1: port 0xe400-0xe4ff mem \ > 0xdffffe00-0xdffffeff ir > q 10 at device 11.0 on pci0 > rlphy1: 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@kaszanka:/usr/obj/usr/src/sys/KASZANKA# gdb -k kernel.debug /var/crash= /vmcore.0 GNU gdb 5.2.1 (FreeBSD) =20 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 condition= s. 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/modu= les/linprocfs/linprocfs.ko.debug...done. Loaded symbols for /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/module= s/linprocfs/linprocfs.ko.debug Reading symbols from /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/modu= les/linux/linux.ko.debug...done. Loaded symbols for /usr/obj/usr/src/sys/KASZANKA/modules/usr/src/sys/module= s/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=3D0, dummy2=3D0, dummy3=3D0, dummy4=3D0= xc8dba7bc "=E0=D7h=C0") at /usr/src/sys/ddb/db_command.c:548 #2 0xc042906a in db_command (last_cmdp=3D0xc068ce80, cmd_table=3D0x0, aux_= cmd_tablep=3D0xc06480c0, aux_cmd_tablep_end=3D0xc06480c4) 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=3D3, code=3D0) at /usr/src/sys/ddb/db_trap.= c:73 #5 0xc05f00b3 in kdb_trap (type=3D3, code=3D0, regs=3D0xc8dba8fc) at /usr/= src/sys/i386/i386/db_interface.c:171 #6 0xc05ff9ee in trap (frame=3D {tf_fs =3D 24, tf_es =3D 16, tf_ds =3D 16, tf_edi =3D 0, tf_esi =3D -= 1067253613, tf_ebp =3D -925128376, tf_isp =3D -925128408, tf_ebx =3D 0, tf_= edx =3D 0, tf_ecx =3D 0, tf_eax =3D 18, tf_trapno =3D 3, tf_err =3D 0, tf_e= ip =3D -1067515059, tf_cs =3D 8, tf_eflags =3D 134, tf_esp =3D -1067175921,= tf_ss =3D -1067255602}) at /usr/src/sys/i386/i386/trap.c:580 #7 0xc05f1988 in calltrap () at {standard input}:94 #8 0xc04e76fc in panic (fmt=3D0xc0630093 "msleep") at /usr/src/sys/kern/ke= rn_shutdown.c:534 #9 0xc04ee999 in msleep (ident=3D0xc4461408, mtx=3D0xc06be3a0, priority=3D= 76, wmesg=3D0xc0635f46 "biord", timo=3D0) at /usr/src/sys/kern/kern_synch.c:262 #10 0xc0532dd6 in bwait (bp=3D0xc4461408, pri=3D76 'L', wchan=3D0xc0635f46 = "biord") at /usr/src/sys/kern/vfs_bio.c:3762 #11 0xc0531523 in bufwait (bp=3D0xc4461408) at /usr/src/sys/kern/vfs_bio.c:= 3044 #12 0xc052d066 in breadn (vp=3D0xc1cd3000, blkno=3D0, size=3D0, rablkno=3D0= x0, rabsize=3D0x0, cnt=3D0, cred=3D0x0, bpp=3D0x0) at /usr/src/sys/kern/vfs_bio.c:747 #13 0xc052cd7c in bread (vp=3D0x0, blkno=3D0, size=3D0, cred=3D0x0, bpp=3D0= x0) at /usr/src/sys/kern/vfs_bio.c:682 #14 0xc0590087 in ffs_update (vp=3D0xc1daf104, waitfor=3D0) at /usr/src/sys= /ufs/ffs/ffs_inode.c:108 #15 0xc05a529f in ffs_fsync (ap=3D0xc8dbab68) at /usr/src/sys/ufs/ffs/ffs_v= nops.c:325 #16 0xc05a4334 in ffs_sync (mp=3D0xc1ccc400, waitfor=3D2, cred=3D0xc0f99e80= , td=3D0xc06922c0) at vnode_if.h:627 #17 0xc054236b in sync (td=3D0xc06922c0, uap=3D0x0) at /usr/src/sys/kern/vf= s_syscalls.c:141 #18 0xc04e6f60 in boot (howto=3D256) at /usr/src/sys/kern/kern_shutdown.c:2= 81 #19 0xc04e7767 in panic () at /usr/src/sys/kern/kern_shutdown.c:550 #20 0xc050b4f0 in propagate_priority (td=3D0xc1dc98c0) at /usr/src/sys/kern= /subr_turnstile.c:176 #21 0xc050bf17 in turnstile_wait (ts=3D0xc0f9e1c0, lock=3D0xc1c3d740, owner= =3D0xc1dc98c0) at /usr/src/sys/kern/subr_turnstile.c:509 #22 0xc04de21f in _mtx_lock_sleep (m=3D0xc1c3d740, opts=3D0, file=3D0xc0628= d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=3D440) at /usr/src/sys/kern/kern_mutex.c:476 #23 0xc04dddd7 in _mtx_lock_flags (m=3D0xc1c3d740, opts=3D0, file=3D0xc0628= d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=3D440) at /usr/src/sys/kern/kern_mutex.c:218 #24 0xc049258f in chn_intr (c=3D0xc1c3d740) at /usr/src/sys/dev/sound/pcm/c= hannel.c:440 #25 0xc047d973 in es_intr (p=3D0xc1bee280) at /usr/src/sys/dev/sound/pci/es= 137x.c:469 #26 0xc04d42c2 in ithread_loop (arg=3D0xc0fa3880) at /usr/src/sys/kern/kern= _intr.c:544 #27 0xc04d32d4 in fork_exit (callout=3D0xc04d4150 , arg=3D0x0= , frame=3D0x0) at /usr/src/sys/kern/kern_fork.c:793 (kgdb) up 9 #9 0xc04ee999 in msleep (ident=3D0xc4461408, mtx=3D0xc06be3a0, priority=3D= 76, wmesg=3D0xc0635f46 "biord", timo=3D0) 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 &=3D ~TDF_SINTR; 264 if (td->td_flags & TDF_TIMEOUT) { 265 td->td_flags &=3D ~TDF_TIMEOUT; 266 if (sig =3D=3D 0) (kgdb) up 1 #10 0xc0532dd6 in bwait (bp=3D0xc4461408, pri=3D76 'L', wchan=3D0xc0635f46 = "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) =3D=3D 0) 3762 msleep(bp, &bdonelock, pri, wchan, 0); 3763 mtx_unlock(&bdonelock); 3764 } 3765 =20 3766 #include "opt_ddb.h" (kgdb) up 8 #18 0xc04e6f60 in boot (howto=3D256) at /usr/src/sys/kern/kern_shutdown.c:2= 81 281 sync(&thread0, NULL); (kgdb) up 2 #20 0xc050b4f0 in propagate_priority (td=3D0xc1dc98c0) 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 t= hat case 172 * it is possible for us to be at SSLEEP or some ot= her 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 =20 180 /* (kgdb) up 1 #21 0xc050bf17 in turnstile_wait (ts=3D0xc0f9e1c0, lock=3D0xc1c3d740, owner= =3D0xc1dc98c0) at /usr/src/sys/kern/subr_turnstile.c:509 509 propagate_priority(td); (kgdb) l 504 =20 505 /* Save who we are blocked on and switch. */ 506 td->td_blocked =3D ts; 507 td->td_lockname =3D lock->lo_name; 508 TD_SET_LOCK(td); 509 propagate_priority(td); 510 =20 511 if (LOCK_LOG_TEST(lock, 0)) 512 CTR4(KTR_LOCK, "%s: td %p blocked on [%p] %s", __fu= nc__, td, 513 lock, lock->lo_name); (kgdb) up 1 =20 #22 0xc04de21f in _mtx_lock_sleep (m=3D0xc1c3d740, opts=3D0, file=3D0xc0628= d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=3D440) at /usr/src/sys/kern/kern_mutex.c:476 476 turnstile_wait(ts, &m->mtx_object, mtx_owner(m)); (kgdb) l 471 #endif 472 =20 473 /* 474 * Block on the turnstile. 475 */ 476 turnstile_wait(ts, &m->mtx_object, mtx_owner(m)); 477 } 478 =20 479 #ifdef KTR 480 if (cont_logged) { (kgdb) up 1 =20 #23 0xc04dddd7 in _mtx_lock_flags (m=3D0xc1c3d740, opts=3D0, file=3D0xc0628= d54 "/usr/src/sys/dev/sound/pcm/channel.c", line=3D440) at /usr/src/sys/kern/kern_mutex.c:218 218 _get_sleep_lock(m, curthread, opts, file, line); (kgdb) l 213 =20 214 MPASS(curthread !=3D NULL); 215 KASSERT(m->mtx_object.lo_class =3D=3D &lock_class_mtx_sleep, 216 ("mtx_lock() of spin mutex %s @ %s:%d", m->mtx_object.l= o_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, li= ne); 222 #ifdef MUTEX_PROFILING (kgdb) up 1 #24 0xc049258f in chn_intr (c=3D0xc1c3d740) at /usr/src/sys/dev/sound/pcm/c= hannel.c:440 440 CHN_LOCK(c); (kgdb) l 435 } 436 =20 437 void 438 chn_intr(struct pcm_channel *c) 439 { 440 CHN_LOCK(c); 441 c->interrupts++; 442 if (c->direction =3D=3D PCMDIR_PLAY) 443 chn_wrintr(c); 444 else (kgdb) up 1 #25 0xc047d973 in es_intr (p=3D0xc1bee280) at /usr/src/sys/dev/sound/pci/es= 137x.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 =20 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 =20 472 /* ES1370 specific */ 473 static int