GENERIC HEAD from 2010-10-25 08:30:19 UTC, r213945M, vmcore.22 KDB: debugger backends: ddb KDB: current backend: ddb 524288K of memory above 4GB ignored Copyright (c) 1992-2010 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 9.0-CURRENT #0 r214955+5fd1aef: Mon Nov 8 01:06:38 CET 2010 pho@x4.osted.lan:/var/tmp/deviant2/sys/i386/compile/PHO i386 WARNING: WITNESS option enabled, expect reduced performance. WARNING: DIAGNOSTIC option enabled, expect reduced performance. CPU: AMD Phenom(tm) 9150e Quad-Core Processor (1800.02-MHz 686-class CPU) Origin = "AuthenticAMD" Id = 0x100f23 Family = 10 Model = 2 Stepping = 3 Features=0x178bfbff Features2=0x802009 AMD Features=0xee500800 AMD Features2=0x7ff TSC: P-state invariant real memory = 4294967296 (4096 MB) avail memory = 3536277504 (3372 MB) : Trying to mount root from ufs:/dev/ad4s1a [rw]... WARNING: / was not properly dismounted Setting hostuuid: 00000000-0000-0000-0000-00218515337d. Setting hostid: 0x6b64ac17. Starting ddb. Entropy harvesting: interrupts ethernet point_to_point kickstart. Starting file system checks: /dev/ad4s1a: 3339 files, 195826 used, 817189 free (861 frags, 102041 blocks, 0.1% fragmentation) /dev/ad4s1f: 7881 files, 218447 used, 794568 free (232 frags, 99292 blocks, 0.0% fragmentation) /dev/ad4s1g: 23468 files, 729043 used, 117584938 free (442 frags, 14698062 blocks, 0.0% fragmentation) /dev/ad4s1d: 753623 files, 5964311 used, 4189888 free (104592 frags, 510662 blocks, 1.0% fragmentation) /dev/ad4s1e: INCORRECT BLOCK COUNT I=6223059 (12 should be 0) (CORRECTED) /dev/ad4s1e: LINK COUNT DIR I=6223053 OWNER=pho MODE=40755 /dev/ad4s1e: SIZE=1024 MTIME=Nov 8 21:48 2010 COUNT 61 SHOULD BE 4 (ADJUSTED) /dev/ad4s1e: UNREF FILE I=6223059 OWNER=pho MODE=100644 /dev/ad4s1e: SIZE=0 MTIME=Nov 8 21:48 2010 (CLEARED) /dev/ad4s1e: LINK COUNT DIR I=6241327 OWNER=pho MODE=40755 /dev/ad4s1e: SIZE=512 MTIME=Nov 8 21:48 2010 COUNT 4 SHOULD BE 3 (ADJUSTED) /dev/ad4s1e: FREE BLK COUNT(S) WRONG IN SUPERBLK (SALVAGED) /dev/ad4s1e: SUMMARY INFORMATION BAD (SALVAGED) /dev/ad4s1e: BLK(S) MISSING IN BIT MAPS (SALVAGED) /dev/ad4s1e: 329687 files, 6199097 used, 19189420 free (6796 frags, 2397828 blocks, 0.0% fragmentation) Mounting local file systems:. Setting hostname: x4.osted.lan. re0: link state changed to DOWN Starting Network: lo0 re0 fwe0 fwip0. lo0: flags=8049 metric 0 mtu 16384 options=3 inet 127.0.0.1 netmask 0xff000000 inet6 ::1 prefixlen 128 inet6 fe80::1%lo0 prefixlen 64 scopeid 0x4 nd6 options=21 re0: flags=8843 metric 0 mtu 1500 options=389b ether 00:21:85:15:33:7d inet 192.168.1.7 netmask 0xffffff00 broadcast 192.168.1.255 inet6 fe80::221:85ff:fe15:337d%re0 prefixlen 64 tentative scopeid 0x1 nd6 options=29 media: Ethernet autoselect (none) status: no carrier fwe0: flags=8802 metric 0 mtu 1500 options=8 ether 02:dc:10:62:ad:eb ch 1 dma -1 fwip0: flags=8802 metric 0 mtu 1500 lladdr 0.dc.10.0.1.62.ad.eb.a.2.ff.fe.0.0.0.0 Starting devd. Starting Network: fwe0. fwe0: flags=8802 metric 0 mtu 1500 options=8 ether 02:dc:10:62:ad:eb ch 1 dma -1 Starting Network: fwip0. fwip0: flags=8802 metric 0 mtu 1500 lladdr 0.dc.10.0.1.62.ad.eb.a.2.ff.fe.0.0.0.0 add net default: gateway 192.168.1.1 add net ::ffff:0.0.0.0: gateway ::1 add net ::0.0.0.0: gateway ::1 add net fe80::: gateway ::1 add net ff02::: gateway ::1 ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib /usr/local/lib/compat/pkg /usr/local/lib /usr/local/lib/compat/pkg /usr/local/lib/wine a.out ldconfig path: /usr/lib/aout /usr/lib/compat/aout Creating and/or trimming log files. Starting syslogd. savecore: reboot Nov 8 21:53:38 x4 savecore: reboot savecore: writing core to vmcore.22 Writing crash summary to /var/crash/core.txt.22. Additional ABI support: linux. Starting rpcbind. NFS access cache time=60 Clearing /tmp (X related). Starting mountd. Starting nfsd. Updating motd:. Starting ntpd. Configuring syscons: keymap blanktime. Starting sshd. Starting cron. Local package initialization: backuplock order reversal: 1st 0xc7fc0880 ufs (ufs) @ kern/vfs_subr.c:2111 2nd 0xdad393a0 bufwait (bufwait) @ ufs/ffs/ffs_softdep.c:11345 3rd 0xc8c33724 ufs (ufs) @ kern/vfs_subr.c:2111 KDB: stack backtrace: db_trace_self_wrapper(c0ceca96,2e706564,31313a63,d353433,c0d1000a,...) at db_trace_self_wrapper+0x26 kdb_backtrace(c08f63eb,c0cefcb4,c6d40168,c6d437d8,e9743890,...) at kdb_backtrace+0x2a _witness_debugger(c0cefcb4,c8c33724,c0ce15d7,c6d437d8,c0cf6ff3,...) at _witness_debugger+0x25 witness_checkorder(c8c33724,9,c0cf6fea,83f,0,...) at witness_checkorder+0x839 __lockmgr_args(c8c33724,80100,c8c33790,0,0,...) at __lockmgr_args+0x814 ffs_lock(e97439b4,c0906f7b,c0cf6369,80100,c8c336cc,...) at ffs_lock+0xa1 VOP_LOCK1_APV(c0dfde40,e97439b4,109,c0e18cc0,c8c336cc,...) at VOP_LOCK1_APV+0xb5 _vn_lock(c8c336cc,80100,c0cf6fea,83f,4,...) at _vn_lock+0x78 vget(c8c336cc,80100,c7c81000,50,0,...) at vget+0xbb vfs_hash_get(c7fc22d4,bae000,80000,c7c81000,e9743b08,...) at vfs_hash_get+0xed ffs_vgetf(c7fc22d4,bae000,80000,e9743b08,1,...) at ffs_vgetf+0x49 softdep_sync_metadata(c7fc0828,0,c0d13e24,144,0,...) at softdep_sync_metadata+0x6a3 ffs_syncvnode(c7fc0828,1,c7c81000,555,c0cf6fea,...) at ffs_syncvnode+0x3e2 ffs_sync(c7fc22d4,1,c0cf66aa,4fd,80,...) at ffs_sync+0x26f dounmount(c7fc22d4,8000000,c7c81000,482,5b85c5ea,...) at dounmount+0x447 unmount(c7c81000,e9743cec,281760f5,1,0,...) at unmount+0x310 syscallenter(c7c81000,e9743ce4,c0c0694d,c0e4da30,0,...) at syscallenter+0x263 syscall(e9743d28) at syscall+0x4f Xint0x80_syscall() at Xint0x80_syscall+0x21 --- syscall (22, FreeBSD ELF32, unmount), eip = 0x280dbadf, esp = 0xbfbfe66c, ebp = 0xbfbfe738 --- lock order reversal: 1st 0xc7fc1310 ufs (ufs) @ kern/vfs_mount.c:1208 2nd 0xc7f9f880 devfs (devfs) @ ufs/ffs/ffs_softdep.c:1606 KDB: stack backtrace: db_trace_self_wrapper(c0ceca96,36313a63,a0d3630,c15ba200,e9743964,...) at db_trace_self_wrapper+0x26 kdb_backtrace(c08f63eb,c0cefc9b,c6d437d8,c6d436a0,e9743a04,...) at kdb_backtrace+0x2a _witness_debugger(c0cefc9b,c7f9f880,c0cdd14e,c6d436a0,c0d10f59,...) at _witness_debugger+0x25 witness_checkorder(c7f9f880,9,c0d10f50,646,c7f9f8ec,...) at witness_checkorder+0x839 __lockmgr_args(c7f9f880,80400,c7f9f8ec,0,0,...) at __lockmgr_args+0x814 vop_stdlock(e9743b24,c0ce7c6e,df,80400,c7f9f828,...) at vop_stdlock+0x65 VOP_LOCK1_APV(c0dd62e0,e9743b24,0,c0e18cc0,c7f9f828,...) at VOP_LOCK1_APV+0xb5 _vn_lock(c7f9f828,80400,c0d10f50,646,c7fc22d4,...) at _vn_lock+0x78 softdep_flushworklist(c7fc22d4,e9743bd0,c7c81000,563,c0cf6fea,...) at softdep_flushworklist+0x47 ffs_sync(c7fc22d4,1,c0cf66aa,4fd,80,...) at ffs_sync+0x2fd dounmount(c7fc22d4,8000000,c7c81000,482,5b85c5ea,...) at dounmount+0x447 unmount(c7c81000,e9743cec,281760f5,1,0,...) at unmount+0x310 syscallenter(c7c81000,e9743ce4,c0c0694d,c0e4da30,0,...) at syscallenter+0x263 syscall(e9743d28) at syscall+0x4f Xint0x80_syscall() at Xint0x80_syscall+0x21 --- syscall (22, FreeBSD ELF32, unmount), eip = 0x280dbadf, esp = 0xbfbfe66c, ebp = 0xbfbfe738 --- ** /dev/ad4s1g ** Last Mounted on /tmp ** Phase 1 - Check Blocks and Sizes ** Phase 2 - Check Pathnames ** Phase 3 - Check Connectivity ** Phase 4 - Check Reference Counts ** Phase 5 - Check Cyl groups 23468 files, 729043 used, 117584938 free (442 frags, 14698062 blocks, 0.0% fragmentation) ***** FILE SYSTEM IS CLEAN ***** usage: kill [-s signal_name] pid ... kill -l [exit_status] kill -signal_name pid ... kill -signal_number pid ... fsck -y /tmp. Starting default moused. Starting inetd. Mon Nov 8 21:54:27 CET 2010 FreeBSD/i386 (x4.osted.lan) (console) login: Kernel page fault with the following non-sleepable locks held: exclusive sleep mutex Softdep Lock (Softdep Lock) r = 0 (0xc0fc6b98) locked @ ufs/ffs/ffs_softdep.c:5330 KDB: stack backtrace: db_trace_self_wrapper(c0ceca96,e97976b4,246,c0de2e34,e9797740,...) at db_trace_self_wrapper+0x26 kdb_backtrace(14d2,3,ffffffff,c0f8d7a4,e9797718,...) at kdb_backtrace+0x2a _witness_debugger(c0cef247,e979772c,4,1,0,...) at _witness_debugger+0x25 witness_warn(5,0,c0d2585e,0,c7c8baa0,...) at witness_warn+0x1fe trap(e97977b8) at trap+0x195 calltrap() at calltrap+0x6 --- trap 0xc, eip = 0xc0b097b1, esp = 0xe97977f8, ebp = 0xe97978a4 --- softdep_setup_freeblocks(c8ff689c,0,0,800,0,...) at softdep_setup_freeblocks+0xc41 ffs_truncate(c8ff5570,0,0,c00,0,...) at ffs_truncate+0x19b9 ufs_inactive(e9797b3c,c0d2a842,c8ff5634,c8ff5634,c8ff5570,...) at ufs_inactive+0x23c VOP_INACTIVE_APV(c0dfde40,e9797b3c,c0cf6fea,92d,c0e18c80,...) at VOP_INACTIVE_APV+0xc5 vinactive(c0dfde40,e9797b70,c0cf6fea,88e,0,...) at vinactive+0xb1 vputx(e9797c24,c095aa1d,c8ff5570,ffffffdf,2,...) at vputx+0x337 vput(c8ff5570,ffffffdf,2,e9797bdc,2841dbd8,...) at vput+0x10 kern_rmdirat(c7cda000,ffffff9c,2841dbd8,0,e9797c50,...) at kern_rmdirat+0x1cd kern_rmdir(c7cda000,2841dbd8,0,e9797c7c,c08ff7e3,...) at kern_rmdir+0x27 rmdir(c7cda000,e9797cec,e9797d28,c0cee516,0,...) at rmdir+0x22 syscallenter(c7cda000,e9797ce4,e9797ce4,0,0,...) at syscallenter+0x263 syscall(e9797d28) at syscall+0x4f Xint0x80_syscall() at Xint0x80_syscall+0x21 --- syscall (137, FreeBSD ELF32, rmdir), eip = 0x280db53b, esp = 0xbfbfeadc, ebp = 0xbfbfeb08 --- Fatal trap 12: page fault while in kernel mode cpuid = 1; apic id = 01 fault virtual address = 0xd00fcbc6 fault code = supervisor read, page not present instruction pointer = 0x20:0xc0b097b1 stack pointer = 0x28:0xe97977f8 frame pointer = 0x28:0xe97978a4 code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, def32 1, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 1639 (rm) [ thread pid 1639 tid 100103 ] Stopped at softdep_setup_freeblocks+0xc41: movl 0xc8(%ebx),%eax db> reset cpu_reset: Restarting BSP cpu_reset_proxy: Stopped CPU 1 (kgdb) bt #0 doadump () at pcpu.h:231 #1 0xc04d5bb9 in db_fncall (dummy1=0xc0b097b1, dummy2=0x0, dummy3=0xffffffff, dummy4=0xe9902498 "¬$\220é") at ../../../ddb/db_command.c:548 #2 0xc04d5fef in db_command (last_cmdp=0xc0e1b27c, cmd_table=0x0, dopager=0x0) at ../../../ddb/db_command.c:445 #3 0xc04d60a4 in db_command_script (command=0xc0e1c188 "call doadump") at ../../../ddb/db_command.c:516 #4 0xc04da2f0 in db_script_exec (scriptname=0xc0e1bae0 "doadump", warnifnotfound=Variable "warnifnotfound" is not available. ) at ../../../ddb/db_script.c:302 #5 0xc04da381 in db_run_cmd (addr=0x1, have_addr=0x0, count=0xc0fe9360, modif=0xe99025d0 "") at ../../../ddb/db_script.c:375 #6 0xc04d5fb1 in db_command (last_cmdp=0xc0e1b27c, cmd_table=0x0, dopager=0x1) at ../../../ddb/db_command.c:445 #7 0xc04d610a in db_command_loop () at ../../../ddb/db_command.c:498 #8 0xc04d802d in db_trap (type=0xc, code=0x0) at ../../../ddb/db_main.c:229 #9 0xc08f203e in kdb_trap (type=0xc, code=0x0, tf=0xe99027b8) at ../../../kern/subr_kdb.c:546 #10 0xc0c05e4f in trap_fatal (frame=0xe99027b8, eva=0xd00fcbc6) at ../../../i386/i386/trap.c:971 #11 0xc0c06373 in trap (frame=0xe99027b8) at ../../../i386/i386/trap.c:361 #12 0xc0bef79c in calltrap () at ../../../i386/i386/exception.s:168 #13 0xc0b097b1 in softdep_setup_freeblocks (ip=0xca3861d0, length=0x0, flags=0x800) at ../../../ufs/ffs/ffs_softdep.c:5435 #14 0xc0aefd19 in ffs_truncate (vp=0xcd01b984, length=0x0, flags=0xc00, cred=0x0, td=0xcdb75000) at ../../../ufs/ffs/ffs_inode.c:326 #15 0xc0b1a5ec in ufs_inactive (ap=0xe9902b3c) at ../../../ufs/ufs/ufs_inode.c:130 #16 0xc0c244d5 in VOP_INACTIVE_APV (vop=0xc0dfe380, a=0xe9902b3c) at vnode_if.c:1863 #17 0xc0957a11 in vinactive (vp=0xcd01b984, td=0xcdb75000) at vnode_if.h:807 #18 0xc09594a7 in vputx (vp=0xcd01b984, func=0x2) at ../../../kern/vfs_subr.c:2232 #19 0xc0959510 in vput (vp=0xcd01b984) at ../../../kern/vfs_subr.c:2259 #20 0xc095aa1d in kern_rmdirat (td=0xcdb75000, fd=0xffffff9c, path=0x2841d538
, pathseg=UIO_USERSPACE) at ../../../kern/vfs_syscalls.c:3879 #21 0xc095aa97 in kern_rmdir (td=0xcdb75000, path=0x2841d538
, pathseg=UIO_USERSPACE) at ../../../kern/vfs_syscalls.c:3819 #22 0xc095aac2 in rmdir (td=0xcdb75000, uap=0xe9902cec) at ../../../kern/vfs_syscalls.c:3812 #23 0xc08ff7e3 in syscallenter (td=0xcdb75000, sa=0xe9902ce4) at ../../../kern/subr_trap.c:318 #24 0xc0c060ef in syscall (frame=0xe9902d28) at ../../../i386/i386/trap.c:1095 #25 0xc0bef801 in Xint0x80_syscall () at ../../../i386/i386/exception.s:266 #26 0x00000033 in ?? () Previous frame inner to this frame (corrupt stack?) (kgdb) f 13 #13 0xc0b097b1 in softdep_setup_freeblocks (ip=0xca3861d0, length=0x0, flags=0x800) at ../../../ufs/ffs/ffs_softdep.c:5435 5435 jwait(&jremref->jr_list); (kgdb) l 5430 */ 5431 while ((jremref = 5432 LIST_FIRST(&dirrem->dm_jremrefhd)) 5433 != NULL) { 5434 stat_jwait_filepage++; 5435 jwait(&jremref->jr_list); 5436 return (0); 5437 } 5438 LIST_REMOVE(dirrem, dm_next); 5439 dirrem->dm_dirinum = pagedep->pd_ino; (kgdb) l *0xc0b097b1 0xc0b097b1 is in softdep_setup_freeblocks (../../../ufs/ffs/ffs_softdep.c:5431). 5426 * If there are any dirrems we wait for 5427 * the journal write to complete and 5428 * then restart the buf scan as the lock 5429 * has been dropped. 5430 */ 5431 while ((jremref = 5432 LIST_FIRST(&dirrem->dm_jremrefhd)) 5433 != NULL) { 5434 stat_jwait_filepage++; 5435 jwait(&jremref->jr_list); (kgdb) $ svn diff -x -p /var/tmp/suj/sys Index: /var/tmp/suj/sys/ufs/ffs/ffs_softdep.c =================================================================== --- /var/tmp/suj/sys/ufs/ffs/ffs_softdep.c (revision 214334) +++ /var/tmp/suj/sys/ufs/ffs/ffs_softdep.c (working copy) @@ -2400,11 +2400,30 @@ journal_space(ump, thresh) int thresh; { struct jblocks *jblocks; + struct mount *mp; + struct fs *fs; int avail; + int suspend; + int inod, blk; jblocks = ump->softdep_jblocks; - if (jblocks == NULL) - return (1); + if (jblocks == NULL) { + fs = ump->um_fs; + mp = UFSTOVFS(ump); + inod = 1024; + blk = 10240; + if ((mp->mnt_kern_flag & MNTK_SUSPEND) != 0) + suspend = (num_inodedep > max_softdeps || + ump->softdep_on_worklist > 20) && + (fs->fs_cstotal.cs_nifree < inod || + fs->fs_cstotal.cs_nbfree < blk); + else + suspend = num_inodedep > max_softdeps || + ump->softdep_on_worklist > max_softdeps / 10 || + fs->fs_cstotal.cs_nifree < inod || + fs->fs_cstotal.cs_nbfree < blk; + return (!suspend); + } /* * We use a tighter restriction here to prevent request_cleanup() * running in threads from running into locks we currently hold. @@ -2431,6 +2450,12 @@ journal_suspend(ump) mp = UFSTOVFS(ump); jblocks = ump->softdep_jblocks; MNT_ILOCK(mp); + if (jblocks == NULL) { + mp->mnt_kern_flag |= MNTK_SUSPEND; + mp->mnt_susp_owner = FIRST_THREAD_IN_PROC(softdepproc); + MNT_IUNLOCK(mp); + return; + } if ((mp->mnt_kern_flag & MNTK_SUSPEND) == 0) { stat_journal_min++; mp->mnt_kern_flag |= MNTK_SUSPEND; @@ -2449,6 +2474,14 @@ journal_unsuspend(struct ufsmount *ump) mp = UFSTOVFS(ump); jblocks = ump->softdep_jblocks; + if (jblocks == NULL && mp->mnt_kern_flag & MNTK_SUSPEND && + journal_space(ump, 0)) { + FREE_LOCK(&lk); + mp->mnt_susp_owner = curthread; + vfs_write_resume(mp); + ACQUIRE_LOCK(&lk); + return (1); + } if (jblocks != NULL && jblocks->jb_suspended && journal_space(ump, jblocks->jb_min)) { jblocks->jb_suspended = 0; @@ -2480,15 +2513,14 @@ softdep_prealloc(vp, waitok) { struct ufsmount *ump; - if (DOINGSUJ(vp) == 0) - return (0); ump = VFSTOUFS(vp->v_mount); ACQUIRE_LOCK(&lk); if (journal_space(ump, 0)) { FREE_LOCK(&lk); return (0); } - stat_journal_low++; + if (DOINGSUJ(vp) == 1) + stat_journal_low++; FREE_LOCK(&lk); if (waitok == MNT_NOWAIT) return (ENOSPC); @@ -10815,11 +10847,9 @@ softdep_slowdown(vp) /* * Check for journal space if needed. */ - if (DOINGSUJ(vp)) { - ump = VFSTOUFS(vp->v_mount); - if (journal_space(ump, 0) == 0) - jlow = 1; - } + ump = VFSTOUFS(vp->v_mount); + if (journal_space(ump, 0) == 0) + jlow = 1; max_softdeps_hard = max_softdeps * 11 / 10; if (num_dirrem < max_softdeps_hard / 2 && num_inodedep < max_softdeps_hard &&