Re: another one: panic: ffs_blkfree: freeing free block

On Thu, May 01, 2003 at 11:32:20PM -0600, M. Warner Losh wrote:
> In message: <20030502035426.GA65366_at_athlon.pn.xcllnt.net>
>             Marcel Moolenaar <marcel_at_xcllnt.net> writes:
> : login: dev = da0p7, block = 600688, fs = /q
> : panic: ffs_blkfree: freeing free block
> 
> I get this all the time on my laptop, and have on and off, for the
> past two weeks.  I posted a traceback, and a me too on a couple of
> other tracebacks that matched mine.  This is the first bug to get me
> really annoyed in quite some time because it is a random killer.

I get it reliably between 60 and 80 seconds after boot. I even
compile new kernels on the disk on which this happens and it's
always the same block. A kernel that is insensitive to all this
is:
FreeBSD 5.0-CURRENT #3: Sat Apr  5 19:12:36 PST 2003
    root_at_pluto2.freebsd.org:/q/src/sys/ia64/compile/PLUTO2

Kernel built in the last day are sure lottery winners:

dev = da0p7, block = 600688, fs = /q
panic: ffs_blkfree: freeing free block
db> trace
Debugger(0xe000000000a2ee28, 0xe0000000006febb0) at Debugger+0x31
panic(0xe000000000a3a210, 0xe0000000027be4f8, 0x92a70, 0xe00000001501c0d4) at panic+0x1b0
ffs_blkfree(0xe00000001501c000, 0xe000000024f42c90, 0x92a70, 0x4000, 0xa000000019dacc28) at ffs_blkfree+0x9f0
indir_trunc(0xe00000003088ad00, 0x92a70, 0x0, 0x0, 0xe000000001f5b4e0) at indir_trunc+0x620
handle_workitem_freeblocks(0xe00000003088ad00, 0x0, 0x0, 0x8cc50, 0xe00000003088ad08) at handle_workitem_freeblocks+0x3a0
process_worklist_item(0x0, 0x0, 0xe0000000027cf400, 0xe00000003088ad00) at process_worklist_item+0x4a0
softdep_process_worklist(0x0, 0xe000000000b51294) at softdep_process_worklist+0x230
sched_sync(0xe000000000d00000, 0x0, 0xe000000032094a00, 0xe000000000b4d500, 0xe000000000b4d500) at sched_sync+0x7e0
fork_exit(0xe000000000a0d598, 0x0, 0xe000000001f5b580, 0xe000000000d00000) at fork_exit+0x1b0
fork_trampoline(0xe000000000a0d598, 0x0, 0xe000000001f5b580) at fork_trampoline+0x30

Details of the filesystem (somehow it smells like UFS2):

/dev/da0p7 on /q (ufs, NFS exported, local, nodev, nosuid, soft-updates)

magic   19540119 (UFS2) time    Thu May  1 20:55:23 2003
superblock location     65536   id      [ 3e38911b 3f1618c6 ]
ncg     151     size    14143888        blocks  13696886
bsize   16384   shift   14      mask    0xffffc000
fsize   2048    shift   11      mask    0xfffff800
frag    8       shift   3       fsbtodb 2
minfree 8%      optim   time    symlinklen 120
maxbsize 16384  maxbpg  2048    maxcontig 8     contigsumsize 8
nbfree  1311207 ndir    26792   nifree  3286671 nffree  143619
bpg     11758   fpg     94064   ipg     23552
nindir  2048    inopb   64      maxfilesize     140806241583103
sbsize  2048    cgsize  16384   csaddr  3000    cssize  4096
sblkno  40      cblkno  48      iblkno  56      dblkno  3000
cgrotor 12      fmod    0       ronly   0       clean   0
flags   soft-updates 
fsmnt   /q
volname         swuid   0

I'm currently added some printfs to get a feel for the problem:

==== //depot/projects/ia64/sys/ufs/ffs/ffs_softdep.c#27 - /q/scratch/marcel/ia64/sys/ufs/ffs/ffs_softdep.c ====
_at__at_ -2537,6 +2537,8 _at__at_
 	ufs_lbn_t lbn;
 	ufs2_daddr_t *countp;
 {
+	static int visit = 0;
+
 	struct buf *bp;
 	struct fs *fs;
 	struct worklist *wk;
_at__at_ -2600,6 +2602,8 _at__at_
 		bap2 = (ufs2_daddr_t *)bp->b_data;
 	}
 	nblocks = btodb(fs->fs_bsize);
+	printf("XXX: %p: visit=%d, nblocks=%ld, NINDIR(fs)=%ld\n", fs,
+	    ++visit, (long)nblocks, (long)(NINDIR(fs)));
 	for (i = NINDIR(fs) - 1; i >= 0; i--) {
 		if (ufs1fmt)
 			nb = bap1[i];
_at__at_ -2612,6 +2616,8 _at__at_
 			     level - 1, lbn + (i * lbnadd), countp)) != 0)
 				allerror = error;
 		}
+		if (nb == 600688)
+			printf("XXX: %ld: i=%d\n", (long)nb, i);
 		ffs_blkfree(fs, freeblks->fb_devvp, nb, fs->fs_bsize,
 		    freeblks->fb_previousinum);
 		fs->fs_pendingblocks -= nblocks;


Which gives:

XXX: 0xe00000001501c000: visit=1, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=2, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=3, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=4, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=5, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=6, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=7, nblocks=32, NINDIR(fs)=2048
XXX: 0xe00000001501c000: visit=8, nblocks=32, NINDIR(fs)=2048
XXX: 600688: i=2

And yes, it's keeping me from other important work as well :-(

--
 Marcel Moolenaar	  USPA: A-39004		 marcel_at_xcllnt.net