kern/87861: "panic: initiate_write_inodeblock_ufs2: already started" on 6.0-RC1

Frank Mayhar frank at exit.com
Sat Oct 22 23:10:15 PDT 2005 

>Number:         87861
>Category:       kern
>Synopsis:       "panic: initiate_write_inodeblock_ufs2: already started" on 6.0-RC1
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Sun Oct 23 06:10:13 GMT 2005
>Closed-Date:
>Last-Modified:
>Originator:     Frank Mayhar
>Release:        FreeBSD 6.0-RC1 i386
>Organization:
Exit Consulting 
>Environment:


FreeBSD jill.exit.com 6.0-RC1 FreeBSD 6.0-RC1 #2: Sat Oct 22 20:42:16 PDT 2005     frank at jill.exit.com:/usr/obj/usr/src/sys/JILL  i386



>Description:


I installed an Intel SRCU42L RAID controller today.  I also upgraded the system to 6.0-RC1 after running into the same problem in 5.4-stable.  The running system is up-to-the-minute, build today after a fresh update.

The upshot is that I built a RAID-5 array, created a file system and proceeded to fill it with the stuff I planned to move onto it.  After a very short time (like, less than a minute), I see the following:

g_vfs_done():da6s1e[WRITE(offset=982941696, length=131072)]error = 16
(A lot of these, at various offsets and of various lengths.)
g_vfs_done():da6s1e[WRITE(offset=972455936, length=81920)]error = 16
g_vfs_done():da6s1e[WRITE(offset=972587008, length=32768)]error = 16
panic: initiate_write_inodeblock_ufs2: already started
cpuid = 1
Uptime: 6m0s
Dumping 1535 MB (3 chunks)
  chunk 0: 1MB (158 pages) ... ok
  chunk 1: 1534MB (392688 pages) 1518 1502 1486 1470 1454 1438 1422 1406 1390 1374 1358 1342 1326 1310 1294 1278 1262 1246 1230 1214 1198 1182 1166 1150 1134 1118 1102 1086 1070 1054 1038 1022 1006 990 974 958 942 926 910 894 878 862 846 830 814 798 782 766 750 734 718 702 686 670 654 638 622 606 590 574 558 542 526 510 494 478 462 446 430 414 398 382 366 350 334 318 302 286 270 254 238 222 206 190 174 158 142 126 110 94 78 62 46 30 14 ... ok
  chunk 2: 1MB (128 pages) ... ok

Dump complete
iir0: Flushing all Host Drives. Please wait ...  g_vfs_done():da6s1e[WRITE(offset=970031104, length=10240)]error = 16
g_vfs_done():da6s1e[WRITE(offset=970072064, length=8192)]error = 16

I saved the corefile.  The traceback is

(kgdb) bt
#0  doadump () at pcpu.h:165
#1  0xc04f4373 in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:399
#2  0xc04f46c9 in panic (
    fmt=0xc066f652 "initiate_write_inodeblock_ufs2: already started")
    at /usr/src/sys/kern/kern_shutdown.c:555
#3  0xc05ce986 in initiate_write_inodeblock_ufs2 (inodedep=0xc360e500, bp=0x0)
    at /usr/src/sys/ufs/ffs/ffs_softdep.c:3865
#4  0xc05ce187 in softdep_disk_io_initiation (bp=0xd6ca5eb0)
    at /usr/src/sys/ufs/ffs/ffs_softdep.c:3600
#5  0xc05d600e in ffs_geom_strategy (bo=0xc309e2e0, bp=0xd6ca5eb0) at buf.h:422
#6  0xc053acdc in bufwrite (bp=0xd6ca5eb0) at buf.h:415
#7  0xc05d5fce in ffs_bufwrite (bp=0xd6ca5eb0)
    at /usr/src/sys/ufs/ffs/ffs_vfsops.c:1663
#8  0xc053c707 in vfs_bio_awrite (bp=0xd6ca5eb0) at buf.h:399
#9  0xc054387c in vop_stdfsync (ap=0xe718bcc0)
    at /usr/src/sys/kern/vfs_default.c:417
#10 0xc04a73e7 in devfs_fsync (ap=0xe718bcc0)
    at /usr/src/sys/fs/devfs/devfs_vnops.c:307
#11 0xc0644134 in VOP_FSYNC_APV (vop=0x0, a=0x0) at vnode_if.c:1020
#12 0xc054b6bf in sync_vnode (bo=0xc309e2e0, td=0xc2ca6900) at vnode_if.h:537
#13 0xc054b9dd in sched_sync () at /usr/src/sys/kern/vfs_subr.c:1664
#14 0xc04de109 in fork_exit (callout=0xc054b784 <sched_sync>, arg=0x0, 
    frame=0xe718bd38) at /usr/src/sys/kern/kern_fork.c:789
#15 0xc0627c1c in fork_trampoline () at /usr/src/sys/i386/i386/exception.s:208

I'll keep the vmcore around for as long as possible; let me know if you want more information from it.  Note that this _only_ seems to happen on the RAID device, not on any of the other SCSI drives.

Here's the system dmesg, just for grins:
Copyright (c) 1992-2005 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
        The Regents of the University of California. All rights reserved.
FreeBSD 6.0-RC1 #2: Sat Oct 22 20:42:16 PDT 2005
    frank at jill.exit.com:/usr/obj/usr/src/sys/JILL
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: AMD Athlon(tm) MP 2800+ (2133.43-MHz 686-class CPU)
  Origin = "AuthenticAMD"  Id = 0x6a0  Stepping = 0
  Features=0x383fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE>
  AMD Features=0xc0480800<SYSCALL,MP,MMX+,3DNow+,3DNow>
real memory  = 1610088448 (1535 MB)
avail memory = 1568432128 (1495 MB)
ACPI APIC Table: <PTLTD          APIC  >
FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
 cpu0 (BSP): APIC ID:  1
 cpu1 (AP): APIC ID:  0
MADT: Forcing active-low polarity and level trigger for SCI
ioapic0 <Version 1.1> irqs 0-23 on motherboard
npx0: [FAST]
npx0: <math processor> on motherboard
npx0: INT 16 interface
acpi0: <PTLTD   RSDT> on motherboard
acpi0: Power Button (fixed)
acpi0: Sleep Button (fixed)
pci_link0: <ACPI PCI Link LNKA> irq 11 on acpi0
pci_link1: <ACPI PCI Link LNKB> irq 5 on acpi0
pci_link2: <ACPI PCI Link LNKC> irq 9 on acpi0
pci_link3: <ACPI PCI Link LNKD> irq 10 on acpi0
Timecounter "ACPI-safe" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x8008-0x800b on acpi0
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
acpi_button0: <Power Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff,0x8000-0x807f,0x8080-0x80ff iomem 0xd8000-0xdbfff on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <ACPI PCI-PCI bridge> at device 1.0 on pci0
pci1: <ACPI PCI bus> on pcib1
isab0: <PCI-ISA bridge> at device 7.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <AMD 768 UDMA100 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xf000-0xf00f at device 7.1 on pci0
ata0: <ATA channel 0> on atapci0
ata1: <ATA channel 1> on atapci0
pci0: <bridge> at device 7.3 (no driver attached)
iir0: <Intel Integrated RAID Controller> mem 0xf6200000-0xf6203fff irq 20 at device 8.0 on pci0
iir0: [GIANT-LOCKED]
em0: <Intel(R) PRO/1000 Network Connection, Version - 2.1.7> port 0x1000-0x103f mem 0xf4080000-0xf409ffff,0xf4000000-0xf403ffff irq 21 at device 9.0 on pci0
em0: Ethernet address: 00:04:23:a8:b2:24
em0:  Speed:N/A  Duplex:N/A
em1: <Intel(R) PRO/1000 Network Connection, Version - 2.1.7> port 0x1040-0x107f mem 0xf40a0000-0xf40bffff,0xf4040000-0xf407ffff irq 22 at device 9.1 on pci0
em1: Ethernet address: 00:04:23:a8:b2:25
em1:  Speed:N/A  Duplex:N/A
em2: <Intel(R) PRO/1000 Network Connection, Version - 2.1.7> port 0x1080-0x10bf mem 0xf40c0000-0xf40dffff irq 23 at device 11.0 on pci0
em2: Ethernet address: 00:e0:81:2b:ac:bc
em2:  Speed:N/A  Duplex:N/A
pcib2: <ACPI PCI-PCI bridge> at device 16.0 on pci0
pci2: <ACPI PCI bus> on pcib2
ohci0: <OHCI (generic) USB controller> mem 0xf4102000-0xf4102fff irq 19 at device 0.0 on pci2
ohci0: [GIANT-LOCKED]
usb0: OHCI version 1.0, legacy support
usb0: SMM does not respond, resetting
usb0: <OHCI (generic) USB controller> on ohci0
usb0: USB revision 1.0
uhub0: AMD OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 4 ports with 4 removable, self powered
ohci1: <NEC uPD 9210 USB controller> mem 0xf4103000-0xf4103fff irq 16 at device 4.0 on pci2
ohci1: [GIANT-LOCKED]
usb1: OHCI version 1.0
usb1: <NEC uPD 9210 USB controller> on ohci1
usb1: USB revision 1.0
uhub1: NEC OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 3 ports with 3 removable, self powered
ohci2: <NEC uPD 9210 USB controller> mem 0xf4104000-0xf4104fff irq 17 at device 4.1 on pci2
ohci2: [GIANT-LOCKED]
usb2: OHCI version 1.0
usb2: <NEC uPD 9210 USB controller> on ohci2
usb2: USB revision 1.0
uhub2: NEC OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
ehci0: <NEC uPD 720100 USB 2.0 controller> mem 0xf4107000-0xf41070ff irq 18 at device 4.2 on pci2
ehci0: [GIANT-LOCKED]
usb3: EHCI version 0.95
usb3: companion controllers, 3 ports each: usb1 usb2
usb3: <NEC uPD 720100 USB 2.0 controller> on ehci0
usb3: USB revision 2.0
uhub3: NEC EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub3: 5 ports with 5 removable, self powered
uhub4: vendor 0x050d product 0x0234, class 9/0, rev 2.00/1.00, addr 2
uhub4: single transaction translator
uhub4: 4 ports with 4 removable, self powered
sym0: <1010-66> port 0x2000-0x20ff mem 0xf4107400-0xf41077ff,0xf4100000-0xf4101fff irq 17 at device 5.0 on pci2
sym0: Symbios NVRAM, ID 7, Fast-80, LVD, parity checking
sym0: open drain IRQ line driver, using on-chip SRAM
sym0: using LOAD/STORE-based firmware.
sym0: handling phase mismatch from SCRIPTS.
sym0: [GIANT-LOCKED]
pci2: <display, VGA> at device 7.0 (no driver attached)
fxp0: <Intel 82551 Pro/100 Ethernet> port 0x2800-0x283f mem 0xf4106000-0xf4106fff,0xf4120000-0xf413ffff irq 18 at device 8.0 on pci2
miibus0: <MII bus> on fxp0
inphy0: <i82555 10/100 media interface> on miibus0
inphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
fxp0: Ethernet address: 00:e0:81:2b:ac:bd
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: model VersaPad, device ID 0
sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
sio0: type 16550A, console
sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0
sio1: type 16550A
ppc0: <ECP parallel printer port> port 0x378-0x37f,0x778-0x77f irq 7 drq 3 on acpi0
ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/9 bytes threshold
ppbus0: <Parallel port bus> on ppc0
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
fdc0: [FAST]
orm0: <ISA Option ROMs> at iomem 0xc0000-0xc7fff,0xc8000-0xc97ff,0xcf000-0xd2fff,0xe0000-0xe3fff on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x100>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
uhub1: device problem (SET_ADDR_FAILED), disabling port 2
uhub2: device problem (SET_ADDR_FAILED), disabling port 1
Timecounters tick every 1.000 msec
Waiting 10 seconds for SCSI devices to settle
(noperiph:sym0:0:-1:-1): SCSI BUS reset delivered.
(probe7:sym0:0:8:0): M_REJECT to send for : 1-6-4-a-0-3e-1-0.
ses0 at iir0 bus 0 target 15 lun 0
ses0: <Dell 8 BAY U2W CU 0205> Removable Processor SCSI-3 device 
ses0: SAF-TE Compliant Device
ses1 at iir0 bus 1 target 15 lun 0
ses1: <Dell 12 BAY U2W CU 0209> Removable Processor SCSI-3 device 
ses1: SAF-TE Compliant Device
pt0 at iir0 bus 0 target 15 lun 0
pt0: <Dell 8 BAY U2W CU 0205> Removable Processor SCSI-3 device 
pt1 at iir0 bus 1 target 15 lun 0
pt1: <Dell 12 BAY U2W CU 0209> Removable Processor SCSI-3 device 
da4 at iir0 bus 2 target 0 lun 0
da4: <Intel Host Drive   #00 > Fixed Direct Access SCSI-2 device 
da4: Tagged Queueing Enabled
da4: 208084MB (426156255 512 byte sectors: 255H 63S/T 26527C)
da5 at iir0 bus 2 target 8 lun 0
da5: <Intel Host Drive   #08 > Fixed Direct Access SCSI-2 device 
da5: Tagged Queueing Enabled
da5: 139878MB (286471080 512 byte sectors: 255H 63S/T 17832C)
da6 at iir0 bus 2 target 14 lun 0
da6: <Intel Host Drive   #14 > Fixed Direct Access SCSI-2 device 
da6: Tagged Queueing Enabled
da6: 139878MB (286471080 512 byte sectors: 255H 63S/T 17832C)
da0 at sym0 bus 0 target 0 lun 0
da0: <QUANTUM ATLAS_V_36_WLS 0230> Fixed Direct Access SCSI-3 device 
da0: 160.000MB/s transfers (80.000MHz, offset 62, 16bit), Tagged Queueing Enabled
da0: 35020MB (71722776 512 byte sectors: 255H 63S/T 4464C)
da1 at sym0 bus 0 target 1 lun 0
da1: <HITACHI DK32DJ-72MC A9A9> Fixed Direct Access SCSI-3 device 
da1: 160.000MB/s transfers (80.000MHz, offset 62, 16bit), Tagged Queueing Enabled
da1: 70513MB (144410880 512 byte sectors: 255H 63S/T 8989C)
SMP: AP CPU #1 Launched!
da3 at sym0 bus 0 target 10 lun 0
da3: <QUANTUM ATLAS10K3_18_SCA 020K> Fixed Direct Access SCSI-3 device 
da3: 160.000MB/s transfers (80.000MHz, offset 62, 16bit), Tagged Queueing Enabled
da3: 17537MB (35916548 512 byte sectors: 255H 63S/T 2235C)
da2 at sym0 bus 0 target 8 lun 0
da2: <SEAGATE SX173404LC BD0A> Fixed Direct Access SCSI-3 device 
da2: 80.000MB/s transfers (40.000MHz, offset 31, 16bit), Tagged Queueing Enabled
da2: 70007MB (143374738 512 byte sectors: 255H 63S/T 8924C)
GEOM_LABEL: Label for provider da3s1 is ext2fs//usr/local.
Trying to mount root from ufs:/dev/da0s1a
WARNING: / was not properly dismounted
WARNING: /amanda was not properly dismounted
WARNING: /spare was not properly dismounted
WARNING: /usr was not properly dismounted
WARNING: /usr/local was not properly dismounted
WARNING: /var was not properly dismounted
WARNING: /var/amanda was not properly dismounted
WARNING: /var/spool was not properly dismounted
WARNING: /usr/obj was not properly dismounted
WARNING: /usr/ports was not properly dismounted
WARNING: /usr/src was not properly dismounted
WARNING: /cvs was not properly dismounted
em1: link state changed to UP



>How-To-Repeat:


See above.


>Fix:





>Release-Note:
>Audit-Trail:
>Unformatted:

More information about the freebsd-bugs mailing list