How to analyze ld at sd mmc on i386 current

[Ryo ONODERA <ryo_on%yk.rim.or.jp@localhost>]

Hi,

I want to analyze my PR kern/46749,
so I am using FFSv2 32GB SDHC card as ld0e at sdmmc.

I suspect functionality of writing to ld at sdmmc is broken,
because newfs generates "cg 0: bad magic number" and
writing to ld at sdmmc causes panic sometime with some SDHC cards.

Also mounting my FAT 16GB micro SDHC card (formatted on Android
phone) with mount_msdos causes freeze.

How to start analyzing?
What kind of information will help debugging?
Is this problem related to userland command?

Thank you.


dmesg of today and typical panic messages are here.

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008, 2009, 2010, 2011, 2012
    The NetBSD Foundation, Inc.  All rights reserved.
Copyright (c) 1982, 1986, 1989, 1991, 1993
    The Regents of the University of California.  All rights reserved.

NetBSD 6.99.10 (GENERIC) #7: Fri Aug  3 02:42:12 JST 2012
        
root%hydrogen.elements.tetera.org@localhost:/usr/obj/sys/arch/i386/compile/GENERIC
total memory = 1013 MB
avail memory = 983 MB
timecounter: Timecounters tick every 10.000 msec
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
FUJITSU FMVLP70WN ( )
mainbus0 (root)
cpu0 at mainbus0 apid 0: Intel(R) Core(TM) Solo CPU     U1400  @ 1.20GHz, id 
0x6ec
ioapic0 at mainbus0 apid 1: pa 0xfec00000, version 20, 24 pins
acpi0 at mainbus0: Intel ACPICA 20110623
acpi0: X/RSDT: OemId <FUJ   ,PC      ,01130000>, AslId <FUJ ,00000100>
acpi0: SCI interrupting at int 9
timecounter: Timecounter "ACPI-Safe" frequency 3579545 Hz quality 900
hpet0 at acpi0: high precision event timer (mem 0xfed00000-0xfed00400)
timecounter: Timecounter "hpet0" frequency 14318180 Hz quality 2000
acpiec0 at acpi0 (EC, PNP0C09): io 0x62,0x66
MCFG (PNP0C02) at acpi0 not configured
MBIO (PNP0C02) at acpi0 not configured
acpivga0 at acpi0 (GFX0): ACPI Display Adapter
acpiout0 at acpivga0 (CRT, 0x0100): ACPI Display Output Device
acpiout1 at acpivga0 (LCD, 0x0110): ACPI Display Output Device
acpiout1: brightness levels: 0 15 29 43 57 71 85 100
acpiout2 at acpivga0 (TV, 0x0200): ACPI Display Output Device
acpiout3 at acpivga0 (DVI, 0x0300): ACPI Display Output Device
acpivga0: connected output devices:
acpivga0:   0x0100 (acpiout0): Ext. Monitor, head 0, bios detect
acpivga0:   0x0110 (acpiout1): LCD Panel, head 0, bios detect
acpivga0:   0x0200 (acpiout2): TV, head 0, bios detect
acpivga0:   0x0300 (acpiout3): Unknown Output Device, head 0, bios detect
DIGI (FUJ02E6) at acpi0 not configured
BTNS (FUJ02BF) at acpi0 not configured
fujbp0 at acpi0 (FJEX, FUJ02B1): Fujitsu Brightness & Pointer
attimer1 at acpi0 (TIME, PNP0100): io 0x40-0x43 irq 0
pcppi1 at acpi0 (SPKR, PNP0800): io 0x61
midi0 at pcppi1: PC speaker
sysbeep0 at pcppi1
npx1 at acpi0 (MATH, PNP0C04): io 0xf0-0xfe irq 13
npx1: reported by CPUID; using exception 16
pckbc1 at acpi0 (KBC, PNP0320) (kbd port): io 0x60,0x64 irq 1
pckbc2 at acpi0 (PS2M, PNP0F13) (aux port): irq 12
fujhk0 at acpi0 (FEXT, FUJ02E3): Fujitsu Hotkeys
acpilid0 at acpi0 (LID, PNP0C0D): ACPI Lid Switch
acpibut0 at acpi0 (PWRB, PNP0C0C): ACPI Power Button
acpiacad0 at acpi0 (AC, ACPI0003): ACPI AC Adapter
acpibat0 at acpi0 (CMB1, PNP0C0A-1): ACPI Battery
acpibat0: Fujitsu LION rechargeable battery
acpibat0: granularity: low->warn 0.001 Ah, warn->full 0.001 Ah
acpitz0 at acpi0 (TZ00): cpu0
acpitz0: levels: critical 100.0 C, passive 95.0 C, passive cooling
acpitz1 at acpi0 (TZ01): cpu0
acpitz1: levels: critical 100.0 C, passive 95.0 C, passive cooling
apm0 at acpi0: Power Management spec V1.2
attimer1: attached to pcppi1
pckbd0 at pckbc1 (kbd slot)
pckbc1: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pms0 at pckbc1 (aux slot)
pckbc1: using irq 12 for aux slot
wsmouse0 at pms0 mux 0
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0: vendor 0x8086 product 0x27a0 (rev. 0x03)
agp0 at pchb0: detected 7932k stolen memory
agp0: aperture at 0xe0000000, size 0x10000000
vga1 at pci0 dev 2 function 0: vendor 0x8086 product 0x27a2 (rev. 0x03)
wsdisplay0 at vga1 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
wsmux1: connecting to wsdisplay0
i915drm0 at vga1: Intel i945GM
i915drm0: AGP at 0xe0000000 256MB
i915drm0: Initialized i915 1.6.0 20080730
vendor 0x8086 product 0x27a6 (miscellaneous display, revision 0x03) at pci0 dev 
2 function 1 not configured
hdaudio0 at pci0 dev 27 function 0: HD Audio Controller
hdaudio0: interrupting at ioapic0 pin 17
hdafg0 at hdaudio0: Sigmatel STAC9228X
hdafg0: DAC00 2ch: Speaker [Built-In]
hdafg0: ADC01 2ch: Mic In [Built-In]
hdafg0: ADC02 2ch: Mic In [Jack]
hdafg0: DAC03 2ch: HP Out [Jack]
hdafg0: 2ch/2ch 44100Hz 48000Hz 88200Hz 96000Hz 192000Hz PCM16 PCM20 PCM24 AC3
audio0 at hdafg0: full duplex, playback, capture, independent
hdvsmfg at hdaudio0 not configured
ppb0 at pci0 dev 28 function 0: vendor 0x8086 product 0x27d0 (rev. 0x02)
ppb0: PCI Express 1.0 <Root Port of PCI-E Root Complex>
pci1 at ppb0 bus 2
pci1: i/o space, memory space enabled, rd/line, wr/inv ok
mskc0 at pci1 dev 0 function 0, Yukon-2 EC Ultra rev. A1 (0x2): ioapic0 pin 16
msk0 at mskc0 port A: Ethernet address 00:17:42:3d:72:02
ukphy0 at msk0 phy 0: OUI 0x000ac2, model 0x000b, rev. 1
ukphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 
1000baseT-FDX, auto
ppb1 at pci0 dev 28 function 2: vendor 0x8086 product 0x27d4 (rev. 0x02)
ppb1: PCI Express 1.0 <Root Port of PCI-E Root Complex>
pci2 at ppb1 bus 5
pci2: i/o space, memory space enabled, rd/line, wr/inv ok
wpi0 at pci2 dev 0 function 0: vendor 0x8086 product 0x4222 (rev. 0x02)
wpi0: interrupting at ioapic0 pin 18
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: M^?M^?M^?M^?wpi0: could not lock memory
, address ff:ff:ff:ff:ff:ff
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: could not lock memory
wpi0: 11a rates: 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
wpi0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
wpi0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 
36Mbps 48Mbps 54Mbps
uhci0 at pci0 dev 29 function 0: vendor 0x8086 product 0x27c8 (rev. 0x02)
uhci0: interrupting at ioapic0 pin 23
usb0 at uhci0: USB revision 1.0
uhci1 at pci0 dev 29 function 1: vendor 0x8086 product 0x27c9 (rev. 0x02)
uhci1: interrupting at ioapic0 pin 20
usb1 at uhci1: USB revision 1.0
uhci2 at pci0 dev 29 function 2: vendor 0x8086 product 0x27ca (rev. 0x02)
uhci2: interrupting at ioapic0 pin 18
usb2 at uhci2: USB revision 1.0
uhci3 at pci0 dev 29 function 3: vendor 0x8086 product 0x27cb (rev. 0x02)
uhci3: interrupting at ioapic0 pin 16
usb3 at uhci3: USB revision 1.0
ehci0 at pci0 dev 29 function 7: vendor 0x8086 product 0x27cc (rev. 0x02)
ehci0: interrupting at ioapic0 pin 23
ehci0: EHCI version 1.0
ehci0: companion controllers, 2 ports each: uhci0 uhci1 uhci2 uhci3
usb4 at ehci0: USB revision 2.0
ppb2 at pci0 dev 30 function 0: vendor 0x8086 product 0x2448 (rev. 0xe2)
pci3 at ppb2 bus 8
pci3: i/o space, memory space enabled
cbb0 at pci3 dev 3 function 0: vendor 0x1180 product 0x0476 (rev. 0x8d)
sdhc0 at pci3 dev 3 function 1: vendor 0x1180 product 0x0822 (rev. 0x13)
sdhc0: interrupting at ioapic0 pin 17
sdhc0: SD Host Specification 1.0, rev.2
sdhc0: using DMA transfer
sdmmc0 at sdhc0 slot 0
cbb0: cacheline 0x0 lattimer 0x40
cbb0: bhlc 0x824000
cbb0: interrupting at ioapic0 pin 16
cardslot0 at cbb0
cardbus0 at cardslot0: bus 9
pcmcia0 at cardslot0
ichlpcib0 at pci0 dev 31 function 0: vendor 0x8086 product 0x27b9 (rev. 0x02)
timecounter: Timecounter "ichlpcib0" frequency 3579545 Hz quality 1000
ichlpcib0: 24-bit timer
ichlpcib0: TCO (watchdog) timer configured.
gpio0 at ichlpcib0: 64 pins
piixide0 at pci0 dev 31 function 1: Intel 82801GB/GR IDE Controller (ICH7) 
(rev. 0x02)
piixide0: bus-master DMA support present
piixide0: primary channel configured to compatibility mode
piixide0: primary channel interrupting at ioapic0 pin 14
atabus0 at piixide0 channel 0
piixide0: secondary channel configured to compatibility mode
piixide0: secondary channel ignored (disabled)
ichsmb0 at pci0 dev 31 function 3: vendor 0x8086 product 0x27da (rev. 0x02)
ichsmb0: interrupting at ioapic0 pin 19
iic0 at ichsmb0: I2C bus
isa0 at ichlpcib0
acpicpu0 at cpu0: ACPI CPU
acpicpu0: C1: FFH, lat   1 us, pow  1000 mW
acpicpu0: C2: I/O, lat   1 us, pow   500 mW
acpicpu0: C3: I/O, lat  17 us, pow   100 mW
acpicpu0: P0: FFH, lat  10 us, pow 31000 mW, 1200 MHz
acpicpu0: P1: FFH, lat  10 us, pow 13000 mW,  800 MHz
coretemp0 at cpu0: thermal sensor, 1 C resolution
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
timecounter: Timecounter "TSC" frequency 1197128160 Hz quality 3000
acpiacad0: AC adapter online.
uhub0 at usb0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1 at usb1: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhub2 at usb2: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhub3 at usb3: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
uhub4 at usb4: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
ld0 at sdmmc0: <SDC  >
ld0: 30959 MB, 7862 cyl, 128 head, 63 sec, 512 bytes/sect x 63404032 sectors
ld0: 4-bit width, bus clock 25.000 MHz
bwi0 at cardbus0 function 0: Broadcom Wireless
bwi0: BBP id 0x4306, BBP rev 0x3, BBP pkg 0
bwi0: MAC: rev 5
bwi0: PHY type 2, rev 2, ver 2
bwi0: RF manu 0x17f, type 0x2050, rev 2
bwi0: invalid antenna gain in sprom
bwi0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
bwi0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 
36Mbps 48Mbps 54Mbps
ehci0: handing over full speed device on port 5 to uhci2
wd0 at atabus0 drive 0
wd0: <TOSHIBA MK6006GAH>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 57231 MB, 116280 cyl, 16 head, 63 sec, 512 bytes/sect x 117210240 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd0(piixide0:0:0): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA)
Kernelized RAIDframe activated
ugen0 at uhub2 port 1
ugen0: vendor 0x08ff Fingerprint Sensor, rev 1.10/6.21, addr 2
boot device: wd0
root on wd0a dumps on wd0b
/: replaying log to memory
root file system type: ffs
/: replaying log to disk
/usr: replaying log to disk
wsdisplay0: screen 1 added (80x25, vt100 emulation)
wsdisplay0: screen 2 added (80x25, vt100 emulation)
wsdisplay0: screen 3 added (80x25, vt100 emulation)
wsdisplay0: screen 4 added (80x25, vt100 emulation)
/home: replaying log to disk
tap0: Ethernet address f2:0b:a4:08:07:0c
i915drm0: interrupting at ioapic0 pin 16



% crash -M netbsd.18.core -N netbsd.18
Crash version 6.99.10, image version 6.99.10.
System panicked: lock error
Backtrace from time of crash is available.
crash> tr
_KERNEL_OPT_NAPMBIOS(c0c485a1,104,c05ed378,8,5,0,0,daf6b378,61353263,0) at 0
_end(104,0,ffec,c0c60d67,c07f24a5,1,0,c0ce1b04,c2812838,c25a07e4) at daf6b3d8
vpanic(c0c485a1,daf6b3d8,4,c057b1ce,c210e000,60,daf6b3fc,c07eb3de,c0c485a1,c0c0e
14f) at vpanic+0x1cf
printf_nolog(c0c485a1,c0c0e14f,c0b566f5,c0c0c81f,c2812838,0,c25a07e0,c08e56e2,c2
5a07e0,0) at printf_nolog
lockdebug_abort(c2812838,c0ce1b04,c0b566f5,c0c0c81f,c210cd00,c2812838,daf6b4ac,c
058a9b9,c0c87640,c247e020) at lockdebug_abort+0x2b
rw_abort(c0c87640,c247e020,daf6b44c,c07ebb9c,c206d160,c25a09b4,0,c057528d,c0d247
80,3) at rw_abort+0x29
rw_vector_enter(c2812838,1,1,0,0,1,daf6b4fc,c0806c40,c259acc0,ffffffff) at rw_ve
ctor_enter+0x570
genfs_lock(daf6b518,a,daf6b52c,c0807041,c0d5d53c,c2817aac,daf6b52c,c07ebb9c,c206
d160,c0ba5ad4) at genfs_lock+0xa9
VOP_LOCK(c2812794,2,daf6b59c,c0993f5a,c2817aac,0,daf6b56c,c09024eb,c2817aac,0) a
t VOP_LOCK+0x2c
vn_lock(c2812794,2,c0c617b1,0,2,0,daf6b62c,c03025b3,c2817aac,0) at vn_lock+0xe0
vget(c2812794,2,1,5980,db0a00a8,c2812794,1306,0,0,c24ff928) at vget+0xe2
ufs_ihashget(1304,0,2,0,2,daf6b6cc,daf6b65c,0,c2812794,c28106c4) at ufs_ihashget
+0x9a
ffs_vget(c2819000,2,0,daf6b86c,c0301e5d,4000,daf6b6ec,c24ff8d8,c2549000,c28106c4
) at ffs_vget+0x103
ffs_valloc(c2812794,8000,ffffffff,daf6b86c,c247e020,c210cd00,daf6b77c,c059218b,c
0c87640,c247e020) at ffs_valloc+0x232
wapbl_log_position(daf6b8fc,daf6b910,daf6b90c,daf6b8f4,c2819044,0,daf6b8dc,c0993
f0e,4946ade,0) at wapbl_log_position+0x3e3
ffs_wapbl_start(c2819000,c2819044,a8,1000,c2107f00,0,daf6b9ac,c0575472,0,c25a09b
4) at ffs_wapbl_start+0xc2
ffs_mountfs(c25a258c,c2819000,c25a07e0,c2819000,c25a258c,6,0,c090a700,c281902c,0
) at ffs_mountfs+0xbf2
ffs_mount(c2819000,bfbfe9d8,c205b590,daf6bca0,c2396f10,0,daf6bbdc,c090ba7e,c2819
000,bfbfe9d8) at ffs_mount+0x211
VFS_MOUNT(c2819000,bfbfe9d8,c205b590,daf6bca0,2000000,c205b590,0,fffffffe,0,0) a
t VFS_MOUNT+0x34
mount_domount(c25a07e0,daf6bc3c,c0c89ec0,bfbfe9d8,2000000,c205b590,daf6bca0,c254
4405,7,86a29d38) at mount_domount+0x11c
do_sys_mount(c25a07e0,0,8048ea8,bfbfe9d8,2000000,bfbfeddc,0,4,daf6bd1c,0) at do_
sys_mount+0x238
sys___mount50(c25a07e0,daf6bcf4,daf6bd1c,c2800bd4,0,bbb1dba3,bbb1d000,c24c26a0,0
,19a) at sys___mount50+0x4d
syscall() at syscall+0x89
--- syscall (number 410) ---
bbb04b57:
crash>

--
Ryo ONODERA // ryo_on%yk.rim.or.jp@localhost
PGP fingerprint = 82A2 DC91 76E0 A10A 8ABB  FD1B F404 27FA C7D1 15F3