Date: Sun, 6 Jun 2004 14:13:05 +0800 (CST) From: Tai-hwa Liang <avatar@mmlab.cse.yzu.edu.tw> To: Don Lewis <truckman@FreeBSD.org> Cc: dl@leo.org Subject: Re: LOR No 9 and strange other kernel messages Message-ID: <0406061343047.77519@www.mmlab.cse.yzu.edu.tw> In-Reply-To: <200406052132.i55LVwka006489@gw.catspoiler.org> References: <200406052132.i55LVwka006489@gw.catspoiler.org>
next in thread | previous in thread | raw e-mail | index | archive | help
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 <return> to continue, or q <return> 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)
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?0406061343047.77519>