Tim Chase
2009-Mar-19 06:09 UTC
in recent 7-STABLE: VOP_WRITE...is not exclusive locked but should be
Hello,
I have a system that had been running quite well with an oldish 7-STABLE
(from around August 7, 2008) but has started deadlocking within the past
week or so.
I updated the kernel to a newer 7-STABLE (Mar 15, 2009) and enabled
INVARIANTS, INVARIANT_SUPPORT, WITNESS, DEBUG_LOCKS DEBUG_VFS_LOCKS and
DIAGNOSTIC and the message indicated in the subject line has now appeared
3 times as shown below. Is this something to be terribly concerned about?
Is there anything I can to to further track down the cause? Since the
system is a production mail server, I have it set to not drop into DDB
when this happens.
The machine is a 4-core Xeon X5450 with 8G of RAM running FreeBSD
amd64 and in userland it's pretty much just cyrus imapd and apache/php.
The file systems are all ZFS on a bunch of SAS drives connected to a
LSI Logic 1068 controller.
As to the deadlock that started this exercise, if the machine follows its
recent pattern, that should happen within the next 2-4 hours.
Thanks,
Tim
-- kernel messages and dmesg.boot below --
Mar 18 14:46:56 xx kernel: KDB: stack backtrace:
Mar 18 14:46:56 xx kernel: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
Mar 18 14:46:56 xx kernel: vfs_badlock() at vfs_badlock+0x95
Mar 18 14:46:56 xx kernel: assert_vop_elocked() at assert_vop_elocked+0x64
Mar 18 14:46:56 xx kernel: VOP_WRITE_APV() at VOP_WRITE_APV+0x155
Mar 18 14:46:56 xx kernel: vn_write() at vn_write+0x1ce
Mar 18 14:46:56 xx kernel: dofilewrite() at dofilewrite+0x85
Mar 18 14:46:56 xx kernel: kern_writev() at kern_writev+0x4c
Mar 18 14:46:56 xx kernel: write() at write+0x54
Mar 18 14:46:56 xx kernel: syscall() at syscall+0x1f6
Mar 18 14:46:56 xx kernel: Xfast_syscall() at Xfast_syscall+0xab
Mar 18 14:46:56 xx kernel: --- syscall (4, FreeBSD ELF64, write), rip =
0x8015aad3c, rsp = 0x7fffffffa658,rbp = 0x803df2fa0 ---
Mar 18 23:56:45 xx kernel: KDB: stack backtrace:
Mar 18 23:56:45 xx kernel: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
Mar 18 23:56:45 xx kernel: vfs_badlock() at vfs_badlock+0x95
Mar 18 23:56:45 xx kernel: assert_vop_elocked() at assert_vop_elocked+0x64
Mar 18 23:56:45 xx kernel: VOP_WRITE_APV() at VOP_WRITE_APV+0x155
Mar 18 23:56:45 xx kernel: vn_write() at vn_write+0x1ce
Mar 18 23:56:45 xx kernel: dofilewrite() at dofilewrite+0x85
Mar 18 23:56:45 xx kernel: kern_writev() at kern_writev+0x4c
Mar 18 23:56:45 xx kernel: write() at write+0x54
Mar 18 23:56:45 xx kernel: syscall() at syscall+0x1f6
Mar 18 23:56:45 xx kernel: Xfast_syscall() at Xfast_syscall+0xab
Mar 18 23:56:45 xx kernel: --- syscall (4, FreeBSD ELF64, write), rip =
0x8015aad3c, rsp = 0x7fffffffa658,rbp = 0x803e1427c ---
Mar 18 23:56:45 xx kernel: VOP_WRITE: 0xffffff0106e9c290 is not exclusive locked
but should be
Mar 18 23:56:58 xx kernel: KDB: stack backtrace:
Mar 18 23:56:58 xx kernel: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
Mar 18 23:56:58 xx kernel: vfs_badlock() at vfs_badlock+0x95
Mar 18 23:56:58 xx kernel: assert_vop_elocked() at assert_vop_elocked+0x64
Mar 18 23:56:58 xx kernel: VOP_WRITE_APV() at VOP_WRITE_APV+0x155
Mar 18 23:56:58 xx kernel: vn_write() at vn_write+0x1ce
Mar 18 23:56:58 xx kernel: dofilewrite() at dofilewrite+0x85
Mar 18 23:56:58 xx kernel: kern_writev() at kern_writev+0x4c
Mar 18 23:56:58 xx kernel: write() at write+0x54
Mar 18 23:56:58 xx kernel: syscall() at syscall+0x1f6
Mar 18 23:56:58 xx kernel: Xfast_syscall() at Xfast_syscall+0xab
Mar 18 23:56:58 xx kernel: --- syscall (4, FreeBSD ELF64, write), rip =
0x8015aad3c, rsp = 0x7fffffffa658,rbp = 0x803e1740c ---
Mar 18 23:56:58 xx kernel: VOP_WRITE: 0xffffff0106e9c290 is not exclusive locked
but should be
Copyright (c) 1992-2009 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 is a registered trademark of The FreeBSD Foundation.
FreeBSD 7.1-STABLE #1: Sun Mar 15 12:20:02 CDT 2009
root@xx:/root/stable7-working/src/sys/amd64/compile/SWMAIL
WARNING: WITNESS option enabled, expect reduced performance.
WARNING: DIAGNOSTIC option enabled, expect reduced performance.
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: Intel(R) Xeon(R) CPU X5450 @ 3.00GHz (2992.52-MHz K8-class CPU)
Origin = "GenuineIntel" Id = 0x10676 Stepping = 6
Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Features2=0xce3bd<SSE3,RSVD2,MON,DS_CPL,VMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,DCA,<b19>>
AMD Features=0x20100800<SYSCALL,NX,LM>
AMD Features2=0x1<LAHF>
Cores per package: 4
usable memory = 8580468736 (8182 MB)
avail memory = 8283054080 (7899 MB)
ACPI APIC Table: <042908 APIC1058>
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
cpu0 (BSP): APIC ID: 0
cpu1 (AP): APIC ID: 1
cpu2 (AP): APIC ID: 2
cpu3 (AP): APIC ID: 3
WITNESS: spin lock cpuset not in order list
This module (opensolaris) contains code covered by the
Common Development and Distribution License (CDDL)
see http://opensolaris.org/os/licensing/opensolaris_license/
WITNESS: spin lock intrcnt not in order list
ioapic0 <Version 2.0> irqs 0-23 on motherboard
ioapic1 <Version 2.0> irqs 24-47 on motherboard
ioapic2 <Version 2.0> irqs 48-71 on motherboard
kbd1 at kbdmux0
acpi0: <042908 XSDT1058> on motherboard
acpi0: [ITHREAD]
acpi0: Power Button (fixed)
acpi0: reservation of fed1c000, 4000 (3) failed
acpi0: reservation of fed20000, 25000 (3) failed
acpi0: reservation of fed45000, 5b000 (3) failed
acpi0: reservation of feda0000, 20000 (3) failed
acpi0: reservation of fec01000, 7f000 (3) failed
acpi0: reservation of fec80000, 6000 (3) failed
acpi0: reservation of fec86000, a000 (3) failed
acpi0: reservation of ff000000, 400000 (3) failed
acpi0: reservation of ff400000, 400000 (3) failed
acpi0: reservation of ff800000, 400000 (3) failed
acpi0: reservation of ffc00000, 400000 (3) failed
acpi0: reservation of fec00000, 1000 (3) failed
acpi0: reservation of fee00000, 1000 (3) failed
acpi0: reservation of 0, a0000 (3) failed
acpi0: reservation of 100000, dff00000 (3) failed
Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0
acpi_hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on
acpi0
Timecounter "HPET" frequency 14318180 Hz quality 900
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <ACPI PCI-PCI bridge> irq 48 at device 1.0 on pci0
pci11: <ACPI PCI bus> on pcib1
pcib2: <ACPI PCI-PCI bridge> irq 52 at device 5.0 on pci0
pci10: <ACPI PCI bus> on pcib2
pcib3: <ACPI PCI-PCI bridge> irq 56 at device 9.0 on pci0
pci5: <ACPI PCI bus> on pcib3
pcib4: <ACPI PCI-PCI bridge> irq 16 at device 0.0 on pci5
pci7: <ACPI PCI bus> on pcib4
pcib5: <ACPI PCI-PCI bridge> at device 0.0 on pci7
pci9: <ACPI PCI bus> on pcib5
pcib6: <ACPI PCI-PCI bridge> at device 2.0 on pci7
pci8: <ACPI PCI bus> on pcib6
em0: <Intel(R) PRO/1000 Network Connection 6.9.6> port 0xe880-0xe89f mem
0xfdfa0000-0xfdfbffff irq 18 at device 0.0 on pci8
em0: Using MSI interrupt
em0: [FILTER]
em0: Ethernet address: 00:22:15:88:38:fc
em1: <Intel(R) PRO/1000 Network Connection 6.9.6> port 0xec00-0xec1f mem
0xfdfe0000-0xfdffffff irq 19 at device 0.1 on pci8
em1: Using MSI interrupt
em1: [FILTER]
em1: Ethernet address: 00:22:15:88:38:fd
pcib7: <ACPI PCI-PCI bridge> at device 0.3 on pci5
pci6: <ACPI PCI bus> on pcib7
mpt0: <LSILogic SAS/SATA Adapter> port 0xd000-0xd0ff mem
0xfdefc000-0xfdefffff,0xfdee0000-0xfdeeffff irq 26 at device 3.0 on pci6
mpt0: [ITHREAD]
mpt0: MPI Version=1.5.16.0
mpt0: Capabilities: ( RAID-0 RAID-1E RAID-1 )
mpt0: 0 Active Volumes (2 Max)
mpt0: 0 Hidden Drive Members (14 Max)
pci0: <base peripheral> at device 15.0 (no driver attached)
pcib8: <ACPI PCI-PCI bridge> irq 16 at device 28.0 on pci0
pci4: <ACPI PCI bus> on pcib8
pcib9: <ACPI PCI-PCI bridge> irq 18 at device 28.2 on pci0
pci3: <ACPI PCI bus> on pcib9
em2: <Intel(R) PRO/1000 Network Connection 6.9.6> port 0xcc00-0xcc1f mem
0xfdae0000-0xfdafffff irq 18 at device 0.0 on pci3
em2: Using MSI interrupt
em2: [FILTER]
em2: Ethernet address: 00:22:15:88:39:93
pcib10: <ACPI PCI-PCI bridge> irq 19 at device 28.3 on pci0
pci2: <ACPI PCI bus> on pcib10
em3: <Intel(R) PRO/1000 Network Connection 6.9.6> port 0xbc00-0xbc1f mem
0xfd9e0000-0xfd9fffff irq 19 at device 0.0 on pci2
em3: Using MSI interrupt
em3: [FILTER]
em3: Ethernet address: 00:22:15:88:39:61
pci0: <serial bus, USB> at device 29.0 (no driver attached)
pci0: <serial bus, USB> at device 29.1 (no driver attached)
pci0: <serial bus, USB> at device 29.7 (no driver attached)
pcib11: <ACPI PCI-PCI bridge> at device 30.0 on pci0
pci1: <ACPI PCI bus> on pcib11
vgapci0: <VGA-compatible display> port 0xac00-0xac7f mem
0xf8000000-0xfbffffff,0xfd8c0000-0xfd8fffff at device 2.0 on pci1
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <Intel 63XXESB2 UDMA100 controller> port
0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xffa0-0xffaf at device 31.1 on pci0
ata0: <ATA channel 0> on atapci0
ata0: [ITHREAD]
atapci1: <Intel 63XXESB2 SATA300 controller> port
0x9c00-0x9c07,0x9880-0x9883,0x9800-0x9807,0x9480-0x9483,0x9400-0x940f mem
0xfd7ffc00-0xfd7fffff irq 19 at device 31.2 on pci0
atapci1: [ITHREAD]
ata2: <ATA channel 0> on atapci1
ata2: [ITHREAD]
ata3: <ATA channel 1> on atapci1
ata3: [ITHREAD]
pci0: <serial bus, SMBus> at device 31.3 (no driver attached)
acpi_button0: <Power Button> on acpi0
fdc0: <floppy drive controller (FDE)> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2
on acpi0
fdc0: [FILTER]
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
atkbd0: [ITHREAD]
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: [ITHREAD]
psm0: model IntelliMouse Explorer, device ID 4
sio0: configured irq 4 not in bitmap of probed irqs 0
sio0: port may not be enabled
sio0: configured irq 4 not in bitmap of probed irqs 0
sio0: port may not be enabled
sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x30 on
acpi0
sio0: type 16550A, console
sio0: [FILTER]
sio1: configured irq 3 not in bitmap of probed irqs 0
sio1: port may not be enabled
sio1: configured irq 3 not in bitmap of probed irqs 0
sio1: port may not be enabled
sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0
sio1: type 16550A
sio1: [FILTER]
cpu0: <ACPI CPU> on acpi0
est0: failed to enable SpeedStep
p4tcc0: <CPU Frequency Thermal Control> on cpu0
cpu1: <ACPI CPU> on acpi0
est1: failed to enable SpeedStep
p4tcc1: <CPU Frequency Thermal Control> on cpu1
cpu2: <ACPI CPU> on acpi0
est2: failed to enable SpeedStep
p4tcc2: <CPU Frequency Thermal Control> on cpu2
cpu3: <ACPI CPU> on acpi0
est3: failed to enable SpeedStep
p4tcc3: <CPU Frequency Thermal Control> on cpu3
orm0: <ISA Option ROMs> at iomem
0xc0000-0xc7fff,0xc8000-0xc8fff,0xc9000-0xc9fff,0xd0000-0xd0fff,0xd1000-0xd1fff
on isa0
ppc0: cannot reserve I/O port range
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
WARNING: ZFS is considered to be an experimental feature in FreeBSD.
Timecounters tick every 1.000 msec
ZFS filesystem version 6
ZFS storage pool version 6
acd0: DMA limited to UDMA33, controller found non-ATA66 cable
acd0: DVDROM <MATSHITADVD-ROM SR-8178/PZ16> at ata0-master UDMA33
da0 at mpt0 bus 0 target 0 lun 0
da0: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da0: 300.000MB/s transfers
da0: Command Queueing Enabled
da0: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da1 at mpt0 bus 0 target 1 lun 0
da1: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da1: 300.000MB/s transfers
da1: Command Queueing Enabled
da1: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da2 at mpt0 bus 0 target 2 lun 0
da2: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da2: 300.000MB/s transfers
da2: Command Queueing Enabled
da2: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da3 at mpt0 bus 0 target 3 lun 0
da3: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da3: 300.000MB/s transfers
da3: Command Queueing Enabled
da3: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da4 at mpt0 bus 0 target 4 lun 0
da4: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da4: 300.000MB/s transfers
da4: Command Queueing Enabled
da4: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da5 at mpt0 bus 0 target 5 lun 0
da5: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da5: 300.000MB/s transfers
da5: Command Queueing Enabled
da5: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da6 at mpt0 bus 0 target 6 lun 0
da6: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da6: 300.000MB/s transfers
da6: Command Queueing Enabled
da6: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da7 at mpt0 bus 0 target 7 lun 0
da7: <SEAGATE ST31000640SS 0001> Fixed Direct Access SCSI-5 device
da7: 300.000MB/s transfers
da7: Command Queueing Enabled
da7: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
SMP: AP CPU #1 Launched!
SMP: AP CPU #3 Launched!
SMP: AP CPU #2 Launched!
WARNING: WITNESS option enabled, expect reduced performance.
WARNING: DIAGNOSTIC option enabled, expect reduced performance.
Trying to mount root from zfs:tank/root
em1: link state changed to UP
John Baldwin
2009-Mar-19 08:59 UTC
in recent 7-STABLE: VOP_WRITE...is not exclusive locked but should be
On Thursday 19 March 2009 8:05:34 am Tim Chase wrote:> Hello, > > I have a system that had been running quite well with an oldish 7-STABLE > (from around August 7, 2008) but has started deadlocking within the past > week or so. > > I updated the kernel to a newer 7-STABLE (Mar 15, 2009) and enabled > INVARIANTS, INVARIANT_SUPPORT, WITNESS, DEBUG_LOCKS DEBUG_VFS_LOCKS and > DIAGNOSTIC and the message indicated in the subject line has now appeared > 3 times as shown below. Is this something to be terribly concerned about? > Is there anything I can to to further track down the cause? Since the > system is a production mail server, I have it set to not drop into DDB > when this happens. > > The machine is a 4-core Xeon X5450 with 8G of RAM running FreeBSD > amd64 and in userland it's pretty much just cyrus imapd and apache/php. > The file systems are all ZFS on a bunch of SAS drives connected to a > LSI Logic 1068 controller. > > As to the deadlock that started this exercise, if the machine follows its > recent pattern, that should happen within the next 2-4 hours.Err, the vn_write() routine should be using an exclusive vnode lock: vn_write() { ... vn_lock(vp, LK_EXCLUSIVE | LK_RETRY, td); if ((flags & FOF_OFFSET) == 0) uio->uio_offset = fp->f_offset; ioflag |= sequential_heuristic(uio, fp); #ifdef MAC error = mac_check_vnode_write(active_cred, fp->f_cred, vp); if (error == 0) #endif error = VOP_WRITE(vp, uio, ioflag, fp->f_cred); ... } Can you check your /sys/kern/vfs_vnops.c and verify that LK_EXCLUSIVE is present in your vn_write() routine? If so, then perhaps run memtest? -- John Baldwin