GENERIC HEAD from Aug 18 17:22 UTC, vmcore.71 Snapshot stress test with Konstantins ufs_inode.c patch GDB: no debug ports present KDB: debugger backends: ddb KDB: current backend: ddb Copyright (c) 1992-2006 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 7.0-CURRENT #2: Fri Aug 18 19:43:37 CEST 2006 pho@crashbox.osted.lan:/usr/src/sys/i386/compile/PHO WARNING: WITNESS option enabled, expect reduced performance. Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: Intel(R) XEON(TM) CPU 1.80GHz (1799.81-MHz 686-class CPU) Origin = "GenuineIntel" Id = 0xf24 Stepping = 4 Features=0x3febfbff<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> Logical CPUs per core: 2 real memory = 1073676288 (1023 MB) avail memory = 1033048064 (985 MB) : Trying to mount root from ufs:/dev/ad0s1a WARNING: / was not properly dismounted fxp0: link state changed to UP swap_pager: indefinite wait buffer: bufobj: 0, blkno: 30056, size: 32768 free ifree inode /tmp/27826 had -2068624 blocks node /tmp/27825 had -2068624 blocks handle_workitem_freeblocks: block count handle_workitem_freeblocks: block count freebsd4_sigreturn: eflags = 0x0 freebsd4_sigreturn: eflags = 0x0 : freebsd4_sigreturn: eflags = 0x0 ffrreeee iinnoodde e/ t/mtp/m27p8/2267 8h2a5d h-a2d0 6-82602648 b6l2oc4k sbl ocks /tmp: mount pending error: blocks 24823488 files 0 /tmp: mount pending error: blocks 24823488 files 0 /tmp: mount pending error: blocks 24823488 files 0 /tmp: mount pending error: blocks 24823488 files 0 /tmp: unmount pending error: blocks 24823488 files 0 acd0: FAILURE - READ_TRACK_INFO ILLEGAL REQUEST asc=0x24 ascq=0x00 sks=0x40 0x00 0x02 acd0: FAILURE - READ_BIG ILLEGAL REQUEST asc=0x64 ascq=0x00 fsync: giving up on dirty 0xc4037b2c: tag devfs, type VCHR usecount 1, writecount 0, refcount 519 mountedhere 0xc3f9b300 flags () v_object 0xc40c5528 ref 0 pages 2062 lock type devfs: EXCL (count 1) by thread 0xc7423000 (pid 62362) dev ad0s1e g_vfs_done():md0[READ(offset=65536, length=8192)]error = 5 fsync: giving up on dirty 0xc4037b2c: tag devfs, type VCHR usecount 1, writecount 0, refcount 1226 mountedhere 0xc3f9b300 flags () v_object 0xc40c5528 ref 0 pages 4894 lock type devfs: EXCL (count 1) by thread 0xc4be16c0 (pid 62984) dev ad0s1e fsync: giving up on dirty 0xc4037b2c: tag devfs, type VCHR usecount 1, writecount 0, refcount 1225 mountedhere 0xc3f9b300 flags () v_object 0xc40c5528 ref 0 pages 4890 lock type devfs: EXCL (count 1) by thread 0xc4be16c0 (pid 62984) dev ad0s1e g_vfs_done():md0[READ(offset=65536, length=8192)]error = 5 fsync: giving up on dirty 0xc4037b2c: tag devfs, type VCHR usecount 1, writecount 0, refcount 73 mountedhere 0xc3f9b300 flags () v_object 0xc40c5528 ref 0 pages 278 lock type devfs: EXCL (count 1) by thread 0xc4af7a20 (pid 64615) dev ad0s1e g_vfs_done():md0[READ(offset=65536, length=8192)]error = 5 ssswwwaaappp__p_apgpaageegrerr:: : ii ndienfndideniftee iwnfiatieint i wtbea iuwfta fietbr u: bbufuffffoeebrj:: r0: , bbublfkonobu:j f:9 o06b1j9,: ,b0,l blkknnoo: 9 :6s 2i87z,e :9s3iz1 ,e4 :0 946s096iz e: 24576 fsync: giving up on dirty 0xc4037b2c: tag devfs, type VCHR usecount 1, writecount 0, refcount 1558 mountedhere 0xc3f9b300 flags () v_object 0xc40c5528 ref 0 pages 6218 lock type devfs: EXCL (count 1) by thread 0xc726da20 (pid 68587) dev ad0s1e g_vfs_done():md0[READ(offset=65536, length=8192)]error = 5 panic: snapacct_ufs2: bad block cpuid = 1 KDB: enter: panic [thread pid 69029 tid 100401 ] Stopped at kdb_enter+0x2b: nop db> where Tracing pid 69029 tid 100401 td 0xc5173a20 kdb_enter(c091d9db) at kdb_enter+0x2b panic(c0935a53,c7592840,d7ebf6c8,c,0,...) at panic+0x14b snapacct_ufs2(c58ea820,c4e361f8,c4e365d0,db934000,c,0,1) at snapacct_ufs2+0x119 fullacct_ufs2(c58ea820,c4e34000,c4e365d0,db934000,c,0,1,d7e8f378,ddda4000,c4e34000,4000,4000,c09c4b20,2) at fullacct_ufs2+0x23 indiracct_ufs2(c58ea820,c531ab2c,0,883c0,0,fffffff4,ffffffff,c,0,4ba,0,1,0,db934000,c07cba80,1) at indiracct_ufs2+0x1ab expunge_ufs2(c58ea820,c5d95948,db934000,c07cba80,1) at expunge_ufs2+0x451 ffs_snapshot(c47d3798,c3d63a60,c3d63a60,c6fa8600,c4037b2c,...) at ffs_snapshot+0x1633 ffs_mount(c47d3798,c5173a20,20000000,201300,0,...) at ffs_mount+0x927 vfs_domount(c5173a20,c3f66540,c3f668b0,1211300,c47b1820,c0a0be88,0,c0927577,2b0) at vfs_domount+0x554 vfs_donmount(c5173a20,1211300,e6946bac) at vfs_donmount+0x414 kernel_mount(c3f66bb0,1211300,bfbfecb0,0,0,...) at kernel_mount+0x6d ffs_cmount(c3f66bb0,bfbfe4d0,1211300,c5173a20,c09da4a0,...) at ffs_cmount+0x5d mount(c5173a20,e6946d04) at mount+0x15e syscall(3b,3b,3b,2816772c,bfbfe470,...) at syscall+0x256 Xint0x80_syscall() at Xint0x80_syscall+0x1f --- syscall (21, FreeBSD ELF32, mount), eip = 0x280c96b3, esp = 0xbfbfe43c, ebp = 0xbfbfeb38 --- db> show alllocks Process 69029 (mksnap_ffs) thread 0xc5173a20 (100401) exclusive sleep mutex Giant r = 1 (0xc0a0be88) locked @ kern/vfs_mount.c:688 Process 68970 (tcp) thread 0xc4afc000 (100144) exclusive sleep mutex so_snd r = 0 (0xc411d9f4) locked @ kern/uipc_sockbuf.c:534 exclusive sleep mutex inp (tcpinp) r = 0 (0xc4cd9720) locked @ netinet/tcp_usrreq.c:801 db> show lockedvnods Locked vnodes 0xc531ab2c: tag ufs, type VREG usecount 1, writecount 1, refcount 812 mountedhere 0 flags () v_object 0xc6192b40 ref 0 pages 3236 lock type ufs: EXCL (count 1) by thread 0xc5173a20 (pid 69029) ino 117866, on dev ad0s1e 0xc58ea820: tag ufs, type VREG usecount 1, writecount 0, refcount 82 mountedhere 0 flags () lock type ufs: EXCL (count 1) by thread 0xc5173a20 (pid 69029) ino 211968, on dev ad0s1e db> ps pid ppid pgrp uid state wmesg wchan cmd 69029 57409 57409 0 R+ CPU 1 mksnap_ffs 69028 68929 58566 1001 S+ sbwait 0xc4d013a0 mkfifo 68982 68909 58566 1001 S+ sbwait 0xc4ce0e00 mkfifo 68980 68907 58566 1001 R+ mkfifo 68978 68913 58566 1001 S+ sbwait 0xc4cfa254 mkfifo 68973 68945 58566 1001 R+ tcp 68972 68948 58566 1001 R+ tcp 68971 68947 58566 1001 R+ tcp 68970 68943 58566 1001 R+ tcp 68969 68950 58566 1001 R+ tcp 68968 68939 58566 1001 R+ tcp 68967 68951 58566 1001 R+ tcp 68965 68911 58566 1001 R+ mkfifo 68963 68926 58566 1001 S+ sbwait 0xc4ce1254 mkfifo 68962 68928 58566 1001 S+ sbwait 0xc4cf03a0 mkfifo 68958 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68957 68927 58566 1001 SL+ swread 0xc26003b0 swap 68956 68927 58566 1001 R+ swap 68955 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68954 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68953 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68952 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68951 68931 58566 1001 S+ sbwait 0xc4cf009c tcp 68950 68931 58566 1001 S+ sbwait 0xc4ce0c48 tcp 68949 68927 58566 1001 SL+ swread 0xc28f30d8 swap 68948 68931 58566 1001 S+ sbwait 0xc411d1e8 tcp 68947 68931 58566 1001 S+ sbwait 0xc4cec480 tcp 68946 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68945 68931 58566 1001 S+ sbwait 0xc4d0509c tcp 68943 68931 58566 1001 S+ sbwait 0xc59d5718 tcp 68942 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68940 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68939 68931 58566 1001 S+ sbwait 0xc59d5afc tcp 68938 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68937 68927 58566 1001 SL+ swread 0xc2075cc8 swap 68936 68927 58566 1001 SL+ pfault 0xc0a66558 swap 68935 68927 58566 1001 R+ swap 68932 68902 58566 1001 SW+ suspfs 0xc47d3804 mkfifo 68931 68891 58566 1001 SW+ wait 0xc4792d38 tcp 68929 68902 58566 1001 R+ mkfifo 68928 68902 58566 1001 R+ mkfifo 68927 68884 58566 1001 SW+ wait 0xc478e69c swap 68926 68902 58566 1001 R+ CPU 3 mkfifo 68925 68902 58566 1001 SW+ suspfs 0xc47d3804 mkfifo 68924 68902 58566 1001 SW+ suspfs 0xc47d3804 mkfifo 68923 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68922 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68921 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68920 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68919 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68918 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68916 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68915 68902 58566 1001 SW+ suspfs 0xc47d3804 mkfifo 68914 68904 58566 1001 SW+ suspfs 0xc47d3804 rw 68913 68902 58566 1001 R+ mkfifo 68912 68902 58566 1001 SW+ suspfs 0xc47d3804 mkfifo 68911 68902 58566 1001 S+ sbwait 0xc4cfa5cc mkfifo 68909 68902 58566 1001 R+ mkfifo 68907 68902 58566 1001 S+ sbwait 0xc424dc48 mkfifo 68905 68886 58566 1001 R+ mkdir 68904 68888 58566 1001 SW+ wait 0xc49b48d0 rw 68902 68894 58566 1001 SW+ wait 0xc649c69c mkfifo 68900 58573 58566 1001 S+ nanslp 0xc0a0c684 mmap 68894 58573 58566 1001 S+ nanslp 0xc0a0c684 mkfifo 68891 58573 58566 1001 S+ nanslp 0xc0a0c684 tcp 68888 58573 58566 1001 S+ nanslp 0xc0a0c684 rw 68886 58573 58566 1001 S+ nanslp 0xc0a0c684 mkdir 68884 58573 58566 1001 S+ nanslp 0xc0a0c684 swap 67032 0 0 0 SL mdwait 0xc6451000 [md4] 67025 0 0 0 SL mdwait 0xc65e8800 [md3] 67018 0 0 0 SL mdwait 0xc55c4800 [md2] 67011 0 0 0 SL mdwait 0xc5381000 [md1] 58573 58572 58566 1001 SW+ wait 0xc495e000 run 58572 58571 58566 1001 SW+ wait 0xc47b58d0 run 58571 58566 58566 1001 S+ nanslp 0xc0a0c684 run 58566 992 58566 1001 SW+ wait 0xc49b78d0 sh 57409 57404 57409 0 SW+ wait 0xc54bc234 sh 57404 57401 57404 0 SW+ wait 0xc4a5a234 bash 57401 57400 57401 0 SW+ pause 0xc54bc904 csh 57400 57394 57400 1001 SW+ wait 0xc54bcd38 su 57394 57393 57394 1001 SWs+ wait 0xc4663d38 bash 57393 57391 57391 1001 SW select 0xc0a58b3c sshd 57391 845 57391 0 SWs sbwait 0xc59d5864 sshd 1887 1020 1887 1001 S+ select 0xc0a58b3c top 1020 1019 1020 1001 SWs+ wait 0xc4041b04 bash 1019 1017 1017 1001 S select 0xc0a58b3c sshd 1017 845 1017 0 SWs sbwait 0xc4673480 sshd 992 991 992 1001 SWs+ wait 0xc4042d38 bash 991 989 989 1001 SW select 0xc0a58b3c sshd 989 845 989 0 SWs sbwait 0xc412d5cc sshd 988 1 988 0 SWs+ ttyin 0xc3df3810 getty 987 1 987 0 SWs+ ttyin 0xc3dfb810 getty 986 1 986 0 SWs+ ttyin 0xc3dfa810 getty 985 1 985 0 SWs+ ttyin 0xc3dfa010 getty 984 1 984 0 SWs+ ttyin 0xc3df5c10 getty 983 1 983 0 SWs+ ttyin 0xc3dfbc10 getty 982 1 982 0 SWs+ ttyin 0xc3dfc010 getty 981 1 981 0 SWs+ ttyin 0xc3dfac10 getty 964 1 964 0 SWs select 0xc0a58b3c inetd 935 1 935 0 SWs select 0xc0a58b3c moused 918 1 918 0 Ss nanslp 0xc0a0c684 watchdogd 864 1 864 0 Ss nanslp 0xc0a0c684 cron 858 1 858 25 SWs pause 0xc40f06d0 sendmail 852 1 852 0 Ss select 0xc0a58b3c sendmail 845 1 845 0 SWs select 0xc0a58b3c sshd 825 1 825 0 Ss select 0xc0a58b3c ntpd 767 763 763 0 SW - 0xc3f61000 nfsd 766 763 763 0 SW - 0xc3f61c00 nfsd 765 763 763 0 SW - 0xc3d76c00 nfsd 764 763 763 0 SW - 0xc3fb0800 nfsd 763 1 763 0 SWs select 0xc0a58b3c nfsd 761 1 761 0 SWs select 0xc0a58b3c mountd 701 1 701 0 SWs select 0xc0a58b3c rpcbind 678 1 678 0 SWs select 0xc0a58b3c syslogd 568 1 568 0 SWs select 0xc0a58b3c devd 42 0 0 0 SL - 0xe4364cfc [schedcpu] 41 0 0 0 SL sdflush 0xc0a65f20 [softdepflush] 40 0 0 0 SL vlruwt 0xc3f6dd38 [vnlru] 39 0 0 0 SL syncer 0xc0a0c450 [syncer] 38 0 0 0 SL psleep 0xc0a58fb4 [bufdaemon] 37 0 0 0 RL [pagezero] 36 0 0 0 SL psleep 0xc0a66780 [vmdaemon] 35 0 0 0 RL CPU 2 [pagedaemon] 34 0 0 0 WL [irq7: ppc0] 33 0 0 0 SL - 0xc3d7603c [fdc0] 32 0 0 0 WL [swi0: sio] 31 0 0 0 WL [irq12: psm0] 30 0 0 0 WL [irq1: atkbd0] 29 0 0 0 WL [irq15: ata1] 28 0 0 0 WL [irq14: ata0] 27 0 0 0 WL [irq17: fxp0] 26 0 0 0 SL usbtsk 0xc0a09c04 [usbtask] 25 0 0 0 SL usbevt 0xc3d67210 [usb0] 24 0 0 0 WL [irq16: uhci0] 23 0 0 0 SL - 0xc3d51480 [em0 taskq] 22 0 0 0 WL [irq9: acpi0] 9 0 0 0 SL - 0xc3d40980 [thread taskq] 21 0 0 0 WL [swi6: Giant taskq] 20 0 0 0 WL [swi6: task queue] 8 0 0 0 SL - 0xc3c7b280 [acpi_task_2] 7 0 0 0 SL - 0xc3c7b280 [acpi_task_1] 6 0 0 0 SL - 0xc3c7b280 [acpi_task_0] 5 0 0 0 SL - 0xc3c7b300 [kqueue taskq] 19 0 0 0 WL [swi2: cambio] 18 0 0 0 WL [swi5: +] 17 0 0 0 SL - 0xc0a07840 [yarrow] 4 0 0 0 SL - 0xc0a0a3bc [g_down] 3 0 0 0 RL [g_up] 2 0 0 0 SL - 0xc0a0a3b0 [g_event] 16 0 0 0 WL [swi3: vm] 15 0 0 0 RL CPU 0 [swi4: clock sio] 14 0 0 0 WL [swi1: net] 13 0 0 0 RL [idle: cpu0] 12 0 0 0 RL [idle: cpu1] 11 0 0 0 RL [idle: cpu2] 10 0 0 0 RL [idle: cpu3] 1 0 1 0 SLs wait 0xc3c32000 [init] 0 0 0 0 WLs [swapper] 68903 68900 58566 1001 Z+ mmap 68917 68904 58566 1001 Z+ rw 68898 58573 58566 1001 Z+ thr2 68887 58573 58566 1001 Z+ thr1 68892 58573 58566 1001 Z+ udp 68901 58573 58566 1001 Z+ socket 68897 58573 58566 1001 Z+ symlink 68890 58573 58566 1001 Z+ sysctl 68895 58573 58566 1001 Z+ shm 68893 58573 58566 1001 Z+ pty 68899 58573 58566 1001 Z+ badcode 68885 58573 58566 1001 Z+ creat 68896 58573 58566 1001 Z+ lockf 68889 58573 58566 1001 Z+ syscall db> call print_uptime Uptime: 1d2h59m26s = 0x4 db> call doadump Physical memory: 1007 MB Dumping 203 MB: 188 172 156 140 124 108 92 76 60 44 28 12 Dump complete = 0xf db> reset cpu_reset: Restarting BSP cpu_reset_proxy: Stopped CPU 1 GDB: no debug ports present (kgdb) f 10 #10 0xc07cbbe9 in snapacct_ufs2 (vp=0xc58ea820, oldblkp=0xc4e361f8, lastblkp=0xc4e365d0, fs=0xdb934000, lblkno=0xc, expungetype=0x1) at ../../../ufs/ffs/ffs_snapshot.c:1469 1469 panic("snapacct_ufs2: bad block"); (kgdb) l 1464 if (expungetype == BLK_SNAP && *blkp == BLK_NOCOPY) { 1465 if (lbn >= NDADDR) 1466 brelse(ibp); 1467 } else { 1468 if (*blkp != 0) 1469 panic("snapacct_ufs2: bad block"); 1470 *blkp = expungetype; 1471 if (lbn >= NDADDR) 1472 bdwrite(ibp); 1473 } (kgdb) info loc ip = (struct inode *) 0xc7592840 blkno = Unhandled dwarf expression opcode 0x93 (kgdb) p *ip $1 = {i_nextsnap = {tqe_next = 0x0, tqe_prev = 0x0}, i_vnode = 0xc58ea820, i_ump = 0xc6fa8600, i_flag = 0x6, i_dev = 0xc3f9b300, i_number = 0x33c00, i_effnlink = 0x1, i_fs = 0xc6ec4000, i_dquot = {0x0, 0x0}, i_modrev = 0x17b840e300eaa, i_lockf = 0x0, i_count = 0x0, i_endoff = 0x0, i_diroff = 0x0, i_offset = 0x0, i_ino = 0x0, i_reclen = 0x0, i_un = {dirhash = 0x0, snapblklist = 0x0}, i_ea_area = 0x0, i_ea_len = 0x0, i_ea_error = 0x0, i_mode = 0x8100, i_nlink = 0x1, i_size = 0x7d000000, i_flags = 0x200000, i_gen = 0xfffffffffa5da25a, i_uid = 0x0, i_gid = 0x5, dinode_u = {din1 = 0xc5cfb900, din2 = 0xc5cfb900}} (kgdb) p *vp $2 = {v_type = VREG, v_tag = 0xc0925ba1 "ufs", v_op = 0xc09da7c0, v_data = 0xc7592840, v_mount = 0xc47d3798, v_nmntvnodes = { tqe_next = 0xc7c11e38, tqe_prev = 0xc5112320}, v_un = {vu_mount = 0x0, vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, le_prev = 0xc3e1a81c}, v_hash = 0x33c00, v_cache_src = {lh_first = 0x0}, v_cache_dst = { tqh_first = 0x0, tqh_last = 0xc58ea850}, v_dd = 0x0, v_cstart = 0x0, v_lasta = 0x0, v_lastw = 0x0, v_clen = 0x0, v_lock = { lk_interlock = 0xc0a0bd38, lk_flags = 0x40040, lk_sharecount = 0x0, lk_waitcount = 0x0, lk_exclusivecount = 0x1, lk_prio = 0x50, lk_wmesg = 0xc0925ba1 "ufs", lk_timo = 0x33, lk_lockholder = 0xc5173a20, lk_newlock = 0x0}, v_interlock = {mtx_object = { lo_name = 0xc0921d63 "vnode interlock", lo_type = 0xc0921d63 "vnode interlock", lo_flags = 0x1030000, lo_witness_data = { lod_list = {stqe_next = 0xc0a1be30}, lod_witness = 0xc0a1be30}}, mtx_lock = 0x4, mtx_recurse = 0x0}, v_vnlock = 0xc58ea878, v_holdcnt = 0x52, v_usecount = 0x1, v_iflag = 0x0, v_vflag = 0x0, v_writecount = 0x0, v_freelist = {tqe_next = 0x0, tqe_prev = 0x0}, v_bufobj = {bo_mtx = 0xc58ea89c, bo_clean = {bv_hd = {tqh_first = 0xd7c97bb0, tqh_last = 0xd7cf48c0}, bv_root = 0xd7ca14e0, bv_cnt = 0x36}, bo_dirty = {bv_hd = {tqh_first = 0xd7ebf6c8, tqh_last = 0xd7d6da70}, bv_root = 0xd7ebf6c8, bv_cnt = 0x1b}, bo_numoutput = 0x0, bo_flag = 0x1, bo_ops = 0xc09cde64, bo_bsize = 0x4000, bo_object = 0x0, bo_synclist = {le_next = 0xc40c7ce4, le_prev = 0xc3e07980}, bo_private = 0xc58ea820, __bo_vnode = 0xc58ea820}, v_pollinfo = 0x0, v_label = 0x0}