Date: Wed, 21 Feb 2001 09:03:26 -0500 From: "James F. Hranicky" <jfh@cise.ufl.edu> To: freebsd-fs@FreeBSD.ORG Subject: Re: Softupdates umount bug? Or vinum problem? Message-ID: <20010221140326.8AF89D80A@mail.cise.ufl.edu> In-Reply-To: Message from Poul-Henning Kamp <phk@critter.freebsd.dk> of "Tue, 20 Feb 2001 21:56:46 %2B0100." <95034.982702606@critter>
next in thread | previous in thread | raw e-mail | index | archive | help
Poul-Henning Kamp <phk@critter.freebsd.dk> wrote:
>
> You may want to try to look at the commit mckusic did this
> morning/night/whatever, it looked like it had something to
> do with this problem.
Is there a time frame for either of these patches making their
way into -stable (I don't see either going into releng_4) ?
Or can anyone suggest a workaround (e.g., run sync 10 times
before umounting) ? Or, should I just disable softupdates for
now (bummer)?
I'm willing to do more testing and work with anyone who's interested.
BTW, all my testing has been on 4.2-STABLE, with latest crash
occuring on this rev:
FreeBSD 4.2-STABLE #1: Thu Feb 15 11:31:58 EST 2001
I'm including all the info I mentioned in my first post here.
Jim
--------------------------------------------------------------------
Trace of 1st crash:
-------------------
db> trace
Debugger(c0338723) at Debugger+0x34
panic(c0358bc7,ce22b400,d6f42d74,c02ad4dc,c7606800) at panic+0x70
ufs_dirbad(c7606800,400,c0358b70,0,d6f9b240) at ufs_dirbad+0x3a
ufs_lookup(d6f42db0,d6f42dc4,c01bf226,d6f42db0,d6f9b240) at ufs_lookup+0x260
ufs_vnoperate(d6f42db0,d6f9b240,d6e3d403,d6f42eac,c02b2715) at ufs_vnoperate+0x15
vfs_cache_lookup(d6f42e08,d6f42e18,c01c1fc4,d6f42e08,d6f9b240) at vfs_cache_lookup+0x28a
ufs_vnoperate(d6f42e08,d6f9b240,c74bf600,d6f42eac,d6e6bbe0) at ufs_vnoperate+0x15
lookup(d6f42e84,d6e6bbe0,d6e6bbe0,d6f42f80,d6e6bbe0) at lookup+0x290
namei(d6f42e84,d6e6bbe0,2,d6f42f80,809c340) at namei+0x178
stat(d6e6bbe0,d6f42f80,809c348,809e080,809c300) at stat+0x41
syscall2(2f,2f,2f,809c300,809e080) at syscall2+0x1f1
Xint0x80_syscall() at Xint0x80_syscall+0x25
Unfortunately, I don't have a dump.
Trace of 2nd crash + shell commands:
------------------------------------
<root@dogwood:~> # mount /export/mail
<root@dogwood:~> # mount
/dev/da0s1a on / (ufs, local)
/dev/da0s1f on /private (ufs, local)
/dev/da0s1e on /var (ufs, local)
procfs on /proc (procfs, local)
/dev/vinum/mail on /export/mail (ufs, NFS exported, local, soft-updates)
<root@dogwood:~> # tunefs -p /export/mail
tunefs: soft updates: (-n) enabled
tunefs: maximum contiguous block count: (-a) 15
tunefs: rotational delay between contiguous blocks: (-d) 0 ms
tunefs: maximum blocks per file in a cylinder group: (-e) 2048
tunefs: minimum percentage of free space: (-m) 1%
tunefs: optimization preference: (-o) time
tunefs: should optimize for space with minfree < 8%
[ Seeing if I could optimize for time with 1% minfree -- no. ]
<root@dogwood:~> # time /var/tmp/make_imap_files
/cise/mail/mhspool/aa1 done
[ crash ]
db> trace
Debugger(c033bf63) at Debugger+0x34
panic(c035a1e1,c035a1c0,41c0,7ada80,c70618d4) at panic+0x70
ffs_valloc(d724ad00,41ed,c732c600,d6f01d08,d6f01e70) at ffs_valloc+0xf8
ufs_mkdir(d6f01e70,d6f01f2c,c01ccc9a,d6f01e70,d6e58d40) at ufs_mkdir+0x85
ufs_vnoperate(d6f01e70,d6e58d40,2,d6f01f80,c0374780) at ufs_vnoperate+0x15
mkdir(d6e58d40,d6f01f80,8099030,4,8099037) at mkdir+0x162
syscall2(2f,2f,2f,8099037,4) at syscall2+0x1f1
Xint0x80_syscall() at Xint0x80_syscall+0x25
Here's the make_imap_script (I'll be running uw-imapd with mods
for MH mailboxes):
#/bin/sh
ypcat passwd | grep tcsh | perl -nle 'print "$1 $2" if (m,^(\S+):\S+:(\d+:\d+):,)' | \
sort -u | egrep '^[abc]' |
while read user ugid ; do
mkdir -p $top/$user/Mail/inbox
#
# Tar about 1000 files into the user's mailbox for testing purposes
#
# Approx time to untar:
#
# Vol with two 1 drive plexes: 2-3 seconds
# Vol with two 2 drive striped plexes: 1 second
#
( cd $top/$user/Mail/inbox ; tar xfBp /tmp/c.tar )
/usr/bin/printf '%s\n%s\n%s\n' 'Path: Mail' 'draft-folder: drafts' 'unseen-sequence: unseen ' > \
$top/$user/.mh_profile ;
/usr/sbin/chown -R $ugid $top/$user
/bin/chmod -R go-rwx $top/$user
echo $top/$user done
done
This runs for about 2300 users, generating quite a bit of fs activity.
In this case, I'm only creating the accounts beginning with [abc]
though...
Info from the dump of the second crash:
---------------------------------------
<root@palm:/usr/obj/private/freebsd-src/src/sys/CISEKERN> # gdb -k kernel.debug /var/crash/vmcore.1
GNU gdb 4.18
[ ... ]
IdlePTD 4567040
initial pcb at 3a6000
panicstr: ffs_valloc: dup alloc
panic messages:
---
panic: ffs_valloc: dup alloc
syncing disks... 47 15 7 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3 3
giving up on 2 buffers
Uptime: 9h59m26s
dumping to dev #da/0x20001, offset 1572992
dump 255 254 253 252 251 250 249 248 247 246 245 244 243 242 241 240 239 238 237 236 235 234 233 232 231 230 229 228 227 226 225 224 223 222 221 220 219 218 217 216 215 214 213 212 211 210 209 208 207 206 205 204 203 202 201 200 199 198 197 196 195 194 193 192 191 190 189 188 187 186 185 184 183 182 181 180 179 178 177 176 175 174 173 172 171 170 169 168 167 166 165 164 163 162 161 160 159 158 157 156 155 154 153 152 151 150 149 148 147 146 145 144 143 142 141 140 139 138 137 136 135 134 133 132 131 130 129 128 127 126 125 124 123 122 121 120 119 118 117 116 115 114 113 112 111 110 109 108 107 106 105 104 103 102 101 100 99 98 97 96 95 94 93 92 91 90 89 88 87 86 85 84 83 82 81 80 79 78 77 76 75 74 73 72 71 70 69 68 67 66 65 64 63 62 61 60 59 58 57 56 55 54 53 52 51 50 49 48 47 46 45 44 43 42 41 40 39 38 37 36 35 34 33 32 31 30 29 28 27 26 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0
---
#0 dumpsys () at /private/freebsd-src/src/sys/kern/kern_shutdown.c:469
469 if (dumping++) {
(kgdb) where
#0 dumpsys () at /private/freebsd-src/src/sys/kern/kern_shutdown.c:469
#1 0xc019bd63 in boot (howto=256) at /private/freebsd-src/src/sys/kern/kern_shutdown.c:309
#2 0xc019c0f9 in panic (fmt=0xc035a1e1 "ffs_valloc: dup alloc")
at /private/freebsd-src/src/sys/kern/kern_shutdown.c:556
#3 0xc02a4054 in ffs_valloc (pvp=0xd724ad00, mode=16877, cred=0xc732c600, vpp=0xd6f01d08)
at /private/freebsd-src/src/sys/ufs/ffs/ffs_alloc.c:609
#4 0xc02b5c25 in ufs_mkdir (ap=0xd6f01e70) at /private/freebsd-src/src/sys/ufs/ufs/ufs_vnops.c:1310
#5 0xc02b6cbd in ufs_vnoperate (ap=0xd6f01e70) at /private/freebsd-src/src/sys/ufs/ufs/ufs_vnops.c:2287
#6 0xc01ccc9a in mkdir (p=0xd6e58d40, uap=0xd6f01f80) at vnode_if.h:653
#7 0xc03004ed in syscall2 (frame={tf_fs = 47, tf_es = 47, tf_ds = 47, tf_edi = 134844471, tf_esi = 4,
tf_ebp = -1077937700, tf_isp = -688906284, tf_ebx = 134844464, tf_edx = 134844464, tf_ecx = 4,
tf_eax = 136, tf_trapno = 7, tf_err = 2, tf_eip = 134605108, tf_cs = 31, tf_eflags = 518,
tf_esp = -1077938064, tf_ss = 47}) at /private/freebsd-src/src/sys/i386/i386/trap.c:1150
#8 0xc02f1ca5 in Xint0x80_syscall ()
#9 0x8050a1d in ?? ()
#10 0x8052da2 in ?? ()
#11 0x8048135 in ?? ()
(kgdb) up
#1 0xc019bd63 in boot (howto=256) at /private/freebsd-src/src/sys/kern/kern_shutdown.c:309
309 dumpsys();
(kgdb)
#2 0xc019c0f9 in panic (fmt=0xc035a1e1 "ffs_valloc: dup alloc")
at /private/freebsd-src/src/sys/kern/kern_shutdown.c:556
556 boot(bootopt);
(kgdb)
#3 0xc02a4054 in ffs_valloc (pvp=0xd724ad00, mode=16877, cred=0xc732c600, vpp=0xd6f01d08)
at /private/freebsd-src/src/sys/ufs/ffs/ffs_alloc.c:609
609 panic("ffs_valloc: dup alloc");
(kgdb) list
604 }
605 ip = VTOI(*vpp);
606 if (ip->i_mode) {
607 printf("mode = 0%o, inum = %lu, fs = %s\n",
608 ip->i_mode, (u_long)ip->i_number, fs->fs_fsmnt);
-->609 panic("ffs_valloc: dup alloc");
610 }
611 if (ip->i_blocks) { /* XXX */
612 printf("free inode %s/%lu had %ld blocks\n",
613 fs->fs_fsmnt, (u_long)ino, (long)ip->i_blocks);
(kgdb) up
#4 0xc02b5c25 in ufs_mkdir (ap=0xd6f01e70) at /private/freebsd-src/src/sys/ufs/ufs/ufs_vnops.c:1310
1310 error = UFS_VALLOC(dvp, dmode, cnp->cn_cred, &tvp);
(kgdb) list
1305 /*
1306 * Must simulate part of ufs_makeinode here to acquire the inode,
1307 * but not have it entered in the parent directory. The entry is
1308 * made later after writing "." and ".." entries.
1309 */
-->1310 error = UFS_VALLOC(dvp, dmode, cnp->cn_cred, &tvp);
1311 if (error)
1312 goto out;
1313 ip = VTOI(tvp);
1314 ip->i_gid = dp->i_gid;
Shell history of 3rd fs crash:
------------------------------
newfs -v -i 2048 -m 1 /dev/vinum/mail
fsck /dev/vinum/mail
[ ok ]
tunefs -n enable /export/mail
tunefs -n enable /dev/vinum/mail
fsck /dev/vinum/mail
[ ok ]
tunefs -p /dev/vinum/mail
tunefs -o time /dev/vinum/mail
[ fs changed back to space during fs IO ]
vi /etc/fstab
mount /export/mail
df -k
showmount -e
cd /export/mail
ls
cd
time /var/tmp/make_imap_files
cat > /var/tmp/mkimf0
vinum list
more /tmp/mail.p1
vinum create -f /tmp/mail.p1
vinum list
vinum attach mail.p1 mail
vinum start mail.p1
vinum list
find /export/mail
[ ok ]
time /var/tmp/make_imap_files
rm -rf /cise/mail/mhspool/a*
vinum list
man iostat
iostat -n 5 1
ls -d /cise/mail/mhspool/a*
rm -rf /cise/mail/mhspool/[bc]*
vinum list
time /var/tmp/make_imap_files
vinum list
cat > /var/tmp/mkimf1
vinum list
vinum list
vinum list
vinum list
vinum list
vinum list
vinum list
vinum list
vinum list
vinum list
vinum list
[ waited for mirror to sync up, between 1-2 hours ]
df -k /export/mail
[ seemed ok ]
umount /export/mail
fsck /dev/vinum/mail
[ failed, many errors ]
mount /export/mail
[ failed ]
vinum list
echo '***** filesystem dead *****'
I went ahead and ran fsck again just now (Wed morning). Here are the
highlights (3M worth of output).
fsck output:
---------------
70578 DUP I=31872
UNEXPECTED SOFT UPDATE INCONSISTENCY
70579 DUP I=31872
UNEXPECTED SOFT UPDATE INCONSISTENCY
70580 DUP I=31873
UNEXPECTED SOFT UPDATE INCONSISTENCY
70581 DUP I=31873
[....]
UNEXPECTED SOFT UPDATE INCONSISTENCY
1806410 DUP I=849031
UNEXPECTED SOFT UPDATE INCONSISTENCY
INTERNAL ERROR: dups with -p
[....]
UNEXPECTED SOFT UPDATE INCONSISTENCY
UNALLOCATED NAME=/lost+found/#01311046
UNEXPECTED SOFT UPDATE INCONSISTENCY
UNALLOCATED NAME=/lost+found/#01311043
[....]
UNEXPECTED SOFT UPDATE INCONSISTENCY
DUP/BAD FILE=/lost+found/#00370626
[....]
I=1125952 OWNER=aarcot MODE=0
SIZE=0 MTIME=Feb 20 10:23 2001
REMOVE? yes
[....]
I=2175671 OWNER=cjn MODE=0
SIZE=0 MTIME=Feb 20 10:27 2001 COUNT 0 SHOULD BE -1
ADJUST? yes
[....]
** Phase 5 - Check Cyl groups
SALVAGE? yes
SALVAGE? yes
SALVAGE? yes
(53252 frags, 4059511 blocks, 0.2% fragmentation)
***** FILE SYSTEM MARKED CLEAN *****
[ Seems like this is premature ]
***** FILE SYSTEM WAS MODIFIED *****
Here's what the dir looks like now:
-----------------------------------
<root@dogwood:~> # ls /export/mail/mhspool
aa1/ aesquive/ ajohnson/ amm/ aritter/ av0/
aa2/ aev/ ajp/ amolina/ arowan/ avance/
[....]
adossani/ ajheim/ amlone/ aring/ aup/ inbox/
Many of the files were missing, and an inbox was put back in the wrong place.
lost+found:
<root@dogwood:~> # ls /export/mail/lost+found
ls: #00354752: Bad file descriptor
ls: #00539840: Bad file descriptor
ls: #00802048: Bad file descriptor
[30 lines of that, then many # files]
<root@dogwood:/export/mail/lost+found> # /bin/ls -1 | wc -l
4449
I'm willing to do more looking around if somone can tell me
where to look.
--------------------------------------------------------------------
To Unsubscribe: send mail to majordomo@FreeBSD.org
with "unsubscribe freebsd-fs" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20010221140326.8AF89D80A>