Add more KTR_VFS logging point in order to have a more effective tracing.

Reviewed by:	brueffer, kib
Tested by:	Gianni Trematerra <giovanni D trematerra A gmail D com>

2 files changed, 78 insertions, 23 deletions

diff --git a/sys/kern/vfs_mount.c b/sys/kern/vfs_mount.c
index 2b870f0..1f767a3 100644
--- a/sys/kern/vfs_mount.c
+++ b/sys/kern/vfs_mount.c
@@ -386,6 +386,8 @@ nmount(td, uap)
 	u_int iovcnt;
 
 	AUDIT_ARG(fflags, uap->flags);
+	CTR4(KTR_VFS, "%s: iovp %p with iovcnt %d and flags %d", __func__,
+	    uap->iovp, uap->iovcnt, uap->flags);
 
 	/*
 	 * Filter out MNT_ROOTFS.  We do not want clients of nmount() in
@@ -400,16 +402,24 @@ nmount(td, uap)
 	 * Check that we have an even number of iovec's
 	 * and that we have at least two options.
 	 */
-	if ((iovcnt & 1) || (iovcnt < 4))
+	if ((iovcnt & 1) || (iovcnt < 4)) {
+		CTR2(KTR_VFS, "%s: failed for invalid iovcnt %d", __func__,
+		    uap->iovcnt);
 		return (EINVAL);
+	}
 
 	error = copyinuio(uap->iovp, iovcnt, &auio);
-	if (error)
+	if (error) {
+		CTR2(KTR_VFS, "%s: failed for invalid uio op with %d errno",
+		    __func__, error);
 		return (error);
+	}
 	iov = auio->uio_iov;
 	for (i = 0; i < iovcnt; i++) {
 		if (iov->iov_len > MMAXOPTIONLEN) {
 			free(auio, M_IOV);
+			CTR1(KTR_VFS, "%s: failed for invalid new auio",
+			    __func__);
 			return (EINVAL);
 		}
 		iov++;
@@ -429,6 +439,7 @@ void
 vfs_ref(struct mount *mp)
 {
 
+	CTR2(KTR_VFS, "%s: mp %p", __func__, mp);
 	MNT_ILOCK(mp);
 	MNT_REF(mp);
 	MNT_IUNLOCK(mp);
@@ -438,6 +449,7 @@ void
 vfs_rel(struct mount *mp)
 {
 
+	CTR2(KTR_VFS, "%s: mp %p", __func__, mp);
 	MNT_ILOCK(mp);
 	MNT_REL(mp);
 	MNT_IUNLOCK(mp);
diff --git a/sys/kern/vfs_subr.c b/sys/kern/vfs_subr.c
index 4c3c462..c97c2a9 100644
--- a/sys/kern/vfs_subr.c
+++ b/sys/kern/vfs_subr.c
@@ -341,6 +341,7 @@ vfs_busy(struct mount *mp, int flags)
 {
 
 	MPASS((flags & ~MBF_MASK) == 0);
+	CTR3(KTR_VFS, "%s: mp %p with flags %d", __func__, mp, flags);
 
 	MNT_ILOCK(mp);
 	MNT_REF(mp);
@@ -348,6 +349,8 @@ vfs_busy(struct mount *mp, int flags)
 		if (flags & MBF_NOWAIT || mp->mnt_kern_flag & MNTK_REFEXPIRE) {
 			MNT_REL(mp);
 			MNT_IUNLOCK(mp);
+			CTR1(KTR_VFS, "%s: failed busying before sleeping",
+			    __func__);
 			return (ENOENT);
 		}
 		if (flags & MBF_MNTLSTLOCK)
@@ -358,6 +361,7 @@ vfs_busy(struct mount *mp, int flags)
 		MNT_IUNLOCK(mp);
 		if (flags & MBF_MNTLSTLOCK)
 			mtx_lock(&mountlist_mtx);
+		CTR1(KTR_VFS, "%s: failed busying after sleep", __func__);
 		return (ENOENT);
 	}
 	if (flags & MBF_MNTLSTLOCK)
@@ -374,11 +378,13 @@ void
 vfs_unbusy(struct mount *mp)
 {
 
+	CTR2(KTR_VFS, "%s: mp %p", __func__, mp);
 	MNT_ILOCK(mp);
 	MNT_REL(mp);
 	mp->mnt_lockref--;
 	if (mp->mnt_lockref == 0 && (mp->mnt_kern_flag & MNTK_DRAINING) != 0) {
 		MPASS(mp->mnt_kern_flag & MNTK_UNMOUNT);
+		CTR1(KTR_VFS, "%s: waking up waiters", __func__);
 		mp->mnt_kern_flag &= ~MNTK_DRAINING;
 		wakeup(&mp->mnt_lockref);
 	}
@@ -393,6 +399,7 @@ vfs_getvfs(fsid_t *fsid)
 {
 	struct mount *mp;
 
+	CTR2(KTR_VFS, "%s: fsid %p", __func__, fsid);
 	mtx_lock(&mountlist_mtx);
 	TAILQ_FOREACH(mp, &mountlist, mnt_list) {
 		if (mp->mnt_stat.f_fsid.val[0] == fsid->val[0] &&
@@ -403,6 +410,7 @@ vfs_getvfs(fsid_t *fsid)
 		}
 	}
 	mtx_unlock(&mountlist_mtx);
+	CTR2(KTR_VFS, "%s: lookup failed for %p id", __func__, fsid);
 	return ((struct mount *) 0);
 }
 
@@ -416,6 +424,7 @@ vfs_busyfs(fsid_t *fsid)
 	struct mount *mp;
 	int error;
 
+	CTR2(KTR_VFS, "%s: fsid %p", __func__, fsid);
 	mtx_lock(&mountlist_mtx);
 	TAILQ_FOREACH(mp, &mountlist, mnt_list) {
 		if (mp->mnt_stat.f_fsid.val[0] == fsid->val[0] &&
@@ -428,6 +437,7 @@ vfs_busyfs(fsid_t *fsid)
 			return (mp);
 		}
 	}
+	CTR2(KTR_VFS, "%s: lookup failed for %p id", __func__, fsid);
 	mtx_unlock(&mountlist_mtx);
 	return ((struct mount *) 0);
 }
@@ -498,6 +508,7 @@ vfs_getnewfsid(struct mount *mp)
 	fsid_t tfsid;
 	int mtype;
 
+	CTR2(KTR_VFS, "%s: mp %p", __func__, mp);
 	mtx_lock(&mntid_mtx);
 	mtype = mp->mnt_vfc->vfc_typenum;
 	tfsid.val[1] = mtype;
@@ -822,7 +833,7 @@ vdestroy(struct vnode *vp)
 {
 	struct bufobj *bo;
 
-	CTR1(KTR_VFS, "vdestroy vp %p", vp);
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	mtx_lock(&vnode_free_list_mtx);
 	numvnodes--;
 	mtx_unlock(&vnode_free_list_mtx);
@@ -867,20 +878,27 @@ vtryrecycle(struct vnode *vp)
 {
 	struct mount *vnmp;
 
-	CTR1(KTR_VFS, "vtryrecycle: trying vp %p", vp);
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	VNASSERT(vp->v_holdcnt, vp,
 	    ("vtryrecycle: Recycling vp %p without a reference.", vp));
 	/*
 	 * This vnode may found and locked via some other list, if so we
 	 * can't recycle it yet.
 	 */
-	if (VOP_LOCK(vp, LK_EXCLUSIVE | LK_NOWAIT) != 0)
+	if (VOP_LOCK(vp, LK_EXCLUSIVE | LK_NOWAIT) != 0) {
+		CTR2(KTR_VFS,
+		    "%s: impossible to recycle, vp %p lock is already held",
+		    __func__, vp);
 		return (EWOULDBLOCK);
+	}
 	/*
 	 * Don't recycle if its filesystem is being suspended.
 	 */
 	if (vn_start_write(vp, &vnmp, V_NOWAIT) != 0) {
 		VOP_UNLOCK(vp, 0);
+		CTR2(KTR_VFS,
+		    "%s: impossible to recycle, cannot start the write for %p",
+		    __func__, vp);
 		return (EBUSY);
 	}
 	/*
@@ -893,13 +911,15 @@ vtryrecycle(struct vnode *vp)
 	if (vp->v_usecount) {
 		VOP_UNLOCK(vp, LK_INTERLOCK);
 		vn_finished_write(vnmp);
+		CTR2(KTR_VFS,
+		    "%s: impossible to recycle, %p is already referenced",
+		    __func__, vp);
 		return (EBUSY);
 	}
 	if ((vp->v_iflag & VI_DOOMED) == 0)
 		vgonel(vp);
 	VOP_UNLOCK(vp, LK_INTERLOCK);
 	vn_finished_write(vnmp);
-	CTR1(KTR_VFS, "vtryrecycle: recycled vp %p", vp);
 	return (0);
 }
 
@@ -913,6 +933,7 @@ getnewvnode(const char *tag, struct mount *mp, struct vop_vector *vops,
 	struct vnode *vp = NULL;
 	struct bufobj *bo;
 
+	CTR3(KTR_VFS, "%s: mp %p with tag %s", __func__, mp, tag);
 	mtx_lock(&vnode_free_list_mtx);
 	/*
 	 * Lend our context to reclaim vnodes if they've exceeded the max.
@@ -995,7 +1016,6 @@ alloc:
 			vp->v_vflag |= VV_NOKNOTE;
 	}
 
-	CTR2(KTR_VFS, "getnewvnode: mp %p vp %p", mp, vp);
 	*vpp = vp;
 	return (0);
 }
@@ -1173,7 +1193,7 @@ int
 vinvalbuf(struct vnode *vp, int flags, int slpflag, int slptimeo)
 {
 
-	CTR2(KTR_VFS, "vinvalbuf vp %p flags %d", vp, flags);
+	CTR3(KTR_VFS, "%s: vp %p with flags %d", __func__, vp, flags);
 	ASSERT_VOP_LOCKED(vp, "vinvalbuf");
 	return (bufobj_invalbuf(&vp->v_bufobj, flags, slpflag, slptimeo));
 }
@@ -1265,7 +1285,9 @@ vtruncbuf(struct vnode *vp, struct ucred *cred, struct thread *td,
 	int trunclbn;
 	struct bufobj *bo;
 
-	CTR2(KTR_VFS, "vtruncbuf vp %p length %jd", vp, length);
+	CTR5(KTR_VFS, "%s: vp %p with cred %p and block %d:%ju", __func__,
+	    vp, cred, blksize, (uintmax_t)length);
+
 	/*
 	 * Round up to the *next* lbn.
 	 */
@@ -1974,8 +1996,7 @@ static void
 v_incr_usecount(struct vnode *vp)
 {
 
-	CTR3(KTR_VFS, "v_incr_usecount: vp %p holdcnt %d usecount %d\n",
-	    vp, vp->v_holdcnt, vp->v_usecount);
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	vp->v_usecount++;
 	if (vp->v_type == VCHR && vp->v_rdev != NULL) {
 		dev_lock();
@@ -1993,8 +2014,7 @@ static void
 v_upgrade_usecount(struct vnode *vp)
 {
 
-	CTR3(KTR_VFS, "v_upgrade_usecount: vp %p holdcnt %d usecount %d\n",
-	    vp, vp->v_holdcnt, vp->v_usecount);
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	vp->v_usecount++;
 	if (vp->v_type == VCHR && vp->v_rdev != NULL) {
 		dev_lock();
@@ -2012,11 +2032,10 @@ static void
 v_decr_usecount(struct vnode *vp)
 {
 
-	CTR3(KTR_VFS, "v_decr_usecount: vp %p holdcnt %d usecount %d\n",
-	    vp, vp->v_holdcnt, vp->v_usecount);
 	ASSERT_VI_LOCKED(vp, __FUNCTION__);
 	VNASSERT(vp->v_usecount > 0, vp,
 	    ("v_decr_usecount: negative usecount"));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	vp->v_usecount--;
 	if (vp->v_type == VCHR && vp->v_rdev != NULL) {
 		dev_lock();
@@ -2036,11 +2055,10 @@ static void
 v_decr_useonly(struct vnode *vp)
 {
 
-	CTR3(KTR_VFS, "v_decr_useonly: vp %p holdcnt %d usecount %d\n",
-	    vp, vp->v_holdcnt, vp->v_usecount);
 	ASSERT_VI_LOCKED(vp, __FUNCTION__);
 	VNASSERT(vp->v_usecount > 0, vp,
 	    ("v_decr_useonly: negative usecount"));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	vp->v_usecount--;
 	if (vp->v_type == VCHR && vp->v_rdev != NULL) {
 		dev_lock();
@@ -2065,11 +2083,15 @@ vget(struct vnode *vp, int flags, struct thread *td)
 	VFS_ASSERT_GIANT(vp->v_mount);
 	VNASSERT((flags & LK_TYPE_MASK) != 0, vp,
 	    ("vget: invalid lock operation"));
+	CTR3(KTR_VFS, "%s: vp %p with flags %d", __func__, vp, flags);
+
 	if ((flags & LK_INTERLOCK) == 0)
 		VI_LOCK(vp);
 	vholdl(vp);
 	if ((error = vn_lock(vp, flags | LK_INTERLOCK)) != 0) {
 		vdrop(vp);
+		CTR2(KTR_VFS, "%s: impossible to lock vnode %p", __func__,
+		    vp);
 		return (error);
 	}
 	if (vp->v_iflag & VI_DOOMED && (flags & LK_RETRY) == 0)
@@ -2100,6 +2122,7 @@ void
 vref(struct vnode *vp)
 {
 
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	VI_LOCK(vp);
 	v_incr_usecount(vp);
 	VI_UNLOCK(vp);
@@ -2144,6 +2167,7 @@ vrele(struct vnode *vp)
 	/* Skip this v_writecount check if we're going to panic below. */
 	VNASSERT(vp->v_writecount < vp->v_usecount || vp->v_usecount < 1, vp,
 	    ("vrele: missed vn_close"));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 
 	if (vp->v_usecount > 1 || ((vp->v_iflag & VI_DOINGINACT) &&
 	    vp->v_usecount == 1)) {
@@ -2157,6 +2181,7 @@ vrele(struct vnode *vp)
 		VI_UNLOCK(vp);
 		panic("vrele: negative ref cnt");
 	}
+	CTR2(KTR_VFS, "%s: return vnode %p to the freelist", __func__, vp);
 	/*
 	 * We want to hold the vnode until the inactive finishes to
 	 * prevent vgone() races.  We drop the use count here and the
@@ -2197,6 +2222,7 @@ vput(struct vnode *vp)
 	KASSERT(vp != NULL, ("vput: null vp"));
 	ASSERT_VOP_LOCKED(vp, "vput");
 	VFS_ASSERT_GIANT(vp->v_mount);
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	VI_LOCK(vp);
 	/* Skip this v_writecount check if we're going to panic below. */
 	VNASSERT(vp->v_writecount < vp->v_usecount || vp->v_usecount < 1, vp,
@@ -2216,6 +2242,7 @@ vput(struct vnode *vp)
 #endif
 		panic("vput: negative ref cnt");
 	}
+	CTR2(KTR_VFS, "%s: return to freelist the vnode %p", __func__, vp);
 	/*
 	 * We want to hold the vnode until the inactive finishes to
 	 * prevent vgone() races.  We drop the use count here and the
@@ -2257,6 +2284,7 @@ void
 vholdl(struct vnode *vp)
 {
 
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	vp->v_holdcnt++;
 	if (VSHOULDBUSY(vp))
 		vbusy(vp);
@@ -2284,11 +2312,14 @@ vdropl(struct vnode *vp)
 {
 
 	ASSERT_VI_LOCKED(vp, "vdropl");
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	if (vp->v_holdcnt <= 0)
 		panic("vdrop: holdcnt %d", vp->v_holdcnt);
 	vp->v_holdcnt--;
 	if (vp->v_holdcnt == 0) {
 		if (vp->v_iflag & VI_DOOMED) {
+			CTR2(KTR_VFS, "%s: destroying the vnode %p", __func__,
+			    vp);
 			vdestroy(vp);
 			return;
 		} else
@@ -2311,6 +2342,7 @@ vinactive(struct vnode *vp, struct thread *td)
 	ASSERT_VI_LOCKED(vp, "vinactive");
 	VNASSERT((vp->v_iflag & VI_DOINGINACT) == 0, vp,
 	    ("vinactive: recursed on VI_DOINGINACT"));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	vp->v_iflag |= VI_DOINGINACT;
 	vp->v_iflag &= ~VI_OWEINACT;
 	VI_UNLOCK(vp);
@@ -2353,7 +2385,8 @@ vflush( struct mount *mp, int rootrefs, int flags, struct thread *td)
 	struct vattr vattr;
 	int busy = 0, error;
 
-	CTR1(KTR_VFS, "vflush: mp %p", mp);
+	CTR4(KTR_VFS, "%s: mp %p with rootrefs %d and flags %d", __func__, mp,
+	    rootrefs, flags);
 	if (rootrefs > 0) {
 		KASSERT((flags & (SKIPSYSTEM | WRITECLOSE)) == 0,
 		    ("vflush: bad args"));
@@ -2361,8 +2394,11 @@ vflush( struct mount *mp, int rootrefs, int flags, struct thread *td)
 		 * Get the filesystem root vnode. We can vput() it
 		 * immediately, since with rootrefs > 0, it won't go away.
 		 */
-		if ((error = VFS_ROOT(mp, LK_EXCLUSIVE, &rootvp, td)) != 0)
+		if ((error = VFS_ROOT(mp, LK_EXCLUSIVE, &rootvp, td)) != 0) {
+			CTR2(KTR_VFS, "%s: vfs_root lookup failed with %d",
+			    __func__, error);
 			return (error);
+		}
 		vput(rootvp);
 
 	}
@@ -2449,8 +2485,11 @@ loop:
 		} else
 			VI_UNLOCK(rootvp);
 	}
-	if (busy)
+	if (busy) {
+		CTR2(KTR_VFS, "%s: failing as %d vnodes are busy", __func__,
+		    busy);
 		return (EBUSY);
+	}
 	for (; rootrefs > 0; rootrefs--)
 		vrele(rootvp);
 	return (0);
@@ -2465,6 +2504,7 @@ vrecycle(struct vnode *vp, struct thread *td)
 	int recycled;
 
 	ASSERT_VOP_ELOCKED(vp, "vrecycle");
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	recycled = 0;
 	VI_LOCK(vp);
 	if (vp->v_usecount == 0) {
@@ -2498,11 +2538,11 @@ vgonel(struct vnode *vp)
 	int active;
 	struct mount *mp;
 
-	CTR1(KTR_VFS, "vgonel: vp %p", vp);
 	ASSERT_VOP_ELOCKED(vp, "vgonel");
 	ASSERT_VI_LOCKED(vp, "vgonel");
 	VNASSERT(vp->v_holdcnt, vp,
 	    ("vgonel: vp %p has no reference.", vp));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	td = curthread;
 
 	/*
@@ -3099,7 +3139,9 @@ vfs_unmountall(void)
 	int error;
 
 	KASSERT(curthread != NULL, ("vfs_unmountall: NULL curthread"));
+	CTR1(KTR_VFS, "%s: unmounting all filesystems", __func__);
 	td = curthread;
+
 	/*
 	 * Since this only runs when rebooting, it is not interlocked.
 	 */
@@ -3140,6 +3182,7 @@ vfs_msync(struct mount *mp, int flags)
 	struct vnode *vp, *mvp;
 	struct vm_object *obj;
 
+	CTR2(KTR_VFS, "%s: mp %p", __func__, mp);
 	MNT_ILOCK(mp);
 	MNT_VNODE_FOREACH(vp, mp, mvp) {
 		VI_LOCK(vp);
@@ -3179,7 +3222,6 @@ static void
 vfree(struct vnode *vp)
 {
 
-	CTR1(KTR_VFS, "vfree vp %p", vp);
 	ASSERT_VI_LOCKED(vp, "vfree");
 	mtx_lock(&vnode_free_list_mtx);
 	VNASSERT(vp->v_op != NULL, vp, ("vfree: vnode already reclaimed."));
@@ -3187,6 +3229,7 @@ vfree(struct vnode *vp)
 	VNASSERT(VSHOULDFREE(vp), vp, ("vfree: freeing when we shouldn't"));
 	VNASSERT((vp->v_iflag & VI_DOOMED) == 0, vp,
 	    ("vfree: Freeing doomed vnode"));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 	if (vp->v_iflag & VI_AGE) {
 		TAILQ_INSERT_HEAD(&vnode_free_list, vp, v_freelist);
 	} else {
@@ -3204,10 +3247,10 @@ vfree(struct vnode *vp)
 static void
 vbusy(struct vnode *vp)
 {
-	CTR1(KTR_VFS, "vbusy vp %p", vp);
 	ASSERT_VI_LOCKED(vp, "vbusy");
 	VNASSERT((vp->v_iflag & VI_FREE) != 0, vp, ("vnode not free"));
 	VNASSERT(vp->v_op != NULL, vp, ("vbusy: vnode already reclaimed."));
+	CTR2(KTR_VFS, "%s: vp %p", __func__, vp);
 
 	mtx_lock(&vnode_free_list_mtx);
 	TAILQ_REMOVE(&vnode_free_list, vp, v_freelist);