From owner-freebsd-stable@FreeBSD.ORG Tue Jan 2 16:56:07 2007 Return-Path: X-Original-To: freebsd-stable@freebsd.org Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id 7A72616A416 for ; Tue, 2 Jan 2007 16:56:07 +0000 (UTC) (envelope-from zingelman@fnal.gov) Received: from mailgw2.fnal.gov (mailgw2.fnal.gov [131.225.111.12]) by mx1.freebsd.org (Postfix) with ESMTP id 4F53913C45D for ; Tue, 2 Jan 2007 16:56:07 +0000 (UTC) (envelope-from zingelman@fnal.gov) Received: from mailav2.fnal.gov (mailav2.fnal.gov [131.225.111.20]) by mailgw2.fnal.gov (iPlanet Messaging Server 5.2 HotFix 2.06 (built Mar 28 2005)) with SMTP id <0JB900HV707PHY@mailgw2.fnal.gov> for freebsd-stable@freebsd.org; Tue, 02 Jan 2007 09:55:24 -0600 (CST) Received: from mailgw2.fnal.gov ([131.225.111.12]) by mailav2.fnal.gov (SAVSMTP 3.1.7.47) with SMTP id M2007010209552417369 for ; Tue, 02 Jan 2007 09:55:24 -0600 Received: from conversion-daemon.mailgw2.fnal.gov by mailgw2.fnal.gov (iPlanet Messaging Server 5.2 HotFix 2.06 (built Mar 28 2005)) id <0JB900301041I7@mailgw2.fnal.gov> (original mail from zingelman@fnal.gov) for freebsd-stable@freebsd.org; Tue, 02 Jan 2007 09:55:24 -0600 (CST) Received: from nova.fnal.gov (nova.fnal.gov [131.225.121.207]) by mailgw2.fnal.gov (iPlanet Messaging Server 5.2 HotFix 2.06 (built Mar 28 2005)) with ESMTP id <0JB900GVF08CBH@mailgw2.fnal.gov> for freebsd-stable@freebsd.org; Tue, 02 Jan 2007 09:55:24 -0600 (CST) Received: from nova.fnal.gov (localhost [127.0.0.1]) by nova.fnal.gov (8.13.8+Sun/8.13.8) with ESMTP id l02FtN0t009149 for ; Tue, 02 Jan 2007 09:55:23 -0600 (CST) Received: from localhost (tez@localhost) by nova.fnal.gov (8.13.8+Sun/8.13.8/Submit) with ESMTP id l02FtM3V009145 for ; Tue, 02 Jan 2007 09:55:23 -0600 (CST) Date: Tue, 02 Jan 2007 09:55:22 -0600 (CST) From: Tim Zingelman X-X-Sender: tez@nova.fnal.gov To: freebsd-stable@freebsd.org Message-id: MIME-version: 1.0 Content-type: TEXT/PLAIN; charset=US-ASCII Content-transfer-encoding: 7BIT X-Authentication-warning: nova.fnal.gov: tez owned process doing -bs Subject: panic: vn_finished_write: neg cnt X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Tim Zingelman List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 02 Jan 2007 16:56:07 -0000 # cd /usr/obj/usr/src/sys/SMP/ # kgdb kernel.debug /var/crash/vmcore.0 [GDB will not be able to debug user-mode threads: /usr/lib/libthread_db.so: Undefined symbol "ps_pglobal_lookup"] GNU gdb 6.1.1 [FreeBSD] Copyright 2004 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "i386-marcel-freebsd". Unread portion of the kernel message buffer: panic: vn_finished_write: neg cnt cpuid = 1 Uptime: 4d21h14m32s Dumping 2047 MB (2 chunks) chunk 0: 1MB (159 pages) ... ok chunk 1: 2047MB (524016 pages) 2031 2015 1999 1983 1967 1951 1935 1919 1903 1887 1871 1855 1839 1823 1807 1791 1775 1759 1743 1727 1711 1695 1679 1663 1647 1631 1615 1599 1583 1567 1551 1535 1519 1503 1487 1471 1455 1439 1423 1407 1391 1375 1359 1343 1327 1311 1295 1279 1263 1247 1231 1215 1199 1183 1167 1151 1135 1119 1103 1087 1071 1055 1039 1023 1007 991 975 959 943 927 911 895 879 863 847 831 815 799 783 767 751 735 719 703 687 671 655 639 623 607 591 575 559 543 527 511 495 479 463 447 431 415 399 383 367 351 335 319 303 287 271 255 239 223 207 191 175 159 143 127 111 95 79 63 47 31 15 #0 doadump () at pcpu.h:165 165 __asm __volatile("movl %%fs:0,%0" : "=r" (td)); (kgdb) backtrace #0 doadump () at pcpu.h:165 #1 0xc06754ea in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:409 #2 0xc0675811 in panic (fmt=0xc090613a "vn_finished_write: neg cnt") at /usr/src/sys/kern/kern_shutdown.c:565 #3 0xc06dc82f in vn_finished_write (mp=0xc675d530) at /usr/src/sys/kern/vfs_vnops.c:1048 #4 0xc06dbb68 in vn_write (fp=0xccded2d0, uio=0xea002cbc, active_cred=0xc6e5a580, flags=0, td=0xc8623900) at /usr/src/sys/kern/vfs_vnops.c:583 #5 0xc0698f43 in dofilewrite (td=0xc8623900, fd=11, fp=0xccded2d0, auio=0xea002cbc, offset=Unhandled dwarf expression opcode 0x93 ) at file.h:252 #6 0xc0698de7 in kern_writev (td=0xc8623900, fd=11, auio=0xea002cbc) at /usr/src/sys/kern/sys_generic.c:402 #7 0xc0698d0d in write (td=0xc8623900, uap=0x0) at /usr/src/sys/kern/sys_generic.c:326 #8 0xc088e583 in syscall (frame= {tf_fs = 59, tf_es = 59, tf_ds = 59, tf_edi = 134973792, tf_esi = 135065600, tf_ebp = -1077968696, tf_isp = -369087132, tf_ebx = 4096, tf_edx = 4096, tf_ecx = 0, tf_eax = 4, tf_trapno = 4096, tf_err = 2, tf_eip = 134840319, tf_cs = 51, tf_eflags = 582, tf_esp = -1077968756, tf_ss = 59}) at /usr/src/sys/i386/i386/trap.c:983 #9 0xc0879d3f in Xint0x80_syscall () at /usr/src/sys/i386/i386/exception.s:200 #10 0x00000033 in ?? () Previous frame inner to this frame (corrupt stack?) (kgdb) up 3 #3 0xc06dc82f in vn_finished_write (mp=0xc675d530) at /usr/src/sys/kern/vfs_vnops.c:1048 1048 panic("vn_finished_write: neg cnt"); (kgdb) list 1043 if (mp == NULL) 1044 return; 1045 MNT_ILOCK(mp); 1046 mp->mnt_writeopcount--; 1047 if (mp->mnt_writeopcount < 0) 1048 panic("vn_finished_write: neg cnt"); 1049 if ((mp->mnt_kern_flag & MNTK_SUSPEND) != 0 && 1050 mp->mnt_writeopcount <= 0) 1051 wakeup(&mp->mnt_writeopcount); 1052 MNT_IUNLOCK(mp); (kgdb) print *mp $1 = {mnt_list = {tqe_next = 0xc675d298, tqe_prev = 0xc675d7c8}, mnt_op = 0xc09ae620, mnt_vfc = 0xc09ae660, mnt_vnodecovered = 0xc6794660, mnt_syncer = 0xc694b660, mnt_nvnodelist = {tqh_first = 0xc7595330, tqh_last = 0xcab48014}, mnt_lock = {lk_interlock = 0xc09dceb8, lk_flags = 0, lk_sharecount = 0, lk_waitcount = 0, lk_exclusivecount = 0, lk_prio = 80, lk_wmesg = 0xc09056c9 "vfslock", lk_timo = 0, lk_lockholder = 0xffffffff, lk_newlock = 0x0}, mnt_mtx = {mtx_object = { lo_class = 0xc09750e4, lo_name = 0xc09056b8 "struct mount mtx", lo_type = 0xc09056b8 "struct mount mtx", lo_flags = 196608, lo_list = { tqe_next = 0x0, tqe_prev = 0x0}, lo_witness = 0x0}, mtx_lock = 3361880322, mtx_recurse = 0}, mnt_writeopcount = -1, mnt_flag = 2101504, mnt_opt = 0xc68098e0, mnt_optnew = 0x0, mnt_kern_flag = 536870912, mnt_maxsymlinklen = 120, mnt_stat = { f_version = 537068824, f_type = 7, f_flags = 2101504, f_bsize = 2048, f_iosize = 16384, f_blocks = 292488222, f_bfree = 188891807, f_bavail = 165492750, f_files = 75601918, f_ffree = 66247979, f_syncwrites = 0, f_asyncwrites = 0, f_syncreads = 0, f_asyncreads = 0, f_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, f_namemax = 255, f_owner = 0, f_fsid = {val = {1164144299, -1500130876}}, f_charspare = '\0' , f_fstypename = "ufs", '\0' , f_mntfromname = "/dev/da0s1f", '\0' , f_mntonname = "/usr", '\0' }, mnt_cred = 0xc695ad00, mnt_data = 0xc6749b00, mnt_time = 0, mnt_iosize_max = 131072, mnt_export = 0xc674cc00, mnt_mntlabel = 0x0, mnt_fslabel = 0x0, mnt_nvnodelistsize = 58931, mnt_hashseed = 3969027219, mnt_markercnt = 0, mnt_holdcnt = 0, mnt_holdcntwaiters = 0, mnt_secondary_writes = 0, mnt_secondary_accwrites = 504046284, mnt_ref = 58931, mnt_gen = 1} (kgdb) up #4 0xc06dbb68 in vn_write (fp=0xccded2d0, uio=0xea002cbc, active_cred=0xc6e5a580, flags=0, td=0xc8623900) at /usr/src/sys/kern/vfs_vnops.c:583 583 vn_finished_write(mp); (kgdb) list 578 if ((flags & FOF_OFFSET) == 0) 579 fp->f_offset = uio->uio_offset; 580 fp->f_nextoff = uio->uio_offset; 581 VOP_UNLOCK(vp, 0, td); 582 if (vp->v_type != VCHR) 583 vn_finished_write(mp); 584 unlock: 585 VFS_UNLOCK_GIANT(vfslocked); 586 return (error); 587 } (kgdb) print flags $5 = 0 (kgdb) print *uio $6 = {uio_iov = 0xea002cb4, uio_iovcnt = 1, uio_offset = 1245192, uio_resid = 0, uio_segflg = UIO_USERSPACE, uio_rw = UIO_WRITE, uio_td = 0xc8623900} (kgdb) print *vp $3 = {v_type = VREG, v_tag = 0xc0904786 "ufs", v_op = 0xc09ae980, v_data = 0xcce7edec, v_mount = 0xc675d530, v_nmntvnodes = { tqe_next = 0xcd9dc660, tqe_prev = 0xc7902014}, v_un = {vu_mount = 0x0, vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = { le_next = 0xcda56770, le_prev = 0xc65f5b14}, v_hash = 26239538, v_cache_src = {lh_first = 0x0}, v_cache_dst = {tqh_first = 0xc86c3594, tqh_last = 0xc86c35a4}, v_dd = 0x0, v_cstart = 72, v_lasta = 419301280, v_lastw = 75, v_clen = 7, v_lock = {lk_interlock = 0xc09dd218, lk_flags = 64, lk_sharecount = 0, lk_waitcount = 0, lk_exclusivecount = 0, lk_prio = 80, lk_wmesg = 0xc0904786 "ufs", lk_timo = 51, lk_lockholder = 0xffffffff, lk_newlock = 0x0}, v_interlock = { mtx_object = {lo_class = 0xc09750e4, lo_name = 0xc0905d01 "vnode interlock", lo_type = 0xc0905d01 "vnode interlock", lo_flags = 196608, lo_list = { tqe_next = 0x0, tqe_prev = 0x0}, lo_witness = 0x0}, mtx_lock = 4, mtx_recurse = 0}, v_vnlock = 0xc8de09e8, v_holdcnt = 80, v_usecount = 1, v_iflag = 0, v_vflag = 0, v_writecount = 1, v_freelist = {tqe_next = 0x0, tqe_prev = 0x0}, v_bufobj = {bo_mtx = 0xc8de0a0c, bo_clean = {bv_hd = { tqh_first = 0xda668910, tqh_last = 0xda524060}, bv_root = 0xda524028, bv_cnt = 72}, bo_dirty = {bv_hd = {tqh_first = 0xda6651f8, tqh_last = 0xda560670}, bv_root = 0xda560638, bv_cnt = 6}, bo_numoutput = 0, bo_flag = 1, bo_ops = 0xc097b364, bo_bsize = 16384, bo_object = 0xcd26c39c, bo_synclist = {le_next = 0xca39c3f0, le_prev = 0xcab480f8}, bo_private = 0xc8de0990, __bo_vnode = 0xc8de0990}, v_pollinfo = 0x0, v_label = 0x0} (kgdb) print *td $7 = {td_proc = 0xcda11430, td_ksegrp = 0xcd9f2ba0, td_plist = { tqe_next = 0x0, tqe_prev = 0xcda11440}, td_kglist = {tqe_next = 0x0, tqe_prev = 0xcd9f2bac}, td_slpq = {tqe_next = 0x0, tqe_prev = 0xc7b0a880}, td_lockq = {tqe_next = 0x0, tqe_prev = 0xe9fdbb1c}, td_runq = { tqe_next = 0x0, tqe_prev = 0x0}, td_selq = {tqh_first = 0x0, tqh_last = 0xc8623930}, td_sleepqueue = 0xc7b0a880, td_turnstile = 0xc8072280, td_umtxq = 0xc72a8800, td_tid = 101129, td_flags = 83951619, td_inhibitors = 0, td_pflags = 0, td_dupfd = 0, td_wchan = 0x0, td_wmesg = 0x0, td_lastcpu = 1 '\001', td_oncpu = 0 '\0', td_owepreempt = 0 '\0', td_locks = 3, td_blocked = 0x0, td_ithd = 0x0, td_lockname = 0x0, td_contested = {lh_first = 0xcd213c00}, td_sleeplocks = 0x0, td_intr_nesting_level = 0, td_pinned = 0, td_mailbox = 0x0, td_ucred = 0xc6e5a580, td_standin = 0x0, td_upcall = 0x0, td_sticks = 2330, td_uuticks = 0, td_usticks = 0, td_intrval = 0, td_oldsigmask = {__bits = {0, 0, 0, 0}}, td_sigmask = {__bits = {0, 0, 0, 0}}, td_siglist = {__bits = {0, 0, 0, 0}}, td_generation = 451, td_sigstk = {ss_sp = 0x0, ss_size = 0, ss_flags = 4}, td_kflags = 0, td_xsig = 0, td_profil_addr = 0, td_profil_ticks = 0, td_base_pri = 216 'X', td_priority = 211 'S', td_pcb = 0xea002d90, td_state = TDS_RUNNING, td_retval = {0, 4096}, td_slpcallout = {c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xda412da8}}, c_time = 422055083, c_arg = 0xc8623900, c_func = 0xc0695340 , c_mtx = 0x0, c_flags = 18}, td_frame = 0xea002d38, td_kstack_obj = 0xcd578738, td_kstack = 3925872640, td_kstack_pages = 2, td_altkstack_obj = 0x0, td_altkstack = 0, td_altkstack_pages = 0, td_critnest = 1, td_md = { md_spinlock_count = 1, md_saved_flags = 582}, td_sched = 0xc8623a58, td_ar = 0x0} (kgdb) print *fp $4 = {f_list = {le_next = 0xce1440d8, le_prev = 0xc6801900}, f_type = 1, f_data = 0xc8de0990, f_flag = 3, f_mtxp = 0xc63dbd00, f_ops = 0xc097cfe0, f_cred = 0xc6e5a580, f_count = 2, f_vnode = 0xc8de0990, f_offset = 1245192, f_vnread_flags = 0, f_gcflag = 0, f_msgcount = 0, f_seqcount = 127, f_nextoff = 1245192, f_label = 0x0} What other info might be of use? System was doing a buildworld -j26 and downloading a port distfile at the time of the crash. System has been attempting to build a package for every port in the tree while looping over buildworld with various large -j numbers to try and prove the system is stable. Twice I have seen: twa0: WARNING: (0x04: 0x0036): Verify fixed data/parity mismatch: unit=2 a couple of times... but nothing else. Here is the interesting part of the dmesg output... more details available if anyone wants to look at this. FreeBSD 6.2-RC2 #3: Wed Dec 27 15:22:35 CST 2006 toor@host.name.xyz:/usr/obj/usr/src/sys/SMP Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: Dual Core AMD Opteron(tm) Processor 280 (2393.19-MHz 686-class CPU) Origin = "AuthenticAMD" Id = 0x20f12 Stepping = 2 Features=0x178bfbff Features2=0x1 AMD Features=0xe2500800 AMD Features2=0x3 Cores per package: 2 real memory = 2147418112 (2047 MB) avail memory = 2096295936 (1999 MB) ACPI APIC Table: 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 MADT: Forcing active-low polarity and level trigger for SCI ioapic0 irqs 0-23 on motherboard ioapic1 irqs 24-27 on motherboard ioapic2 irqs 28-31 on motherboard kbd1 at kbdmux0 ath_hal: 0.9.17.2 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413) acpi0: on motherboard acpi0: Power Button (fixed) Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x5008-0x500b on acpi0 bge0: mem 0xfc9e0000-0xfc9effff irq 26 at device 5.0 on pci2 miibus0: on bge0 brgphy0: on miibus0 brgphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseTX, 1000baseTX-FDX, auto bge0: Ethernet address: 00:30:48:5a:8f:92 bge1: mem 0xfc9b0000-0xfc9bffff irq 27 at device 5.1 on pci2 miibus1: on bge1 brgphy1: on miibus1 brgphy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseTX, 1000baseTX-FDX, auto bge1: Ethernet address: 00:30:48:5a:8f:93 3ware device driver for 9000 series storage controllers, version: 3.60.02.012 twa0: <3ware 9000 series Storage Controller> port 0xac00-0xac3f mem 0xfa000000-0xfbffffff,0xfc8ff000-0xfc8fffff irq 29 at device 3.0 on pci1 twa0: [FAST] twa0: INFO: (0x04: 0x0053): Battery capacity test is overdue: twa0: INFO: (0x15: 0x1300): Controller details:: Model 9550SX-12MI, 12 ports, Firmware FE9X 3.04.00.005, BIOS BE9X 3.04.00.002 da0 at twa0 bus 0 target 2 lun 0 da0: Fixed Direct Access SCSI-3 device da0: 100.000MB/s transfers da0: 915495MB (1874933760 512 byte sectors: 255H 63S/T 116709C) SMP: AP CPU #1 Launched! SMP: AP CPU #3 Launched! SMP: AP CPU #2 Launched! Trying to mount root from ufs:/dev/da0s1a bge0: link state changed to UP vmmon: SMP support for this release is BROKEN. module_register_init: MOD_LOAD (vmmon, 0xc6c020b4, 0) error 22 vmnet1: Ethernet address: 00:bd:a0:4f:00:01 (note that vmmon is not used, just loaded because I've been building packages for the whole ports tree to burn in this box)