Bug 345

Current directory is /var/crash/
Reading symbol data from /var/crash/kernel.15...done.
(kgdb) core vmcore.15
IdlePTD 246000
panic: biodone: page busy < 0

current pcb at 1f74c4
Reading in symbols for ../../i386/i386/machdep.c...done.
(kgdb) up
Reading in symbols for ../../kern/subr_prf.c...done.
#1  0xf0114ab3 in panic (fmt=(char *) 0xf0126f68 "biodone: page busy < 0\n") (../../kern/subr_prf.c line 128)
128	(../../kern/subr_prf.c)
(kgdb) directory /usr/src/sys/compile/CLINETSERVER
Source directories searched: /m/katiska/news/crash:/usr/src/sys/compile/CLINETSERVER
(kgdb) up
Reading in symbols for ../../kern/vfs_bio.c...done.
#2  0xf0127187 in biodone (bp=(struct buf *) 0xf27043b8) (../../kern/vfs_bio.c line 1134)
(kgdb) print *m
$1 = {pageq = {tqe_next = 0x0, tqe_prev = 0xf02c12c4}, hashq = {tqe_next = 0x0, tqe_prev = 0xf0268580}, listq = {tqe_next = 0xf02bb2e4, tqe_prev = 0xf02bec08}, object = 0xf0e2a280, offset = 0x00030000, phys_addr = 0x018dc000, wire_count = 0x0000, flags = 0x0042, hold_count = 0, act_count = 0x0000, bmapped = 0x0000, busy = 0x0000, valid = 0x00ff, dirty = 0x0000}
(kgdb) bt
#0  boot (arghowto=256) (../../i386/i386/machdep.c line 850)
#1  0xf0114ab3 in panic (fmt=(char *) 0xf0126f68 "biodone: page busy < 0\n") (../../kern/subr_prf.c line 128)
#2  0xf0127187 in biodone (bp=(struct buf *) 0xf27043b8) (../../kern/vfs_bio.c line 1134)
#3  0xf015cf2b in nfs_doio (...)
#4  0xf015bcba in nfs_bioread (...)
#5  0xf0174022 in nfs_read (...)
#6  0xf012f012 in vn_read (...)
#7  0xf0115c9b in read (...)
#8  0xf01b9a8d in syscall (...)
(kgdb) up
Reading in symbols for ../../nfs/nfs_bio.c...done.
#3  0xf015cf2b in nfs_doio (bp=(struct buf *) 0xf27043b8, cr=(struct ucred *) 0xf0db7f00, p=(struct proc *) 0xf0d4a900) (../../nfs/nfs_bio.c line 867)
(kgdb) up
#4  0xf015bcba in nfs_bioread (vp=(struct vnode *) 0xf0ab9800, uio=(struct uio *) 0xefbfff28, ioflag=0, cred=(struct ucred *) 0xf0db7f00) (../../nfs/nfs_bio.c line 249)
(kgdb) down
#3  0xf015cf2b in nfs_doio (bp=(struct buf *) 0xf27043b8, cr=(struct ucred *) 0xf0db7f00, p=(struct proc *) 0xf0d4a900) (../../nfs/nfs_bio.c line 867)
(kgdb) down
#2  0xf0127187 in biodone (bp=(struct buf *) 0xf27043b8) (../../kern/vfs_bio.c line 1134)
(kgdb) down
#1  0xf0114ab3 in panic (fmt=(char *) 0xf0126f68 "biodone: page busy < 0\n") (../../kern/subr_prf.c line 128)
(kgdb) up
#2  0xf0127187 in biodone (bp=(struct buf *) 0xf27043b8) (../../kern/vfs_bio.c line 1134)
(kgdb) up
#3  0xf015cf2b in nfs_doio (bp=(struct buf *) 0xf27043b8, cr=(struct ucred *) 0xf0db7f00, p=(struct proc *) 0xf0d4a900) (../../nfs/nfs_bio.c line 867)
(kgdb) print bp
$2 = (struct buf *) 0xf27043b8
(kgdb) print *bp
$3 = {b_hash = {le_next = 0xf26e8408, le_prev = 0xf0228c24}, b_vnbufs = {le_next = 0xf26e9928, le_prev = 0xf0ab982c}, b_freelist = {tqe_next = 0x0, tqe_prev = 0xf01f7648}, b_actf = 0x0, b_actb = 0x0, b_proc = 0x0, b_flags = 537920016, b_qindex = 0, b_error = 0, b_bufsize = 8192, b_bcount = 8192, b_resid = 0, b_dev = 0xffffffff, b_un = {b_addr = 0xf3438000 "\366t\005\270D\024\004"}, b_saveaddr = 0x0, b_lblkno = 24, b_blkno = 384, b_iodone = 0x0, b_iodone_chain = 0x0, b_vp = 0xf0ab9800, b_pfcent = 0, b_dirtyoff = 0, b_dirtyend = 0, b_rcred = 0xffffffff, b_wcred = 0xffffffff, b_validoff = 0, b_validend = 8192, b_pblkno = 233688, b_savekva = 0x0, b_driver1 = 0x0, b_driver2 = 0x0, b_spc = 0x0, b_pages = {0xf02c9c7c, 0xf0283488, 0x0 <repeats 14 times>}, b_npages = 2}
(kgdb) up
#4  0xf015bcba in nfs_bioread (vp=(struct vnode *) 0xf0ab9800, uio=(struct uio *) 0xefbfff28, ioflag=0, cred=(struct ucred *) 0xf0db7f00) (../../nfs/nfs_bio.c line 249)
(kgdb) print cred
$4 = (struct ucred *) 0xf0db7f00
(kgdb) print *cred
$5 = {cr_ref = 0x002d, cr_uid = 0x000005b5, cr_ngroups = 2, cr_groups = {0x000003e8, 0x000003e8, 0x00000000 <repeats 14 times>}}
(kgdb) print p
$6 = (struct proc *) 0xf0d4a900
(kgdb) print *proc
No symbol "proc" in current context.
(kgdb) print *p
$7 = {p_forw = 0xf0228efc, p_back = 0x0, p_next = 0xf0bdad00, p_prev = 0xf0e65c08, p_cred = 0xf0cbfa20, p_fd = 0xf0ce0180, p_stats = 0xf4694288, p_limit = 0xf022fdf4, p_vmspace = 0xf0b8d100, p_sigacts = 0xf469415c, p_flag = 16390, p_stat = 2, p_pad1 = {"\276\255\336"}, p_pid = 6952, p_hash = 0x0, p_pgrpnxt = 0x0, p_pptr = 0xf0bdad00, p_osptr = 0x0, p_ysptr = 0x0, p_cptr = 0x0, p_oppid = 0, p_dupfd = 0, p_estcpu = 0x000003f8, p_cpticks = 994, p_pctcpu = 0x0000001e, p_wchan = 0x0, p_wmesg = 0xf01e41d0 "netio", p_swtime = 0x00000090, p_slptime = 0x00000000, p_realtimer = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}, p_rtime = {tv_sec = 5, tv_usec = 29118}, p_uticks = 0x18e, p_sticks = 0x48d, p_iticks = 0x56, p_traceflag = 0, p_tracep = 0x0, p_siglist = 0, p_textvp = 0xf0ab9800, p_lock = 0, p_pad2 = {"\000\000\000"}, p_spare = {0, 0}, p_sigmask = 0x00000000, p_sigignore = 0x10489000, p_sigcatch = 0x28044003, p_priority = 0x18, p_usrpri = 0x7f, !
 p_nice = 0, p_comm = {"irc1\000n", '\000' <repeats 11 times>}, p_pgrp = 0xf0e85e40, p_sysent = 0xf01e3620, p_rtprio = {type = 0x0001, prio = 0x0000}, p_thread = -559038737, p_addr = 0xf4694000, p_md = {md_flags = -559038737, md_regs = 0xefbfffbc}, p_xstat = 0xbeef, p_acflag = 0x0000, p_ru = 0xdeadbeef}
(kgdb) list
244                              got_buf = 1;
245                             if ((bp->b_flags & (B_DONE | B_DELWRI)) == 0) {
246                                     bp->b_flags |= B_READ;
247                                     not_readin = 0;
248                                     vfs_busy_pages(bp, 0);
249                                     error = nfs_doio(bp, cred, p);
250                                     if (error) {
251                                         brelse(bp);
252                                         return (error);
253                                     }
(kgdb) up
Reading in symbols for ../../nfs/nfs_vnops.c...done.
#5  0xf0174022 in nfs_read (ap=(struct vop_read_args *) 0xefbffedc) (../../nfs/nfs_vnops.c line 780)
(kgdb) list
775      {
776             register struct vnode *vp = ap->a_vp;
777     
778             if (vp->v_type != VREG)
779                     return (EPERM);
780             return (nfs_bioread(vp, ap->a_uio, ap->a_ioflag, ap->a_cred));
781     }
782     
783     /*
784      * nfs readlink call
(kgdb) print *vp
Cannot read memory: address 0x0 out of bounds.
(kgdb) print *ap
Cannot read memory: address 0x0 out of bounds.
(kgdb) print ap
$8 = (struct vop_read_args *) 0x0
(kgdb) print vp
$9 = (struct vnode *) 0x0
(kgdb) print (struct vop_read_args *) 0xefbffedc
Undefined command: "".
(kgdb) print *(struct vop_read_args *) 0xefbffedc
$10 = (struct vop_read_args *) 0xefbffedc
(kgdb) print *(struct vop_read_args *) 0xefbffedc
$11 = {a_desc = 0xf01e223c, a_vp = 0xf0ab9800, a_uio = 0xefbfff28, a_ioflag = 0, a_cred = 0xf0db7f00}
(kgdb) up
Reading in symbols for ../../kern/vfs_vnops.c...done.
#6  0xf012f012 in vn_read (fp=(struct file *) 0xf0ec9fc0, uio=(struct uio *) 0xefbfff28, cred=(struct ucred *) 0xf0db7f00) (./vnode_if.h line 211)
Source file is more recent than executable.
(kgdb) print *vp
$12 = {v_flag = 0x00002002, v_usecount = 4, v_writecount = 0, v_holdcnt = 25, v_lastr = 23, v_id = 0x0001c621, v_mount = 0xf0afb600, v_op = 0xf0a18f00, v_freelist = {tqe_next = 0xf0c02a80, tqe_prev = 0xf0adec9c}, v_mntvnodes = {le_next = 0xf0ba4c80, le_prev = 0xf0b800a4}, v_cleanblkhd = {lh_first = 0xf27043b8}, v_dirtyblkhd = {lh_first = 0x0}, v_numoutput = 0, v_type = VREG, v_un = {vu_mountedhere = 0x0, vu_socket = 0x0, vu_specinfo = 0x0, vu_fifoinfo = 0x0}, v_lease = 0x0, v_lastw = 0, v_cstart = 0, v_lasta = 0, v_clen = 0, v_ralen = 0, v_maxra = 0, v_vmdata = 0xf0e2a280 "\364\324,\360\364\262+\360", v_tag = VT_NFS, v_data = 0xf0df5900}
(kgdb) print *uio
$13 = {uio_iov = 0xefbfff20, uio_iovcnt = 1, uio_offset = 196608, uio_resid = 2048, uio_segflg = UIO_USERSPACE, uio_rw = UIO_READ, uio_procp = 0xf0d4a900}
(kgdb) print *ioflag
No symbol "ioflag" in current context.
(kgdb) print *cred
$14 = {cr_ref = 0x002d, cr_uid = 0x000005b5, cr_ngroups = 2, cr_groups = {0x000003e8, 0x000003e8, 0x00000000 <repeats 14 times>}}
(kgdb) list
206              a.a_desc = VDESC(vop_read);
207             a.a_vp = vp;
208             a.a_uio = uio;
209             a.a_ioflag = ioflag;
210             a.a_cred = cred;
211             return (VCALL(vp, VOFFSET(vop_read), &a));
212     }
213     struct vop_write_args {
214             struct vnodeop_desc *a_desc;
215             struct vnode *a_vp;
(kgdb) up
Reading in symbols for ../../kern/sys_generic.c...done.
#7  0xf0115c9b in read (p=(struct proc *) 0xf0d4a900, uap=(struct read_args *) 0xefbfff94, retval=(int *) 0xefbfff8c) (../../kern/sys_generic.c line 112)
(kgdb) print *fp
Cannot read memory: address 0x0 out of bounds.
(kgdb) print fp
$15 = (struct file *) 0x0
(kgdb) print *(struct read_args *) 0xefbfff94
$16 = {fd = 7, buf = 0xefbfbfb8 , nbyte = 0x00000800}
(kgdb) up
Reading in symbols for ../../i386/i386/trap.c...done.
#8  0xf01b9a8d in syscall (frame={tf_es = 39, tf_ds = 39, tf_edi = 617216, tf_esi = -272646216, tf_ebp = -272644164, tf_isp = -272629788, tf_ebx = 617216, tf_edx = 292332, tf_ecx = 8, tf_eax = 3, tf_trapno = 530, tf_err = 530, tf_eip = 134625685, tf_cs = 31, tf_eflags = 530, tf_esp = -272646244, tf_ss = 39}) (../../i386/i386/trap.c line 828)
(kgdb) print args
$17 = {7, -272646216, 2048, 0, 0, 0, 1073741823, -272644164}
(kgdb) print rval
$18 = {0, 292332}
(kgdb) up
Initial frame selected; you cannot go up.
(kgdb) list
823                      ktrsyscall(p->p_tracep, code, callp->sy_narg, args);
824     #endif
825             rval[0] = 0;
826             rval[1] = frame.tf_edx;
827     
828             error = (*callp->sy_call)(p, args, rval);
829     
830             switch (error) {
831     
832             case 0:
(kgdb) down
#7  0xf0115c9b in read (p=(struct proc *) 0xf0d4a900, uap=(struct read_args *) 0xefbfff94, retval=(int *) 0xefbfff8c) (../../kern/sys_generic.c line 112)
(kgdb) list
107               */
108             if (KTRPOINT(p, KTR_GENIO))
109                     ktriov = aiov;
110     #endif
111             cnt = uap->nbyte;
112             if ((error = (*fp->f_ops->fo_read)(fp, &auio, fp->f_cred)))
113                     if (auio.uio_resid != cnt && (error == ERESTART ||
114                         error == EINTR || error == EWOULDBLOCK))
115                             error = 0;
116             cnt -= auio.uio_resid;
(kgdb) down
#6  0xf012f012 in vn_read (fp=(struct file *) 0xf0ec9fc0, uio=(struct uio *) 0xefbfff28, cred=(struct ucred *) 0xf0db7f00) (./vnode_if.h line 211)
(kgdb) list
206              a.a_desc = VDESC(vop_read);
207             a.a_vp = vp;
208             a.a_uio = uio;
209             a.a_ioflag = ioflag;
210             a.a_cred = cred;
211             return (VCALL(vp, VOFFSET(vop_read), &a));
212     }
213     struct vop_write_args {
214             struct vnodeop_desc *a_desc;
215             struct vnode *a_vp;
(kgdb) down
#5  0xf0174022 in nfs_read (ap=(struct vop_read_args *) 0xefbffedc) (../../nfs/nfs_vnops.c line 780)
(kgdb) list
775      {
776             register struct vnode *vp = ap->a_vp;
777     
778             if (vp->v_type != VREG)
779                     return (EPERM);
780             return (nfs_bioread(vp, ap->a_uio, ap->a_ioflag, ap->a_cred));
781     }
782     
783     /*
784      * nfs readlink call
(kgdb) down
#4  0xf015bcba in nfs_bioread (vp=(struct vnode *) 0xf0ab9800, uio=(struct uio *) 0xefbfff28, ioflag=0, cred=(struct ucred *) 0xf0db7f00) (../../nfs/nfs_bio.c line 249)
(kgdb) list
244                              got_buf = 1;
245                             if ((bp->b_flags & (B_DONE | B_DELWRI)) == 0) {
246                                     bp->b_flags |= B_READ;
247                                     not_readin = 0;
248                                     vfs_busy_pages(bp, 0);
249                                     error = nfs_doio(bp, cred, p);
250                                     if (error) {
251                                         brelse(bp);
252                                         return (error);
253                                     }
(kgdb) down
#3  0xf015cf2b in nfs_doio (bp=(struct buf *) 0xf27043b8, cr=(struct ucred *) 0xf0db7f00, p=(struct proc *) 0xf0d4a900) (../../nfs/nfs_bio.c line 867)
(kgdb) list
862                      }
863                     bp->b_dirtyoff = bp->b_dirtyend = 0;
864                 }
865             }
866             bp->b_resid = uiop->uio_resid;
867             biodone(bp);
868             return (error);
869     }
(kgdb) down
#2  0xf0127187 in biodone (bp=(struct buf *) 0xf27043b8) (../../kern/vfs_bio.c line 1134)
(kgdb) list
1129                                         m->offset, foff, resid, i);
1130                                    printf(" iosize: %d, lblkno: %d\n",
1131                                        bp->b_vp->v_mount->mnt_stat.f_iosize, bp->b_lblkno);
1132                                    printf(" valid: 0x%x, dirty: 0x%x, mapped: %d\n",
1133                                        m->valid, m->dirty, m->bmapped);
1134                                    panic("biodone: page busy < 0\n");
1135                            }
1136                            --m->busy;
1137                            if( (m->busy == 0) && (m->flags & PG_WANTED))
1138                                    wakeup((caddr_t) m);
(kgdb) list 1122
1117                             if (!bogusflag && resid > 0) {
1118                                    vm_page_set_valid(m, foff & (PAGE_SIZE-1), resid);
1119                                    vm_page_set_clean(m, foff & (PAGE_SIZE-1), resid);
1120                            }
1121    
1122                            /*
1123                             * when debugging new filesystems or buffer I/O methods, this
1124                             * is the most common error that pops up.  if you see this, you
1125                             * have not set the page busy flag correctly!!!
1126                             */
(kgdb) list
1127                             if (m->busy == 0) {
1128                                    printf("biodone: page busy < 0, off: %d, foff: %d, resid: %d, index: %d\n",
1129                                        m->offset, foff, resid, i);
1130                                    printf(" iosize: %d, lblkno: %d\n",
1131                                        bp->b_vp->v_mount->mnt_stat.f_iosize, bp->b_lblkno);
1132                                    printf(" valid: 0x%x, dirty: 0x%x, mapped: %d\n",
1133                                        m->valid, m->dirty, m->bmapped);
1134                                    panic("biodone: page busy < 0\n");
1135                            }
1136                            --m->busy;
(kgdb) list
1137                             if( (m->busy == 0) && (m->flags & PG_WANTED))
1138                                    wakeup((caddr_t) m);
1139                            --obj->paging_in_progress;
1140                            foff += resid;
1141                            iosize -= resid;
1142                    }
1143                    if (obj && obj->paging_in_progress == 0 &&
1144                        (obj->flags & OBJ_PIPWNT)) {
1145                            obj->flags &= ~OBJ_PIPWNT;
1146                            wakeup((caddr_t) obj);
(kgdb) list
1147                     }
1148            }
1149            /*
1150             * For asynchronous completions, release the buffer now. The brelse
1151             * checks for B_WANTED and will do the wakeup there if necessary - so
1152             * no need to do a wakeup here in the async case.
1153             */
1154    
1155            if (bp->b_flags & B_ASYNC) {
1156                    brelse(bp);
(kgdb)

Fix: 

Dunno,

-- 
Heikki Suonsivu, T{ysikuu 10 C 83/02210 Espoo/FINLAND,
hsu@cs.hut.fi  home +358-0-8031121 work -4513377 fax -4555276  riippu SN
How-To-Repeat: 
	Hard to say.  The system tries to run as an nntp server but
there are often other users in the system as well.  With -current it
seems to panic about twice a day, sometimes corrupting a couple of
files or a directory.  I'll try to send more dumps and update kernel
every couple of days or so.