From owner-freebsd-current@FreeBSD.ORG Mon Jul 21 21:03:28 2008 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 5B901106567A for ; Mon, 21 Jul 2008 21:03:28 +0000 (UTC) (envelope-from gallatin@cs.duke.edu) Received: from duke.cs.duke.edu (duke.cs.duke.edu [152.3.140.1]) by mx1.freebsd.org (Postfix) with ESMTP id 278DF8FC14 for ; Mon, 21 Jul 2008 21:03:28 +0000 (UTC) (envelope-from gallatin@cs.duke.edu) Received: from [172.31.193.10] (cpe-075-177-134-250.nc.res.rr.com [75.177.134.250]) (authenticated bits=0) by duke.cs.duke.edu (8.14.2/8.14.2) with ESMTP id m6LL3KhG027313 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO) for ; Mon, 21 Jul 2008 17:03:27 -0400 (EDT) X-DKIM: Sendmail DKIM Filter v2.5.3 duke.cs.duke.edu m6LL3KhG027313 DKIM-Signature: v=1; a=rsa-sha256; c=simple/simple; d=cs.duke.edu; s=mail; t=1216674207; bh=q6PS3Ur1IRtLq/Ckl1N5wgLOtkNYnD977MxXfbgbkcI=; h=Message-ID:Date:From:MIME-Version:To:Subject:Content-Type: Content-Transfer-Encoding; b=uGY5sTmn/GQXgMtYuQnAE2FXHjJOO3+fVLj+v lEt6YgRvjFZ+bISPXVzaMYPHv0OjdurAiT0iCiyRBPAxLcAcw/3SYwRmSZHHRqFAy/E bGutoekRqBrp5myIgizLmFj9NN4trU3OfK2WJrhlpFmWWZ2p8k0AQ0dPaGP9g08lx7Q = Message-ID: <4884F992.7090008@cs.duke.edu> Date: Mon, 21 Jul 2008 17:03:14 -0400 From: Andrew Gallatin User-Agent: Thunderbird 2.0.0.14 (X11/20080505) MIME-Version: 1.0 To: freebsd-current@freebsd.org Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Subject: reproducible "panic: share->excl" X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 21 Jul 2008 21:03:28 -0000 I can panic today's -current reliably (or hang it with WITNESS/INVARIENTS disabled). When it crashes, I see the appended panic messages. It seems to be 100% reproducible on my box (AMD64 x2, 512MB ram, UFS2). If anybody savvy in this area would like to reproduce it, I've left the program at ~gallatin/ahunt.c on freefall. Compile it, and run it as: ./a.out -mmbfileinit -madvise=/var/tmp/zot -random -size=95536 -touch=4096 -rewrite=2 Cheers, Drew PS: Here is a serial console log from the panic: KDB: debugger backends: ddb KDB: current backend: ddb Copyright (c) 1992-2008 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 8.0-CURRENT #2 r180446:180672: Mon Jul 21 16:35:46 EDT 2008 gallatin@venice:/usr/src/sys/amd64/compile/WITNESS WARNING: WITNESS option enabled, expect reduced performance. Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: AMD Athlon(tm) 64 X2 Dual Core Processor 3800+ (2050.16-MHz K8-class CPU) Origin = "AuthenticAMD" Id = 0x20f32 Stepping = 2 Features=0x178bfbff Features2=0x1 AMD Features=0xe2500800 AMD Features2=0x3 Cores per package: 2 usable memory = 522149888 (497 MB) avail memory = 502501376 (479 MB) ACPI APIC Table: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs cpu0 (BSP): APIC ID: 0 cpu1 (AP): APIC ID: 1 ioapic0: Changing APIC ID to 2 ioapic0 irqs 0-23 on motherboard kbd1 at kbdmux0 ath_hal: 0.9.20.3 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413) acpi0: on motherboard acpi0: [ITHREAD] acpi0: Power Button (fixed) acpi0: reservation of 0, a0000 (3) failed acpi0: reservation of 100000, 1fde0000 (3) failed Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 pci0: at device 0.0 (no driver attached) isab0: at device 1.0 on pci0 isa0: on isab0 pci0: at device 1.1 (no driver attached) ohci0: mem 0xfe02f000-0xfe02ffff irq 21 at device 2.0 on pci0 ohci0: [GIANT-LOCKED] ohci0: [ITHREAD] usb0: OHCI version 1.0, legacy support usb0: on ohci0 usb0: USB revision 1.0 uhub0: on usb0 uhub0: 10 ports with 10 removable, self powered ehci0: mem 0xfeb00000-0xfeb000ff irq 22 at device 2.1 on pci0 ehci0: [GIANT-LOCKED] ehci0: [ITHREAD] usb1: waiting for BIOS to give up control usb1: timed out waiting for BIOS usb1: EHCI version 1.0 usb1: companion controller, 4 ports each: usb0 usb1: on ehci0 usb1: USB revision 2.0 uhub1: on usb1 uhub1: 10 ports with 10 removable, self powered atapci0: port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xe800-0xe80f at device 6.0 on pci0 ata0: on atapci0 ata0: [ITHREAD] ata1: on atapci0 ata1: [ITHREAD] atapci1: port 0x9f0-0x9f7,0xbf0-0xbf3,0x970-0x977,0xb70-0xb73,0xd400-0xd40f mem 0xfe02c000-0xfe02cfff irq 23 at device 7.0 on pci0 atapci1: [ITHREAD] ata2: on atapci1 ata2: [ITHREAD] ata3: on atapci1 ata3: [ITHREAD] atapci2: port 0x9e0-0x9e7,0xbe0-0xbe3,0x960-0x967,0xb60-0xb63,0xc000-0xc00f mem 0xfe02b000-0xfe02bfff irq 21 at device 8.0 on pci0 atapci2: [ITHREAD] ata4: on atapci2 ata4: [ITHREAD] ata5: on atapci2 ata5: [ITHREAD] pcib1: at device 9.0 on pci0 pci1: on pcib1 vgapci0: port 0xac00-0xacff mem 0xd8000000-0xdfffffff,0xfdfe0000-0xfdfeffff irq 18 at device 6.0 on pci1 fwohci0: port 0xa800-0xa87f mem 0xfdfff000-0xfdfff7ff irq 17 at device 9.0 on pci1 fwohci0: [FILTER] fwohci0: OHCI version 1.10 (ROM=1) fwohci0: No. of Isochronous channels is 4. fwohci0: EUI64 00:01:29:10:00:04:d8:01 fwohci0: Phy 1394a available S400, 2 ports. fwohci0: Link S400, max_rec 2048 bytes. firewire0: on fwohci0 fwe0: on firewire0 if_fwe0: Fake Ethernet address: 02:01:29:04:d8:01 fwe0: Ethernet address: 02:01:29:04:d8:01 fwip0: on firewire0 fwip0: Firewire address: 00:01:29:10:00:04:d8:01 @ 0xfffe00000000, S400, maxrec 2048 sbp0: on firewire0 dcons_crom0: on firewire0 dcons_crom0: bus_addr 0x1174000 fwohci0: Initiate bus reset fwohci0: BUS reset fwohci0: node_id=0xc800ffc0, gen=1, CYCLEMASTER mode skc0: port 0xa400-0xa4ff mem 0xfdff8000-0xfdffbfff irq 18 at device 10.0 on pci1 skc0: Marvell Yukon Lite Gigabit Ethernet rev. (0x9) sk0: on skc0 sk0: Ethernet address: 00:01:29:f5:bc:3e miibus0: on sk0 e1000phy0: PHY 0 on miibus0 e1000phy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseTX-FDX, auto skc0: [ITHREAD] nfe0: port 0xbc00-0xbc07 mem 0xfe02a000-0xfe02afff irq 22 at device 10.0 on pci0 miibus1: on nfe0 ciphy0: PHY 1 on miibus1 ciphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto nfe0: Ethernet address: 00:01:29:f5:6b:91 nfe0: [FILTER] pcib2: at device 11.0 on pci0 pci2: on pcib2 pcib3: at device 12.0 on pci0 pci3: on pcib3 pcib4: at device 13.0 on pci0 pci4: on pcib4 pcib5: at device 14.0 on pci0 pci5: on pcib5 pci5: at device 0.0 (no driver attached) cpu0: on acpi0 powernow0: on cpu0 device_attach: powernow0 attach returned 6 cpu1: on acpi0 powernow1: on cpu1 device_attach: powernow1 attach returned 6 acpi_button0: on acpi0 acpi_tz0: on acpi0 atrtc0: port 0x70-0x73 irq 8 on acpi0 fdc0: port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0 fdc0: [FILTER] sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 sio0: type 16550A, console sio0: [FILTER] sio1: port 0x2f8-0x2ff irq 3 on acpi0 sio1: type 16550A sio1: [FILTER] orm0: at iomem 0xc0000-0xcbfff,0xcc000-0xd37ff on isa0 atkbdc0: at port 0x60,0x64 on isa0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] atkbd0: [ITHREAD] 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 uhub2: on uhub0 uhub2: 3 ports with 2 removable, bus powered ukbd0: on uhub2 kbd2 at ukbd0 uhid0: on uhub2 ums0: on uhub2 ums0: 1 buttons. Timecounter "TSC" freqfirewire0: 1 nodes, maxhop <= 0, cable IRM = 0 (me) firewire0: bus manager 0 (me) uency 2050155704 Hz quality 800 Timecounters tick every 1.000 msec acd0: DVDROM at ata0-master UDMA33 ad8: 78167MB at ata4-master SATA150 ad10: 114473MB at ata5-master SATA150 GEOM_LABEL: Label for provider ad8s2 is ext2fs//1. SMP: AP CPU #1 Launched! WARNING: WITNESS option enabled, expect reduced performance. lock order reversal: (sleepable after non-sleepable) 1st 0xffffff000175d028 struct mount mtx (struct mount mtx) @ kern/vfs_subr.c:343 2nd 0xffffff000175d000 vfslock (vfslock) @ kern/vfs_subr.c:370 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a witness_checkorder() at witness_checkorder+0x609 __lockmgr_args() at __lockmgr_args+0xc74 vfs_busy() at vfs_busy+0xe7 vfs_mount_alloc() at vfs_mount_alloc+0x8b vfs_mountroot() at vfs_mountroot+0x241 start_init() at start_init+0x62 fork_exit() at fork_exit+0x12a fork_trampoline() at fork_trampoline+0xe --- trap 0, rip = 0, rsp = 0xfffffffe40010d30, rbp = 0 --- lock order reversal: (sleepable after non-sleepable) 1st 0xffffff0001763470 vnode interlock (vnode interlock) @ fs/devfs/devfs_vnops.c:288 2nd 0xffffff0001763448 devfs (devfs) @ kern/vfs_subr.c:2044 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a witness_checkorder() at witness_checkorder+0x609 __lockmgr_args() at __lockmgr_args+0x502 vop_stdlock() at vop_stdlock+0x39 VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b _vn_lock() at _vn_lock+0x47 vget() at vget+0x7b devfs_allocv() at devfs_allocv+0x10c devfs_root() at devfs_root+0x52 set_rootvnode() at set_rootvnode+0x2d vfs_mountroot() at vfs_mountroot+0x2fe start_init() at start_init+0x62 fork_exit() at fork_exit+0x12a fork_trampoline() at fork_trampoline+0xe --- trap 0, rip = 0, rsp = 0xfffffffe40010d30, rbp = 0 --- Trying to mount root from ufs:/dev/ad8s3a lock order reversal: (sleepable after non-sleepable) 1st 0xffffff00017632f0 bufobj interlock (bufobj interlock) @ kern/vfs_bio.c:2429 2nd 0xfffffffe503099e8 bufwait (bufwait) @ kern/vfs_bio.c:2443 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a witness_checkorder() at witness_checkorder+0x609 __lockmgr_args() at __lockmgr_args+0x502 getblk() at getblk+0xe3 breadn() at breadn+0x3f bread() at bread+0x1e ffs_blkatoff() at ffs_blkatoff+0x61 ufs_lookup() at ufs_lookup+0x5f3 vfs_cache_lookup() at vfs_cache_lookup+0xf8 VOP_LOOKUP_APV() at VOP_LOOKUP_APV+0x95 lookup() at lookup+0x4b2 namei() at namei+0x43f kern_unlinkat() at kern_unlinkat+0x9d vfs_mountroot_try() at vfs_mountroot_try+0x41b vfs_mountroot() at vfs_mountroot+0x3eb start_init() at start_init+0x62 fork_exit() at fork_exit+0x12a fork_trampoline() at fork_trampoline+0xe --- trap 0, rip = 0, rsp = 0xfffffffe40010d30, rbp = 0 --- Entropy harvesting: interrupts ethernet point_to_point kickstart. /dev/ad8s3a: FILE SYSTEM CLEAN; SKIPPING CHECKS /dev/ad8s3a: clean, 56390 free (1062 frags, 6916 blocks, 0.8% fragmentation) /dev/ad8s3d: FILE SYSTEM CLEAN; SKIPPING CHECKS /dev/ad8s3d: clean, 126833 free (25 frags, 15851 blocks, 0.0% fragmentation) /dev/ad8s3f: FILE SYSTEM CLEAN; SKIPPING CHECKS /dev/ad8s3f: clean, 2601443 free (90875 frags, 313821 blocks, 2.3% fragmentation) /dev/ad8s3e: FILE SYSTEM CLEAN; SKIPPING CHECKS /dev/ad8s3e: clean, 847205 free (28653 frags, 102319 blocks, 1.l9% fragmentationoc) k order reversal: 1st 0xffffff00018447f8 ufs (ufs) @ kern/vfs_subr.c:2044 2nd 0xffffffff80b0fcc0 kernel linker (kernel linker) @ kern/kern_linker.c:693 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2a witness_checkorder() at witness_checkorder+0x609 _sx_xlock() at _sx_xlock+0x52 linker_file_lookup_set() at linker_file_lookup_set+0xe1 linker_file_register_sysctls() at linker_file_register_sysctls+0x20 linker_load_module() at linker_load_module+0x909 linker_load_dependencies() at linker_load_dependencies+0x1bc link_elf_load_file() at link_elf_load_file+0xa8a linker_load_module() at linker_load_module+0x8bf kern_kldload() at kern_kldload+0xac kldload() at kldload+0x84 syscall() at syscall+0x1dd Xfast_syscall() at Xfast_syscall+0xab --- syscall (304, FreeBSD ELF64, kldload), rip = 0x800691c5c, rsp = 0x7fffffffedd8, rbp = 0 --- This module (opensolaris) contains code covered by the Common Development and Distribution License (CDDL) see http://opensolaris.org/os/licensing/opensolaris_license/ WARNING: ZFS is considered to be an experimental feature in FreeBSD. ZFS WARNING: Recommended minimum kmem_size is 512MB; expect unstable behavior. Consider tuning vm.kmem_size and vm.kmem_size_max in /boot/loader.conf. ZFS filesystem version 6 ZFS storage pool version 6 nfe0: link state changed to DOWN Starting Network: lo0 nfe0. sk0: link state changed to DOWN /etc/rc.d/power_profile: WARNING: unable to set hw.acpi.cpu.cx_lowest=C1 Waiting 30s for an interface to come up: ................nfe0: link state changed to UP (nfe0) Mounting NFS file systems:. Setting date via ntp. 21 Jul 16:46:30 ntpdate[1360]: adjust time server 152.2.21.1 offset 0.316513 sec Recovering vi editor sessions:. Configuring syscons: blanktime. Mon Jul 21 16:46:32 EDT 2008 FreeBSD/amd64 (venice) (ttyd0) login: shared lock of (lockmgr) ufs @ kern/vfs_subr.c:2044 while exclusively locked from kern/vfs_vnops.c:593 panic: share->excl cpuid = 1 KDB: enter: panic [thread pid 1702 tid 100149 ] Stopped at kdb_enter+0x3d: movq $0,0x639958(%rip) db> tr Tracing pid 1702 tid 100149 td 0xffffff000d08f000 kdb_enter() at kdb_enter+0x3d panic() at panic+0x176 witness_checkorder() at witness_checkorder+0x137 __lockmgr_args() at __lockmgr_args+0xc74 ffs_lock() at ffs_lock+0x8c VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b _vn_lock() at _vn_lock+0x47 vget() at vget+0x7b vnode_pager_lock() at vnode_pager_lock+0x146 vm_fault() at vm_fault+0x1e2 trap_pfault() at trap_pfault+0x128 trap() at trap+0x395 calltrap() at calltrap+0x8 --- trap 0xc, rip = 0xffffffff8079f2bd, rsp = 0xfffffffe58c2f7b0, rbp = 0xfffffffe58c2f830 --- copyin() at copyin+0x3d ffs_write() at ffs_write+0x2f8 VOP_WRITE_APV() at VOP_WRITE_APV+0x10b vn_write() at vn_write+0x23f dofilewrite() at dofilewrite+0x85 --More-- kern_writev() at kern_writev+0x60 write() at write+0x54 syscall() at syscall+0x1dd Xfast_syscall() at Xfast_syscall+0xab --- syscall (4, FreeBSD ELF64, write), rip = 0x8007296ec, rsp = 0x7fffffffe158, rbp = 0x7fffffffe210 --- db> show locks exclusive sleep mutex vnode interlock r = 0 (0xffffff000d0dc0c0) locked @ vm/vnode_pager.c:1199 exclusive sx user map r = 0 (0xffffff000d054360) locked @ vm/vm_map.c:3115 exclusive lockmgr bufwait r = 0 (0xfffffffe5047f278) locked @ kern/vfs_bio.c:1783 exclusive lockmgr ufs r = 0 (0xffffff000d0dc098) locked @ kern/vfs_vnops.c:593 db>