From owner-freebsd-stable@FreeBSD.ORG Thu Mar 19 13:09:31 2009 Return-Path: Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id D619F106564A for ; Thu, 19 Mar 2009 13:09:31 +0000 (UTC) (envelope-from tim@chase2k.com) Received: from smtp.onlight.com (mx2.onlight.com [69.128.127.253]) by mx1.freebsd.org (Postfix) with ESMTP id 4A5848FC1C for ; Thu, 19 Mar 2009 13:09:31 +0000 (UTC) (envelope-from tim@chase2k.com) Received: from localhost (livingston [127.0.0.1]) by clean.onlight.com (Postfix) with ESMTP id 6781A82012A0 for ; Thu, 19 Mar 2009 07:05:42 -0500 (CDT) X-Virus-Scanned: amavisd-new at onlight.com Received: from smtp.onlight.com ([127.0.0.1]) by localhost (filter.onlight.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP id HnCGvjNIm7zS for ; Thu, 19 Mar 2009 07:05:38 -0500 (CDT) Received: from chase2k.com.vpn.onlight.com (chase2k.com.vpn.onlight.com [10.8.0.33]) by smtp.onlight.com (Postfix) with ESMTPA id 92CA6830272D for ; Thu, 19 Mar 2009 07:05:38 -0500 (CDT) Date: Thu, 19 Mar 2009 07:05:34 -0500 (CDT) From: Tim Chase Sender: tim@cardinal.onlight.com To: freebsd-stable@freebsd.org Message-ID: User-Agent: Alpine 2.00 (LFD 1167 2008-08-23) MIME-Version: 1.0 Content-Type: TEXT/PLAIN; format=flowed; charset=US-ASCII Subject: in recent 7-STABLE: VOP_WRITE...is not exclusive locked but should be X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 19 Mar 2009 13:09:32 -0000 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 Features2=0xce3bd> AMD Features=0x20100800 AMD Features2=0x1 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 irqs 0-23 on motherboard ioapic1 irqs 24-47 on motherboard ioapic2 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: iomem 0xfed00000-0xfed003ff on acpi0 Timecounter "HPET" frequency 14318180 Hz quality 900 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 pcib1: irq 48 at device 1.0 on pci0 pci11: on pcib1 pcib2: irq 52 at device 5.0 on pci0 pci10: on pcib2 pcib3: irq 56 at device 9.0 on pci0 pci5: on pcib3 pcib4: irq 16 at device 0.0 on pci5 pci7: on pcib4 pcib5: at device 0.0 on pci7 pci9: on pcib5 pcib6: at device 2.0 on pci7 pci8: on pcib6 em0: 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: 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: at device 0.3 on pci5 pci6: on pcib7 mpt0: 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: at device 15.0 (no driver attached) pcib8: irq 16 at device 28.0 on pci0 pci4: on pcib8 pcib9: irq 18 at device 28.2 on pci0 pci3: on pcib9 em2: 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: irq 19 at device 28.3 on pci0 pci2: on pcib10 em3: 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: at device 29.0 (no driver attached) pci0: at device 29.1 (no driver attached) pci0: at device 29.7 (no driver attached) pcib11: at device 30.0 on pci0 pci1: on pcib11 vgapci0: port 0xac00-0xac7f mem 0xf8000000-0xfbffffff,0xfd8c0000-0xfd8fffff at device 2.0 on pci1 isab0: at device 31.0 on pci0 isa0: on isab0 atapci0: port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xffa0-0xffaf at device 31.1 on pci0 ata0: on atapci0 ata0: [ITHREAD] atapci1: 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: on atapci1 ata2: [ITHREAD] ata3: on atapci1 ata3: [ITHREAD] pci0: at device 31.3 (no driver attached) acpi_button0: on acpi0 fdc0: port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0 fdc0: [FILTER] fd0: <1440-KB 3.5" drive> on fdc0 drive 0 atkbdc0: port 0x60,0x64 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] atkbd0: [ITHREAD] psm0: 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: on acpi0 est0: failed to enable SpeedStep p4tcc0: on cpu0 cpu1: on acpi0 est1: failed to enable SpeedStep p4tcc1: on cpu1 cpu2: on acpi0 est2: failed to enable SpeedStep p4tcc2: on cpu2 cpu3: on acpi0 est3: failed to enable SpeedStep p4tcc3: on cpu3 orm0: at iomem 0xc0000-0xc7fff,0xc8000-0xc8fff,0xc9000-0xc9fff,0xd0000-0xd0fff,0xd1000-0xd1fff on isa0 ppc0: cannot reserve I/O port range sc0: at flags 0x100 on isa0 sc0: VGA <16 virtual consoles, flags=0x100> vga0: 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 at ata0-master UDMA33 da0 at mpt0 bus 0 target 0 lun 0 da0: 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: 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: 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: 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: 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: 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: 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: 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