From owner-freebsd-current@FreeBSD.ORG Sat Jun 5 23:13:07 2004 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 A67C016A4CE; Sat, 5 Jun 2004 23:13:07 -0700 (PDT) Received: from www.mmlab.cse.yzu.edu.tw (www.mmlab.cse.yzu.edu.tw [140.138.145.166]) by mx1.FreeBSD.org (Postfix) with ESMTP id 0874543D1D; Sat, 5 Jun 2004 23:13:07 -0700 (PDT) (envelope-from avatar@mmlab.cse.yzu.edu.tw) Received: by www.mmlab.cse.yzu.edu.tw (qmail, from userid 1000) id D4CC24EFCD8; Sun, 6 Jun 2004 14:13:05 +0800 (CST) Received: from localhost (localhost [127.0.0.1]) by www.mmlab.cse.yzu.edu.tw (qmail) with ESMTP id D10DB4EFCD7; Sun, 6 Jun 2004 14:13:05 +0800 (CST) Date: Sun, 6 Jun 2004 14:13:05 +0800 (CST) From: Tai-hwa Liang To: Don Lewis In-Reply-To: <200406052132.i55LVwka006489@gw.catspoiler.org> Message-ID: <0406061343047.77519@www.mmlab.cse.yzu.edu.tw> References: <200406052132.i55LVwka006489@gw.catspoiler.org> MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII cc: freebsd-current@FreeBSD.org cc: dl@leo.org Subject: Re: LOR No 9 and strange other kernel messages 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: Sun, 06 Jun 2004 06:13:07 -0000 On Sat, 5 Jun 2004, Don Lewis wrote: > On 5 Jun, Tai-hwa Liang wrote: > > On Fri, 4 Jun 2004, Don Lewis wrote: > >> On 4 Jun, Tai-hwa Liang wrote: > >> > On Fri, 4 Jun 2004, Daniel Lang wrote: > >> >> Hi, > >> >> > >> >> I just went through my syslog and stumbled across a LOR, which is > >> >> documented on the Zabbadoz LOR page (id 009). > >> >> > >> >> The reason for this mail is the following kernel messages: > >> >> > >> >> [..] > >> >> Jun 1 11:08:06 atrbg11 kernel: x: 2 > >> >> Jun 1 11:08:06 atrbg11 kernel: x: 2 > >> >> [..] > >> >> > >> >> Seems some leftovers from a developer who did not want to > >> >> bother others with the gory details. ;-)) > >> > > >> > I guess that came from sys/dev/sound/pcm/sound.c:872. My Thinkpad T40 also > >> > ran into this when the disk/network(combination) load is high enough. > >> > >> Looks likely, but I'd expect this would only get triggered when sysctl > >> is used to set or query the number of vchans. In any case, this marks > >> another spot where locking is broken in the sound code. > > > > I use the default setting without tweaking any vchan related sysctl > > such like hw.snd.pcm0.vchans(leave it to default 0) or hw.snd.maxautovchans > > (also left to 0 on my T40). > > Maybe your sound client software (or something else on the system) is > querying for the number of vchans. Even "sysctl -a" will invoke the > handler. I'm using the stock mpg123 0.59r to play MP3 files. Since I've never read the source before, I'm not sure whether it utilised vchan related sysctls or not. > > I'm wondering about whether this "bug" is ACPI related(interrupt storm?) > > since recently when I run "make buildworld buildkernel" on one terminal and > > do large file transmission(FTP ISO images on using em0) at the same time, > > the sound tends to become "broken." Meanwhile, the "x: 2" message popped > > on my console and later on my em0 doesn't work anymore(I have to do a reboot > > to get it back; however, the other part of the system still works while > > em0 was dead: sound continue playing, can compile/edit programs). > > It is quite possible that locking collisions in the sound code might > happen more frequently when the system is busy. > > Do your sound hardware and em0 share the same irq? If they do, that Nope. interrupt total rate irq0: clk 356127 99 irq1: atkbd0 6006 1 irq4: cbb0 em0++ 1378364 386 irq6: cbb1 pcm0 110211 30 irq7: ppc0 3 0 irq8: rtc 455852 127 irq12: psm0 16785 4 irq13: npx0 1 0 irq14: ata0 322853 90 irq15: ata1 55 0 Total 2646257 742 > might be a clue that the problems are related. Can you boot with ACPI > disabled, and if so, does it change the symptoms? Whoops! My first trial on booting without ACPI -- kernel panic in usb_get_next_event(). Apparently I have to disconnect the USB mouse prior to kernel booting. See final section for the backtrace. And, yes, the em0 didn't hang after booting to the non-ACPI environment. However, there're still something weird happening at that moment: 1. There're still a couple of "x: 2" dumped on console. Test case: "make buildworld buildkernel -DNOCLEAN" in one xterm, mpg123 in another xterm, and providing file downloading to another Windoze box. 2. While the remote box was downloading(Intel eepro 100/VE) files, the number of interrupt on em0 was dramatically reduced to 300 ~ 500+ per second. It was 3000+ when ACPI was enabled(no device polling in kernel). 3. The system average load is surprising low(I'm using SCHED_4BSD), about 0.06 ~ 0.30; however, the download was awfully slooowwwww. It took my brother's Windoze XP about 25 minutes to complete the whole downloading(3 ISO files, about 2GB in total). I'm pretty sure that the mediaopt on em0 was 100baseTX + full-duplex. ------------------------ backtrace --------------------------- 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: from debugger panic messages: --- Fatal trap 12: page fault while in kernel mode fault virtual address = 0x0 fault code = supervisor read, page not present instruction pointer = 0x8:0xc074af0d stack pointer = 0x10:0xcdce59fc frame pointer = 0x10:0xcdce5a08 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, def32 1, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 403 (usbd) kernel: type 12 trap, code=0 panic: from debugger at line 453 in file ../../../ddb/db_command.c Stack backtrace: Fatal trap 3: breakpoint instruction fault while in kernel mode instruction pointer = 0x8:0xc05a9f9d stack pointer = 0x10:0xcdce57dc frame pointer = 0x10:0xcdce57e0 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, def32 1, gran 1 processor eflags = IOPL = 0 current process = 403 (usbd) panic: from debugger at line 453 in file ../../../ddb/db_command.cUptime: 15s Dumping 255 MB 16 32 48 64 80 96 112 128 144 160 176 192 208 224 240 --- Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/md/md.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/md/md.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/linux/linux.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/linux/linux.ko.debug Reading symbols from /boot/kernel/if_em.ko...done. Loaded symbols for /boot/kernel/if_em.ko Reading symbols from /boot/kernel/if_wi.ko...done. Loaded symbols for /boot/kernel/if_wi.ko Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/wlan/wlan.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/wlan/wlan.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/rc4/rc4.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/rc4/rc4.ko.debug Reading symbols from /boot/kernel/snd_ich.ko...done. Loaded symbols for /boot/kernel/snd_ich.ko Reading symbols from /boot/kernel/snd_pcm.ko...done. Loaded symbols for /boot/kernel/snd_pcm.ko Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/ums/ums.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/ums/ums.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/---Type to continue, or q to quit--- usb/usb.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/usb/usb.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/umass/umass.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/umass/umass.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/agp/agp.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/agp/agp.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/random/random.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/random/random.ko.debug Reading symbols from /boot/kernel/if_ath.ko...done. Loaded symbols for /boot/kernel/if_ath.ko Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/ath_hal/ath_hal.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/ath_hal/ath_hal.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/smbfs/smbfs.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/smbfs/smbfs.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/libmchain/libmchain.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/libmchain/libmchain.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/libiconv/libiconv.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/libiconv/libiconv.ko.debug Reading symbols from /boot/kernel/radeon.ko...done. Loaded symbols for /boot/kernel/radeon.ko Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/msdosfs/msdosfs.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/msdosfs/msdosfs.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/msdosfs_iconv/msdosfs_iconv.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/msdosfs_iconv/msdosfs_iconv.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/linprocfs/linprocfs.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/linprocfs/linprocfs.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/pseudofs/pseudofs.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/pseudofs/pseudofs.ko.debug Reading symbols from /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/procfs/procfs.ko.debug...done. Loaded symbols for /usr/src/sys/i386/compile/rtfm/modules/usr/src/sys/modules/procfs/procfs.ko.debug #0 doadump () at ../../../kern/kern_shutdown.c:236 236 dumping++; (kgdb) where #0 doadump () at ../../../kern/kern_shutdown.c:236 #1 0xc04c88e7 in boot (howto=260) at ../../../kern/kern_shutdown.c:370 #2 0xc04c8bf9 in __panic () at ../../../kern/kern_shutdown.c:548 #3 0xc0450bdb in db_panic () at ../../../ddb/db_command.c:453 #4 0xc0450b68 in db_command (last_cmdp=0xc061fec0, cmd_table=0xc05fa760, aux_cmd_tablep=0xc05f4db4, aux_cmd_tablep_end=0xc05f4db8) at ../../../ddb/db_command.c:348 #5 0xc0450c48 in db_command_loop () at ../../../ddb/db_command.c:475 #6 0xc04533e5 in db_trap (type=12, code=0) at ../../../ddb/db_trap.c:73 #7 0xc05a9d2d in kdb_trap (type=12, code=0, regs=0xcdce59bc) at ../../../i386/i386/db_interface.c:159 #8 0xc05b8123 in trap_fatal (frame=0xcdce59bc, eva=0) at ../../../i386/i386/trap.c:810 #9 0xc05b7e8f in trap_pfault (frame=0xcdce59bc, usermode=0, eva=0) at ../../../i386/i386/trap.c:733 #10 0xc05b7ac9 in trap (frame= {tf_fs = 24, tf_es = -842137584, tf_ds = -1067909104, tf_edi = -842114540, tf_esi = 0, tf_ebp = -842114552, tf_isp = -842114584, tf_ebx = 0, tf_edx = 19, tf_ecx = 96, tf_eax = -842114540, tf_trapno = 12, tf_err = 0, tf_eip = -1066094835, tf_cs = 8, tf_eflags = 66050, tf_esp = 0, tf_ss = 983056}) at ../../../i386/i386/trap.c:420 #11 0xc074af0d in usb_get_next_event (ue=0xcdce5a14) at /usr/src/sys/dev/usb/usb.c:752 #12 0xc074ab24 in usbread (dev=0xc062632c, uio=0xcdce5c88, flag=983056) at /usr/src/sys/dev/usb/usb.c:510 #13 0xc0490e90 in spec_read (ap=0xcdce5c18) at ../../../fs/specfs/spec_vnops.c:273 #14 0xc04909d7 in spec_vnoperate (ap=0x0) at ../../../fs/specfs/spec_vnops.c:118 #15 0xc052250d in vn_read (fp=0xc2c7d088, uio=0xcdce5c88, active_cred=0xc14f3e00, flags=0, td=0xc2afd930) at vnode_if.h:398 #16 0xc04eac8f in dofileread (td=0xc2afd930, fp=0xc2c7d088, fd=7, buf=0xbfbfeb60, nbyte=0, offset=0, flags=0) at ../../../sys/file.h:233 #17 0xc04eab83 in read (td=0xc2afd930, uap=0xcdce5d14) at ../../../kern/sys_generic.c:107 #18 0xc05b842b in syscall (frame= {tf_fs = 47, tf_es = 47, tf_ds = 47, tf_edi = -1077940696, tf_esi = -1077941416, tf_ebp = -1077941016, tf_isp = -842113676, tf_ebx = 7, tf_edx = 20, tf_ecx = -1077941584, tf_eax = 3, tf_trapno = 12, tf_err = 2, tf_eip = 671899255, tf_cs = 31, tf_eflags = 658, tf_esp = -1077941444, tf_ss = 47}) at ../../../i386/i386/trap.c:1004 #19 0x280c5e77 in ?? () ---Can't read userspace from dump, or kernel process--- (kgdb) set print pretty (kgdb) f 11 #11 0xc074af0d in usb_get_next_event (ue=0xcdce5a14) at /usr/src/sys/dev/usb/usb.c:752 752 *ue = ueq->ue; (kgdb) print ueq $1 = (struct usb_event_q *) 0x0 (kgdb) print ue $2 = (struct usb_event *) 0xcdce5a14 (kgdb)