Date: Mon, 5 Jan 2004 11:27:30 -0800 (PST) From: Don Lewis <truckman@FreeBSD.org> To: bde@zeta.org.au Cc: shoesoft@gmx.net Subject: Re: page fault panic tracked down (selwakeuppri()) Message-ID: <200401051927.i05JRU7E011991@gw.catspoiler.org> In-Reply-To: <20040105202928.Q4703@gamplex.bde.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On 5 Jan, Bruce Evans wrote: > On Sun, 4 Jan 2004, Stefan Ehmann wrote: > >> For the first time I got a backtrace that ended in the soundcard module >> - So maybe this is the right direction (on the other hand this might be >> some newly introduced error) >> >> panic: bad bufsize >> #0 doadump () at /usr/src/sys/kern/kern_shutdown.c:240 >> #1 0xc04e5198 in boot (howto=256) at >> /usr/src/sys/kern/kern_shutdown.c:372 >> #2 0xc04e5527 in panic () at /usr/src/sys/kern/kern_shutdown.c:550 >> #3 0xc07ec648 in feed_vchan_s16 () from /boot/kernel/snd_pcm.ko >> #4 0xc07e2c6d in sndbuf_feed () from /boot/kernel/snd_pcm.ko >> #5 0xc07e3225 in chn_wrfeed () from /boot/kernel/snd_pcm.ko >> #6 0xc07e327c in chn_wrintr () from /boot/kernel/snd_pcm.ko >> #7 0xc07e3990 in chn_intr () from /boot/kernel/snd_pcm.ko >> #8 0xc07fca2f in csa_intr () from /boot/kernel/snd_csa.ko >> #9 0xc07fb724 in csa_intr () from /boot/kernel/snd_csa.ko >> #10 0xc04d1692 in ithread_loop (arg=0xc1737b00) >> at /usr/src/sys/kern/kern_intr.c:544 >> #11 0xc04d0684 in fork_exit (callout=0xc04d1500 <ithread_loop>, arg=0x0, >> frame=0x0) at /usr/src/sys/kern/kern_fork.c:796 > > The sound driver is in modules. Have you ruled out having an inconsistent > module. > >> Nearly all other panics (I put a collection of ~20 backtraces on >> http://stud4.tuwien.ac.at/~e0125637/fbsd/ if it's of any interest) ended >> up in file system code. > > The args in many of these don't make sense. E.g., in bt.13: > > % ... > % #15 0xc06743f8 in calltrap () at {standard input}:94 > % #16 0xc0502a34 in lockmgr (lkp=0xc3a91028, flags=0, interlkp=0xe4, > % td=0xc06bfc68) at /usr/src/sys/kern/kern_lock.c:228 > % #17 0xc0566c67 in vfs_busy (mp=0x0, flags=0, interlkp=0x0, td=0x0) > % at /usr/src/sys/kern/vfs_subr.c:527 > % #18 0xc056362c in lookup (ndp=0xd8cd5bdc) at /usr/src/sys/kern/vfs_lookup.c:559 > % ... > > mp=0x0 in #17 can't happen, and is inconsistent with lkp!=0 in #16 > (since lkp = &mp->mnt_lock). The panic in line 228 in #16 is from lkp > being garbage, so apparently it is not &mp->mnt_lock for a correct mp > either. flags=0 and interlkp=0x0 in #17 are correct. td=0x0 is > inconsistent with td!=0 in #16 (I think the latter is correct). flags=0 > in #16 is correct. interlkp=0xe4 in #16 is inconsistent with interlkp=0 > in #17. As I've mentioned before, it appears that gdb has problems decoding stack frames around a trap and I've seen a lot of "can't happen" things in the stack frames leading up to the trap. > Compiling without optimization might simplify debugging, but I thought that > gcc doesn't clobber stack args even with optimization. > > bt.34 has an example of a garbage arg the is unlikely to be from > mis-debugging it since it is in 2 stack frames: > > % ... > % #3 0xc0560029 in getblk (vp=0xc42ec6d8, blkno=16, size=7537385, slpflag=0, > ^^^^^^^^^^^^ > % slptimeo=0, flags=0) at /usr/src/sys/kern/vfs_bio.c:2415 > % #4 0xc05650bd in cluster_read (vp=0xc42ec6d8, filesize=3675636, lblkno=16, > % size=7537385, cred=0x0, totread=32768, seqcount=0, bpp=0x0) > ^^^^^^^^^^^^ > % at /usr/src/sys/kern/vfs_cluster.c:127 > % #5 0xc419efa7 in ext2_read (ap=0xd8d17bcc) > % at @/gnu/ext2fs/ext2_readwrite.c:115 > % ... > > `size' is the ext2fs block size. It should be either 1K or 4K for ext2fs. > So the size, or more likely the pointer to it, is corrupt in ext2_read() > here: > > % size = BLKSIZE(fs, ip, lbn); > ^^^^^^^^^^^^^^^^^^^^^^^^^^^ > % blkoffset = blkoff(fs, uio->uio_offset); > % > % xfersize = fs->s_frag_size - blkoffset; > % if (uio->uio_resid < xfersize) > % xfersize = uio->uio_resid; > % if (bytesinfile < xfersize) > % xfersize = bytesinfile; > % > % if (lblktosize(fs, nextlbn) >= ip->i_size) > % error = bread(vp, lbn, size, NOCRED, &bp); > % else if ((vp->v_mount->mnt_flag & MNT_NOCLUSTERR) == 0) > % error = cluster_read(vp, > % ip->i_size, lbn, size, NOCRED, > ^^^^ > % uio->uio_resid, (ap->a_ioflag >> 16), &bp); > > BLKSIZE(fs, ip, lbn) depends mainly on ip (fs is ip->FS), so it seems that > we have a corrupt ip here. This is consistent with some of the panics > being nearer to inode allocation. *_vget() has delicate locking which > has caused problems before. I just remembered than ext2_vget() and > other *_vget() (nfs...) are missing the last round of locking changes > in ffs_vget() (ffs_vfsops.c 1.181). But these changes are only claimed > to be simplifications and optimizationns. I can't see any bugs in the > locking in ext2_vget() except that stuff like the following makes too > many assumptions: My next to last message on this subject appears to have disappeared into the void, but basically I'm very suspicious of the sound code at this point. In some of the earlier debugging that Stefan and I did, we typically found chunks of the kernel heap that were zeroed. One common case was that an entire "struct mount" was clobbered. It is very interesting that feed_vchan_s16() bzero()s a couple of buffers allocated from the heap. We also turned on DEBUG_VFS_LOCKS and added some extra sanity checks in the lock checking functions. When the assertions failed, it tended to eliminate point away from the file system top half, and it really looked to me like the problem was in the bottom half of the kernel. This also is consistent with a problem in the sound interrupt code. Another clue is that Stefan mentioned that the panics tend to occur when switching between songs, which could either point to a file system problem or something in the sound code if the player closes and opens the channel or does something else to flush it. There are parts of the sound code that allocate and re-allocate the buffers that is unprotected by the channel mutex (which can't be held across a malloc() call). The channel interrupt handler should not be running during these times, but this code is difficult enough for me to follow that I can't be sure. The problem really looks to me a lot like either the interrupt handler is getting called at a bad time or for some other reason it is getting garbage parameters. We'll probably have to peel back a few more layers of the onion. I suspect that ext2fs + selwakeuppri() + certain CPU speeds + certain sound hardware == bad luck.
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200401051927.i05JRU7E011991>