Skip site navigation (1)Skip section navigation (2)
Date:      Tue, 03 Sep 2019 14:05:56 -0000
From:      Alan Somers <asomers@FreeBSD.org>
To:        src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org
Subject:   svn commit: r345675 - head/sys/fs/fuse
Message-ID:  <201903290213.x2T2D7kd058602@repo.freebsd.org>

next in thread | raw e-mail | index | archive | help
Author: asomers
Date: Fri Mar 29 02:13:06 2019
New Revision: 345675
URL: https://svnweb.freebsd.org/changeset/base/345675

Log:
  fusefs: convert debug printfs into dtrace probes
  
  fuse(4) was heavily instrumented with debug printf statements that could
  only be enabled with compile-time flags. They fell into three basic groups:
  
  1. Totally redundant with dtrace FBT probes. These I deleted.
  2. Print textual information, usually error messages. These I converted to
     SDT probes of the form fuse:fuse:FILE:trace. They work just like the old
     printf statements except they can be enabled at runtime with dtrace. They
     can be filtered by FILE and/or by priority.
  3. More complicated probes that print detailed information. These I
     converted into ad-hoc SDT probes.
  
  Also, de-inline fuse_internal_cache_attrs.  It's big enough to be a regular
  function, and this way it gets a dtrace FBT probe.
  
  This commit is a merge of r345304, r344914, r344703, and r344664 from
  projects/fuse2.
  
  Reviewed by:	cem
  MFC after:	2 weeks
  Sponsored by:	The FreeBSD Foundation
  Differential Revision:	https://reviews.freebsd.org/D19667

Deleted:
  head/sys/fs/fuse/fuse_debug.h
Modified:
  head/sys/fs/fuse/fuse.h
  head/sys/fs/fuse/fuse_device.c
  head/sys/fs/fuse/fuse_file.c
  head/sys/fs/fuse/fuse_internal.c
  head/sys/fs/fuse/fuse_internal.h
  head/sys/fs/fuse/fuse_io.c
  head/sys/fs/fuse/fuse_ipc.c
  head/sys/fs/fuse/fuse_ipc.h
  head/sys/fs/fuse/fuse_main.c
  head/sys/fs/fuse/fuse_node.c
  head/sys/fs/fuse/fuse_vfsops.c
  head/sys/fs/fuse/fuse_vnops.c
Directory Properties:
  head/   (props changed)

Modified: head/sys/fs/fuse/fuse.h
==============================================================================
--- head/sys/fs/fuse/fuse.h	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse.h	Fri Mar 29 02:13:06 2019	(r345675)
@@ -159,65 +159,8 @@ do {						\
 		(cred) = (td)->td_ucred;	\
 } while (0)
 
-/* Debug related stuff */
-
-#ifndef FUSE_DEBUG_DEVICE
-#define FUSE_DEBUG_DEVICE               0
-#endif
-
-#ifndef FUSE_DEBUG_FILE
-#define FUSE_DEBUG_FILE                 0
-#endif
-
-#ifndef FUSE_DEBUG_INTERNAL
-#define FUSE_DEBUG_INTERNAL             0
-#endif
-
-#ifndef FUSE_DEBUG_IO
-#define FUSE_DEBUG_IO                   0
-#endif
-
-#ifndef FUSE_DEBUG_IPC
-#define FUSE_DEBUG_IPC                  0
-#endif
-
-#ifndef FUSE_DEBUG_LOCK
-#define FUSE_DEBUG_LOCK                 0
-#endif
-
-#ifndef FUSE_DEBUG_VFSOPS
-#define FUSE_DEBUG_VFSOPS               0
-#endif
-
-#ifndef FUSE_DEBUG_VNOPS
-#define FUSE_DEBUG_VNOPS                0
-#endif
-
-#ifndef FUSE_TRACE
-#define FUSE_TRACE                      0
-#endif
-
-#define DEBUGX(cond, fmt, ...) do {					\
-	if (((cond))) {							\
-		printf("%s: " fmt, __func__, ## __VA_ARGS__);		\
-	}								\
-} while (0)
-
-#define fuse_lck_mtx_lock(mtx) do {						\
-	DEBUGX(FUSE_DEBUG_LOCK, "0:   lock(%s): %s@%d by %d\n",			\
-	    __STRING(mtx), __func__, __LINE__, curthread->td_proc->p_pid);	\
-	mtx_lock(&(mtx));							\
-	DEBUGX(FUSE_DEBUG_LOCK, "1:   lock(%s): %s@%d by %d\n",			\
-	    __STRING(mtx), __func__, __LINE__, curthread->td_proc->p_pid);	\
-} while (0)
-
-#define fuse_lck_mtx_unlock(mtx) do {						\
-	DEBUGX(FUSE_DEBUG_LOCK, "0: unlock(%s): %s@%d by %d\n",			\
-	    __STRING(mtx), __func__, __LINE__, curthread->td_proc->p_pid);	\
-	mtx_unlock(&(mtx));							\
-	DEBUGX(FUSE_DEBUG_LOCK, "1: unlock(%s): %s@%d by %d\n",			\
-	    __STRING(mtx), __func__, __LINE__, curthread->td_proc->p_pid);	\
-} while (0)
+#define fuse_lck_mtx_lock(mtx) mtx_lock(&(mtx))
+#define fuse_lck_mtx_unlock(mtx) mtx_unlock(&(mtx))
 
 void fuse_ipc_init(void);
 void fuse_ipc_destroy(void);

Modified: head/sys/fs/fuse/fuse_device.c
==============================================================================
--- head/sys/fs/fuse/fuse_device.c	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse_device.c	Fri Mar 29 02:13:06 2019	(r345675)
@@ -73,6 +73,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/mutex.h>
 #include <sys/proc.h>
 #include <sys/mount.h>
+#include <sys/sdt.h>
 #include <sys/stat.h>
 #include <sys/fcntl.h>
 #include <sys/sysctl.h>
@@ -82,8 +83,13 @@ __FBSDID("$FreeBSD$");
 #include "fuse.h"
 #include "fuse_ipc.h"
 
-#define FUSE_DEBUG_MODULE DEVICE
-#include "fuse_debug.h"
+SDT_PROVIDER_DECLARE(fuse);
+/* 
+ * Fuse trace probe:
+ * arg0: verbosity.  Higher numbers give more verbose messages
+ * arg1: Textual message
+ */
+SDT_PROBE_DEFINE2(fuse, , device, trace, "int", "char*");
 
 static struct cdev *fuse_dev;
 
@@ -127,15 +133,14 @@ fuse_device_open(struct cdev *dev, int oflags, int dev
 	struct fuse_data *fdata;
 	int error;
 
-	FS_DEBUG("device %p\n", dev);
+	SDT_PROBE2(fuse, , device, trace, 1, "device open");
 
 	fdata = fdata_alloc(dev, td->td_ucred);
 	error = devfs_set_cdevpriv(fdata, fdata_dtor);
 	if (error != 0)
 		fdata_trydestroy(fdata);
 	else
-		FS_DEBUG("%s: device opened by thread %d.\n", dev->si_name,
-		    td->td_tid);
+		SDT_PROBE2(fuse, , device, trace, 1, "device open success");
 	return (error);
 }
 
@@ -170,7 +175,7 @@ fuse_device_close(struct cdev *dev, int fflag, int dev
 	fuse_lck_mtx_unlock(data->aw_mtx);
 	FUSE_UNLOCK();
 
-	FS_DEBUG("%s: device closed by thread %d.\n", dev->si_name, td->td_tid);
+	SDT_PROBE2(fuse, , device, trace, 1, "device close");
 	return (0);
 }
 
@@ -214,7 +219,7 @@ fuse_device_read(struct cdev *dev, struct uio *uio, in
 	int buflen[3];
 	int i;
 
-	FS_DEBUG("fuse device being read on thread %d\n", uio->uio_td->td_tid);
+	SDT_PROBE2(fuse, , device, trace, 1, "fuse device read");
 
 	err = devfs_get_cdevpriv((void **)&data);
 	if (err != 0)
@@ -223,7 +228,9 @@ fuse_device_read(struct cdev *dev, struct uio *uio, in
 	fuse_lck_mtx_lock(data->ms_mtx);
 again:
 	if (fdata_get_dead(data)) {
-		FS_DEBUG2G("we know early on that reader should be kicked so we don't wait for news\n");
+		SDT_PROBE2(fuse, , device, trace, 2,
+			"we know early on that reader should be kicked so we "
+			"don't wait for news");
 		fuse_lck_mtx_unlock(data->ms_mtx);
 		return (ENODEV);
 	}
@@ -249,7 +256,7 @@ again:
 		 * -- and some other cases, too, tho not totally clear, when
 		 * (cv_signal/wakeup_one signals the whole process ?)
 		 */
-		FS_DEBUG("no message on thread #%d\n", uio->uio_td->td_tid);
+		SDT_PROBE2(fuse, , device, trace, 1, "no message on thread");
 		goto again;
 	}
 	fuse_lck_mtx_unlock(data->ms_mtx);
@@ -259,16 +266,18 @@ again:
 		 * somebody somewhere -- eg., umount routine --
 		 * wants this liaison finished off
 		 */
-		FS_DEBUG2G("reader is to be sacked\n");
+		SDT_PROBE2(fuse, , device, trace, 2, "reader is to be sacked");
 		if (tick) {
-			FS_DEBUG2G("weird -- \"kick\" is set tho there is message\n");
+			SDT_PROBE2(fuse, , device, trace, 2, "weird -- "
+				"\"kick\" is set tho there is message");
 			FUSE_ASSERT_MS_DONE(tick);
 			fuse_ticket_drop(tick);
 		}
 		return (ENODEV);	/* This should make the daemon get off
 					 * of us */
 	}
-	FS_DEBUG("message got on thread #%d\n", uio->uio_td->td_tid);
+	SDT_PROBE2(fuse, , device, trace, 1,
+		"fuse device read message successfully");
 
 	KASSERT(tick->tk_ms_bufdata || tick->tk_ms_bufsize == 0,
 	    ("non-null buf pointer with positive size"));
@@ -302,7 +311,8 @@ again:
 		 */
 		if (uio->uio_resid < buflen[i]) {
 			fdata_set_dead(data);
-			FS_DEBUG2G("daemon is stupid, kick it off...\n");
+			SDT_PROBE2(fuse, , device, trace, 2,
+			    "daemon is stupid, kick it off...");
 			err = ENODEV;
 			break;
 		}
@@ -320,16 +330,14 @@ again:
 static inline int
 fuse_ohead_audit(struct fuse_out_header *ohead, struct uio *uio)
 {
-	FS_DEBUG("Out header -- len: %i, error: %i, unique: %llu; iovecs: %d\n",
-	    ohead->len, ohead->error, (unsigned long long)ohead->unique,
-	    uio->uio_iovcnt);
-
 	if (uio->uio_resid + sizeof(struct fuse_out_header) != ohead->len) {
-		FS_DEBUG("Format error: body size differs from size claimed by header\n");
+		SDT_PROBE2(fuse, , device, trace, 1, "Format error: body size "
+			"differs from size claimed by header");
 		return (EINVAL);
 	}
 	if (uio->uio_resid && ohead->error) {
-		FS_DEBUG("Format error: non zero error but message had a body\n");
+		SDT_PROBE2(fuse, , device, trace, 1, 
+			"Format error: non zero error but message had a body");
 		return (EINVAL);
 	}
 	/* Sanitize the linuxism of negative errnos */
@@ -338,6 +346,8 @@ fuse_ohead_audit(struct fuse_out_header *ohead, struct
 	return (0);
 }
 
+SDT_PROBE_DEFINE1(fuse, , device, fuse_device_write_bumped_into_callback,
+		"uint64_t");
 /*
  * fuse_device_write first reads the header sent by the daemon.
  * If that's OK, looks up ticket/callback node by the unique id seen in header.
@@ -353,15 +363,13 @@ fuse_device_write(struct cdev *dev, struct uio *uio, i
 	struct fuse_ticket *tick, *x_tick;
 	int found = 0;
 
-	FS_DEBUG("resid: %zd, iovcnt: %d, thread: %d\n",
-	    uio->uio_resid, uio->uio_iovcnt, uio->uio_td->td_tid);
-
 	err = devfs_get_cdevpriv((void **)&data);
 	if (err != 0)
 		return (err);
 
 	if (uio->uio_resid < sizeof(struct fuse_out_header)) {
-		FS_DEBUG("got less than a header!\n");
+		SDT_PROBE2(fuse, , device, trace, 1,
+			"fuse_device_write got less than a header!");
 		fdata_set_dead(data);
 		return (EINVAL);
 	}
@@ -385,8 +393,9 @@ fuse_device_write(struct cdev *dev, struct uio *uio, i
 	fuse_lck_mtx_lock(data->aw_mtx);
 	TAILQ_FOREACH_SAFE(tick, &data->aw_head, tk_aw_link,
 	    x_tick) {
-		FS_DEBUG("bumped into callback #%llu\n",
-		    (unsigned long long)tick->tk_unique);
+		SDT_PROBE1(fuse, , device,
+			fuse_device_write_bumped_into_callback,
+			tick->tk_unique);
 		if (tick->tk_unique == ohead.unique) {
 			found = 1;
 			fuse_aw_remove(tick);
@@ -405,12 +414,14 @@ fuse_device_write(struct cdev *dev, struct uio *uio, i
 			 * via ticket_drop(), so no manual mucking
 			 * around...)
 			 */
-			FS_DEBUG("pass ticket to a callback\n");
+			SDT_PROBE2(fuse, , device, trace, 1,
+				"pass ticket to a callback");
 			memcpy(&tick->tk_aw_ohead, &ohead, sizeof(ohead));
 			err = tick->tk_aw_handler(tick, uio);
 		} else {
 			/* pretender doesn't wanna do anything with answer */
-			FS_DEBUG("stuff devalidated, so we drop it\n");
+			SDT_PROBE2(fuse, , device, trace, 1,
+				"stuff devalidated, so we drop it");
 		}
 
 		/*
@@ -421,7 +432,8 @@ fuse_device_write(struct cdev *dev, struct uio *uio, i
 		fuse_ticket_drop(tick);
 	} else {
 		/* no callback at all! */
-		FS_DEBUG("erhm, no handler for this response\n");
+		SDT_PROBE2(fuse, , device, trace, 1,
+			"erhm, no handler for this response");
 		err = EINVAL;
 	}
 

Modified: head/sys/fs/fuse/fuse_file.c
==============================================================================
--- head/sys/fs/fuse/fuse_file.c	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse_file.c	Fri Mar 29 02:13:06 2019	(r345675)
@@ -58,11 +58,10 @@
 #include <sys/cdefs.h>
 __FBSDID("$FreeBSD$");
 
-#include <sys/types.h>
+#include <sys/param.h>
 #include <sys/module.h>
 #include <sys/systm.h>
 #include <sys/errno.h>
-#include <sys/param.h>
 #include <sys/kernel.h>
 #include <sys/conf.h>
 #include <sys/uio.h>
@@ -74,6 +73,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/proc.h>
 #include <sys/mount.h>
 #include <sys/vnode.h>
+#include <sys/sdt.h>
 #include <sys/sysctl.h>
 
 #include "fuse.h"
@@ -82,8 +82,13 @@ __FBSDID("$FreeBSD$");
 #include "fuse_ipc.h"
 #include "fuse_node.h"
 
-#define FUSE_DEBUG_MODULE FILE
-#include "fuse_debug.h"
+SDT_PROVIDER_DECLARE(fuse);
+/* 
+ * Fuse trace probe:
+ * arg0: verbosity.  Higher numbers give more verbose messages
+ * arg1: Textual message
+ */
+SDT_PROBE_DEFINE2(fuse, , file, trace, "int", "char*");
 
 static int fuse_fh_count = 0;
 
@@ -102,9 +107,6 @@ fuse_filehandle_open(struct vnode *vp, fufh_type_t fuf
 	int oflags = 0;
 	int op = FUSE_OPEN;
 
-	fuse_trace_printf("fuse_filehandle_open(vp=%p, fufh_type=%d)\n",
-	    vp, fufh_type);
-
 	if (fuse_filehandle_valid(vp, fufh_type)) {
 		panic("FUSE: filehandle_open called despite valid fufh (type=%d)",
 		    fufh_type);
@@ -118,6 +120,8 @@ fuse_filehandle_open(struct vnode *vp, fufh_type_t fuf
 	if (vnode_isdir(vp)) {
 		op = FUSE_OPENDIR;
 		if (fufh_type != FUFH_RDONLY) {
+			SDT_PROBE2(fuse, , file, trace, 1,
+				"non-rdonly fh requested for a directory?");
 			printf("FUSE:non-rdonly fh requested for a directory?\n");
 			fufh_type = FUFH_RDONLY;
 		}
@@ -129,7 +133,8 @@ fuse_filehandle_open(struct vnode *vp, fufh_type_t fuf
 	foi->flags = oflags;
 
 	if ((err = fdisp_wait_answ(&fdi))) {
-		debug_printf("OUCH ... daemon didn't give fh (err = %d)\n", err);
+		SDT_PROBE2(fuse, , file, trace, 1,
+			"OUCH ... daemon didn't give fh");
 		if (err == ENOENT) {
 			fuse_internal_vnode_disappear(vp);
 		}
@@ -167,9 +172,6 @@ fuse_filehandle_close(struct vnode *vp, fufh_type_t fu
 	int err = 0;
 	int op = FUSE_RELEASE;
 
-	fuse_trace_printf("fuse_filehandle_put(vp=%p, fufh_type=%d)\n",
-	    vp, fufh_type);
-
 	fufh = &(fvdat->fufh[fufh_type]);
 	if (!FUFH_IS_VALID(fufh)) {
 		panic("FUSE: filehandle_put called on invalid fufh (type=%d)",
@@ -266,7 +268,6 @@ fuse_filehandle_init(struct vnode *vp, fufh_type_t fuf
 	struct fuse_vnode_data *fvdat = VTOFUD(vp);
 	struct fuse_filehandle *fufh;
 
-	FS_DEBUG("id=%jd type=%d\n", (intmax_t)fh_id, fufh_type);
 	fufh = &(fvdat->fufh[fufh_type]);
 	MPASS(!FUFH_IS_VALID(fufh));
 	fufh->fh_id = fh_id;

Modified: head/sys/fs/fuse/fuse_internal.c
==============================================================================
--- head/sys/fs/fuse/fuse_internal.c	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse_internal.c	Fri Mar 29 02:13:06 2019	(r345675)
@@ -58,11 +58,10 @@
 #include <sys/cdefs.h>
 __FBSDID("$FreeBSD$");
 
-#include <sys/types.h>
+#include <sys/param.h>
 #include <sys/module.h>
 #include <sys/systm.h>
 #include <sys/errno.h>
-#include <sys/param.h>
 #include <sys/kernel.h>
 #include <sys/conf.h>
 #include <sys/uio.h>
@@ -70,6 +69,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/queue.h>
 #include <sys/lock.h>
 #include <sys/mutex.h>
+#include <sys/sdt.h>
 #include <sys/sx.h>
 #include <sys/proc.h>
 #include <sys/mount.h>
@@ -94,8 +94,13 @@ __FBSDID("$FreeBSD$");
 #include "fuse_file.h"
 #include "fuse_param.h"
 
-#define FUSE_DEBUG_MODULE INTERNAL
-#include "fuse_debug.h"
+SDT_PROVIDER_DECLARE(fuse);
+/* 
+ * Fuse trace probe:
+ * arg0: verbosity.  Higher numbers give more verbose messages
+ * arg1: Textual message
+ */
+SDT_PROBE_DEFINE2(fuse, , internal, trace, "int", "char*");
 
 #ifdef ZERO_PAD_INCOMPLETE_BUFS
 static int isbzero(void *buf, size_t len);
@@ -127,8 +132,6 @@ fuse_internal_access(struct vnode *vp,
 	 */
 	/* return 0;*/
 
-	fuse_trace_printf_func();
-
 	mp = vnode_mount(vp);
 	vtype = vnode_vtype(vp);
 
@@ -204,13 +207,71 @@ fuse_internal_access(struct vnode *vp,
 	return err;
 }
 
+/*
+ * Cache FUSE attributes from feo, in attr cache associated with vnode 'vp'.
+ * Optionally, if argument 'vap' is not NULL, store a copy of the converted
+ * attributes there as well.
+ *
+ * If the nominal attribute cache TTL is zero, do not cache on the 'vp' (but do
+ * return the result to the caller).
+ */
+void
+fuse_internal_cache_attrs(struct vnode *vp, struct fuse_attr *attr,
+	uint64_t attr_valid, uint32_t attr_valid_nsec, struct vattr *vap)
+{
+	struct mount *mp;
+	struct fuse_vnode_data *fvdat;
+	struct vattr *vp_cache_at;
+
+	mp = vnode_mount(vp);
+	fvdat = VTOFUD(vp);
+
+	/* Honor explicit do-not-cache requests from user filesystems. */
+	if (attr_valid == 0 && attr_valid_nsec == 0)
+		fvdat->valid_attr_cache = false;
+	else
+		fvdat->valid_attr_cache = true;
+
+	vp_cache_at = VTOVA(vp);
+
+	if (vap == NULL && vp_cache_at == NULL)
+		return;
+
+	if (vap == NULL)
+		vap = vp_cache_at;
+
+	vattr_null(vap);
+
+	vap->va_fsid = mp->mnt_stat.f_fsid.val[0];
+	vap->va_fileid = attr->ino;
+	vap->va_mode = attr->mode & ~S_IFMT;
+	vap->va_nlink     = attr->nlink;
+	vap->va_uid       = attr->uid;
+	vap->va_gid       = attr->gid;
+	vap->va_rdev      = attr->rdev;
+	vap->va_size      = attr->size;
+	/* XXX on i386, seconds are truncated to 32 bits */
+	vap->va_atime.tv_sec  = attr->atime;
+	vap->va_atime.tv_nsec = attr->atimensec;
+	vap->va_mtime.tv_sec  = attr->mtime;
+	vap->va_mtime.tv_nsec = attr->mtimensec;
+	vap->va_ctime.tv_sec  = attr->ctime;
+	vap->va_ctime.tv_nsec = attr->ctimensec;
+	vap->va_blocksize = PAGE_SIZE;
+	vap->va_type = IFTOVT(attr->mode);
+	vap->va_bytes = attr->blocks * S_BLKSIZE;
+	vap->va_flags = 0;
+
+	if (vap != vp_cache_at && vp_cache_at != NULL)
+		memcpy(vp_cache_at, vap, sizeof(*vap));
+}
+
+
 /* fsync */
 
 int
 fuse_internal_fsync_callback(struct fuse_ticket *tick, struct uio *uio)
 {
-	fuse_trace_printf_func();
-
 	if (tick->tk_aw_ohead.error == ENOSYS) {
 		fsess_set_notimpl(tick->tk_data->mp, fticket_opcode(tick));
 	}
@@ -227,8 +288,6 @@ fuse_internal_fsync(struct vnode *vp,
 	struct fuse_fsync_in *ffsi;
 	struct fuse_dispatcher fdi;
 
-	fuse_trace_printf_func();
-
 	if (vnode_isdir(vp)) {
 		op = FUSE_FSYNCDIR;
 	}
@@ -386,8 +445,6 @@ fuse_internal_remove(struct vnode *dvp,
 	err = 0;
 	fvdat = VTOFUD(vp);
 
-	debug_printf("dvp=%p, cnp=%p, op=%d\n", vp, cnp, op);
-
 	fdisp_init(&fdi, cnp->cn_namelen + 1);
 	fdisp_make_vp(&fdi, op, dvp, cnp->cn_thread, cnp->cn_cred);
 
@@ -442,8 +499,6 @@ fuse_internal_newentry_makerequest(struct mount *mp,
     size_t bufsize,
     struct fuse_dispatcher *fdip)
 {
-	debug_printf("fdip=%p\n", fdip);
-
 	fdip->iosize = bufsize + cnp->cn_namelen + 1;
 
 	fdisp_make(fdip, op, mp, dnid, cnp->cn_thread, cnp->cn_cred);
@@ -477,7 +532,8 @@ fuse_internal_newentry_core(struct vnode *dvp,
 		    feo->nodeid, 1);
 		return err;
 	}
-	cache_attrs(*vpp, feo, NULL);
+	fuse_internal_cache_attrs(*vpp, &feo->attr, feo->attr_valid,
+		feo->attr_valid_nsec, NULL);
 
 	return err;
 }
@@ -526,9 +582,6 @@ fuse_internal_forget_send(struct mount *mp,
 	struct fuse_dispatcher fdi;
 	struct fuse_forget_in *ffi;
 
-	debug_printf("mp=%p, nodeid=%ju, nlookup=%ju\n",
-	    mp, (uintmax_t)nodeid, (uintmax_t)nlookup);
-
 	/*
          * KASSERT(nlookup > 0, ("zero-times forget for vp #%llu",
          *         (long long unsigned) nodeid));
@@ -574,7 +627,8 @@ fuse_internal_init_callback(struct fuse_ticket *tick, 
 
 	/* XXX: Do we want to check anything further besides this? */
 	if (fiio->major < 7) {
-		debug_printf("userpace version too low\n");
+		SDT_PROBE2(fuse, , internal, trace, 1,
+			"userpace version too low");
 		err = EPROTONOSUPPORT;
 		goto out;
 	}

Modified: head/sys/fs/fuse/fuse_internal.h
==============================================================================
--- head/sys/fs/fuse/fuse_internal.h	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse_internal.h	Fri Mar 29 02:13:06 2019	(r345675)
@@ -193,75 +193,9 @@ int fuse_internal_access(struct vnode *vp, mode_t mode
     struct fuse_access_param *facp, struct thread *td, struct ucred *cred);
 
 /* attributes */
+void fuse_internal_cache_attrs(struct vnode *vp, struct fuse_attr *attr,
+	uint64_t attr_valid, uint32_t attr_valid_nsec, struct vattr *vap);
 
-/*
- * Cache FUSE attributes 'fat', with nominal expiration
- * 'attr_valid'.'attr_valid_nsec', in attr cache associated with vnode 'vp'.
- * Optionally, if argument 'vap' is not NULL, store a copy of the converted
- * attributes there as well.
- *
- * If the nominal attribute cache TTL is zero, do not cache on the 'vp' (but do
- * return the result to the caller).
- */
-static inline void
-fuse_internal_attr_fat2vat(struct vnode *vp, struct fuse_attr *fat,
-    uint64_t attr_valid, uint32_t attr_valid_nsec, struct vattr *vap)
-{
-	struct mount *mp;
-	struct fuse_vnode_data *fvdat;
-	struct vattr *vp_cache_at;
-
-	mp = vnode_mount(vp);
-	fvdat = VTOFUD(vp);
-
-	DEBUGX(FUSE_DEBUG_INTERNAL, "node #%ju, mode 0%o\n",
-	    (uintmax_t)fat->ino, fat->mode);
-
-	/* Honor explicit do-not-cache requests from user filesystems. */
-	if (attr_valid == 0 && attr_valid_nsec == 0)
-		fvdat->valid_attr_cache = false;
-	else
-		fvdat->valid_attr_cache = true;
-
-	vp_cache_at = VTOVA(vp);
-
-	if (vap == NULL && vp_cache_at == NULL)
-		return;
-
-	if (vap == NULL)
-		vap = vp_cache_at;
-
-	vattr_null(vap);
-
-	vap->va_fsid = mp->mnt_stat.f_fsid.val[0];
-	vap->va_fileid = fat->ino;
-	vap->va_mode = fat->mode & ~S_IFMT;
-	vap->va_nlink     = fat->nlink;
-	vap->va_uid       = fat->uid;
-	vap->va_gid       = fat->gid;
-	vap->va_rdev      = fat->rdev;
-	vap->va_size      = fat->size;
-	/* XXX on i386, seconds are truncated to 32 bits */
-	vap->va_atime.tv_sec  = fat->atime;
-	vap->va_atime.tv_nsec = fat->atimensec;
-	vap->va_mtime.tv_sec  = fat->mtime;
-	vap->va_mtime.tv_nsec = fat->mtimensec;
-	vap->va_ctime.tv_sec  = fat->ctime;
-	vap->va_ctime.tv_nsec = fat->ctimensec;
-	vap->va_blocksize = PAGE_SIZE;
-	vap->va_type = IFTOVT(fat->mode);
-	vap->va_bytes = fat->blocks * S_BLKSIZE;
-	vap->va_flags = 0;
-
-	if (vap != vp_cache_at && vp_cache_at != NULL)
-		memcpy(vp_cache_at, vap, sizeof(*vap));
-}
-
-
-#define	cache_attrs(vp, fuse_out, vap_out)				\
-	fuse_internal_attr_fat2vat((vp), &(fuse_out)->attr,		\
-	    (fuse_out)->attr_valid, (fuse_out)->attr_valid_nsec, (vap_out))
-
 /* fsync */
 
 int fuse_internal_fsync(struct vnode *vp, struct thread *td,
@@ -300,24 +234,15 @@ void fuse_internal_vnode_disappear(struct vnode *vp);
 static inline int
 fuse_internal_checkentry(struct fuse_entry_out *feo, enum vtype vtyp)
 {
-	DEBUGX(FUSE_DEBUG_INTERNAL,
-	    "feo=%p, vtype=%d\n", feo, vtyp);
-
 	if (vtyp != IFTOVT(feo->attr.mode)) {
-		DEBUGX(FUSE_DEBUG_INTERNAL,
-		    "EINVAL -- %x != %x\n", vtyp, IFTOVT(feo->attr.mode));
 		return (EINVAL);
 	}
 
 	if (feo->nodeid == FUSE_NULL_ID) {
-		DEBUGX(FUSE_DEBUG_INTERNAL,
-		    "EINVAL -- feo->nodeid is NULL\n");
 		return (EINVAL);
 	}
 
 	if (feo->nodeid == FUSE_ROOT_ID) {
-		DEBUGX(FUSE_DEBUG_INTERNAL,
-		    "EINVAL -- feo->nodeid is FUSE_ROOT_ID\n");
 		return (EINVAL);
 	}
 

Modified: head/sys/fs/fuse/fuse_io.c
==============================================================================
--- head/sys/fs/fuse/fuse_io.c	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse_io.c	Fri Mar 29 02:13:06 2019	(r345675)
@@ -98,10 +98,14 @@ __FBSDID("$FreeBSD$");
 #include "fuse_ipc.h"
 #include "fuse_io.h"
 
-#define FUSE_DEBUG_MODULE IO
-#include "fuse_debug.h"
+SDT_PROVIDER_DECLARE(fuse);
+/* 
+ * Fuse trace probe:
+ * arg0: verbosity.  Higher numbers give more verbose messages
+ * arg1: Textual message
+ */
+SDT_PROBE_DEFINE2(fuse, , io, trace, "int", "char*");
 
-
 static int 
 fuse_read_directbackend(struct vnode *vp, struct uio *uio,
     struct ucred *cred, struct fuse_filehandle *fufh);
@@ -115,6 +119,8 @@ static int 
 fuse_write_biobackend(struct vnode *vp, struct uio *uio,
     struct ucred *cred, struct fuse_filehandle *fufh, int ioflag);
 
+SDT_PROBE_DEFINE5(fuse, , io, io_dispatch, "struct vnode*", "struct uio*",
+		"int", "struct ucred*", "struct fuse_filehandle*");
 int
 fuse_io_dispatch(struct vnode *vp, struct uio *uio, int ioflag,
     struct ucred *cred)
@@ -130,6 +136,8 @@ fuse_io_dispatch(struct vnode *vp, struct uio *uio, in
 		printf("FUSE: io dispatch: filehandles are closed\n");
 		return err;
 	}
+	SDT_PROBE5(fuse, , io, io_dispatch, vp, uio, ioflag, cred, fufh);
+
 	/*
          * Ideally, when the daemon asks for direct io at open time, the
          * standard file flag should be set according to this, so that would
@@ -145,12 +153,12 @@ fuse_io_dispatch(struct vnode *vp, struct uio *uio, in
 	switch (uio->uio_rw) {
 	case UIO_READ:
 		if (directio) {
-			FS_DEBUG("direct read of vnode %ju via file handle %ju\n",
-			    (uintmax_t)VTOILLU(vp), (uintmax_t)fufh->fh_id);
+			SDT_PROBE2(fuse, , io, trace, 1,
+				"direct read of vnode");
 			err = fuse_read_directbackend(vp, uio, cred, fufh);
 		} else {
-			FS_DEBUG("buffered read of vnode %ju\n", 
-			      (uintmax_t)VTOILLU(vp));
+			SDT_PROBE2(fuse, , io, trace, 1,
+				"buffered read of vnode");
 			err = fuse_read_biobackend(vp, uio, cred, fufh);
 		}
 		break;
@@ -162,12 +170,12 @@ fuse_io_dispatch(struct vnode *vp, struct uio *uio, in
 		 * cached.
 		 */
 		if (directio || fuse_data_cache_mode == FUSE_CACHE_WT) {
-			FS_DEBUG("direct write of vnode %ju via file handle %ju\n",
-			    (uintmax_t)VTOILLU(vp), (uintmax_t)fufh->fh_id);
+			SDT_PROBE2(fuse, , io, trace, 1,
+				"direct write of vnode");
 			err = fuse_write_directbackend(vp, uio, cred, fufh, ioflag);
 		} else {
-			FS_DEBUG("buffered write of vnode %ju\n", 
-			      (uintmax_t)VTOILLU(vp));
+			SDT_PROBE2(fuse, , io, trace, 1,
+				"buffered write of vnode");
 			err = fuse_write_biobackend(vp, uio, cred, fufh, ioflag);
 		}
 		break;
@@ -178,6 +186,9 @@ fuse_io_dispatch(struct vnode *vp, struct uio *uio, in
 	return (err);
 }
 
+SDT_PROBE_DEFINE3(fuse, , io, read_bio_backend_start, "int", "int", "int");
+SDT_PROBE_DEFINE2(fuse, , io, read_bio_backend_feed, "int", "int");
+SDT_PROBE_DEFINE3(fuse, , io, read_bio_backend_end, "int", "ssize_t", "int");
 static int
 fuse_read_biobackend(struct vnode *vp, struct uio *uio,
     struct ucred *cred, struct fuse_filehandle *fufh)
@@ -190,9 +201,6 @@ fuse_read_biobackend(struct vnode *vp, struct uio *uio
 
 	const int biosize = fuse_iosize(vp);
 
-	FS_DEBUG("resid=%zx offset=%jx fsize=%jx\n",
-	    uio->uio_resid, uio->uio_offset, VTOFUD(vp)->filesize);
-
 	if (uio->uio_resid == 0)
 		return (0);
 	if (uio->uio_offset < 0)
@@ -209,7 +217,8 @@ fuse_read_biobackend(struct vnode *vp, struct uio *uio
 		lbn = uio->uio_offset / biosize;
 		on = uio->uio_offset & (biosize - 1);
 
-		FS_DEBUG2G("biosize %d, lbn %d, on %d\n", biosize, (int)lbn, on);
+		SDT_PROBE3(fuse, , io, read_bio_backend_start,
+			biosize, (int)lbn, on);
 
 		/*
 	         * Obtain the buffer cache block.  Figure out the buffer size
@@ -258,19 +267,22 @@ fuse_read_biobackend(struct vnode *vp, struct uio *uio
 		if (on < bcount)
 			n = MIN((unsigned)(bcount - on), uio->uio_resid);
 		if (n > 0) {
-			FS_DEBUG2G("feeding buffeater with %d bytes of buffer %p,"
-				" saying %d was asked for\n",
-				n, bp->b_data + on, n + (int)bp->b_resid);
+			SDT_PROBE2(fuse, , io, read_bio_backend_feed,
+				n, n + (int)bp->b_resid);
 			err = uiomove(bp->b_data + on, n, uio);
 		}
 		brelse(bp);
-		FS_DEBUG2G("end of turn, err %d, uio->uio_resid %zd, n %d\n",
-		    err, uio->uio_resid, n);
+		SDT_PROBE3(fuse, , io, read_bio_backend_end, err,
+			uio->uio_resid, n);
 	} while (err == 0 && uio->uio_resid > 0 && n > 0);
 
 	return (err);
 }
 
+SDT_PROBE_DEFINE1(fuse, , io, read_directbackend_start, "struct fuse_read_in*");
+SDT_PROBE_DEFINE2(fuse, , io, read_directbackend_complete,
+	"struct fuse_dispatcher*", "struct uio*");
+
 static int
 fuse_read_directbackend(struct vnode *vp, struct uio *uio,
     struct ucred *cred, struct fuse_filehandle *fufh)
@@ -301,17 +313,13 @@ fuse_read_directbackend(struct vnode *vp, struct uio *
 		fri->size = MIN(uio->uio_resid,
 		    fuse_get_mpdata(vp->v_mount)->max_read);
 
-		FS_DEBUG2G("fri->fh %ju, fri->offset %ju, fri->size %ju\n",
-			(uintmax_t)fri->fh, (uintmax_t)fri->offset, 
-			(uintmax_t)fri->size);
+		SDT_PROBE1(fuse, , io, read_directbackend_start, fri);
 
 		if ((err = fdisp_wait_answ(&fdi)))
 			goto out;
 
-		FS_DEBUG2G("complete: got iosize=%d, requested fri.size=%zd; "
-			"resid=%zd offset=%ju\n",
-			fri->size, fdi.iosize, uio->uio_resid, 
-			(uintmax_t)uio->uio_offset);
+		SDT_PROBE2(fuse, , io, read_directbackend_complete,
+			fdi.iosize, uio);
 
 		if ((err = uiomove(fdi.answ, MIN(fri->size, fdi.iosize), uio)))
 			break;
@@ -361,13 +369,24 @@ fuse_write_directbackend(struct vnode *vp, struct uio 
 		if ((err = fdisp_wait_answ(&fdi)))
 			break;
 
+		/* Adjust the uio in the case of short writes */
 		diff = chunksize - ((struct fuse_write_out *)fdi.answ)->size;
 		if (diff < 0) {
 			err = EINVAL;
 			break;
+		} else if (diff > 0 && !(ioflag & IO_DIRECT)) {
+			/* 
+			 * XXX We really should be directly checking whether
+			 * the file was opened with FOPEN_DIRECT_IO, not
+			 * IO_DIRECT.  IO_DIRECT can be set in multiple ways.
+			 */
+			SDT_PROBE2(fuse, , io, trace, 1,
+				"misbehaving filesystem: short writes are only "
+				"allowed with direct_io");
 		}
 		uio->uio_resid += diff;
 		uio->uio_offset -= diff;
+
 		if (uio->uio_offset > fvdat->filesize &&
 		    fuse_data_cache_mode != FUSE_CACHE_UC) {
 			fuse_vnode_setsize(vp, cred, uio->uio_offset);
@@ -380,6 +399,10 @@ fuse_write_directbackend(struct vnode *vp, struct uio 
 	return (err);
 }
 
+SDT_PROBE_DEFINE6(fuse, , io, write_biobackend_start, "int64_t", "int", "int",
+		"struct uio*", "int", "bool");
+SDT_PROBE_DEFINE2(fuse, , io, write_biobackend_append_race, "long", "int");
+
 static int
 fuse_write_biobackend(struct vnode *vp, struct uio *uio,
     struct ucred *cred, struct fuse_filehandle *fufh, int ioflag)
@@ -393,8 +416,6 @@ fuse_write_biobackend(struct vnode *vp, struct uio *ui
 	const int biosize = fuse_iosize(vp);
 
 	KASSERT(uio->uio_rw == UIO_WRITE, ("ncl_write mode"));
-	FS_DEBUG("resid=%zx offset=%jx fsize=%jx\n",
-	    uio->uio_resid, uio->uio_offset, fvdat->filesize);
 	if (vp->v_type != VREG)
 		return (EIO);
 	if (uio->uio_offset < 0)
@@ -421,10 +442,6 @@ fuse_write_biobackend(struct vnode *vp, struct uio *ui
 		on = uio->uio_offset & (biosize - 1);
 		n = MIN((unsigned)(biosize - on), uio->uio_resid);
 
-		FS_DEBUG2G("lbn %ju, on %d, n %d, uio offset %ju, uio resid %zd\n",
-			(uintmax_t)lbn, on, n, 
-			(uintmax_t)uio->uio_offset, uio->uio_resid);
-
 again:
 		/*
 	         * Handle direct append and file extension cases, calculate
@@ -438,7 +455,8 @@ again:
 	                 * readers from reading garbage.
 	                 */
 			bcount = on;
-			FS_DEBUG("getting block from OS, bcount %d\n", bcount);
+			SDT_PROBE6(fuse, , io, write_biobackend_start,
+				lbn, on, n, uio, bcount, true);
 			bp = getblk(vp, lbn, bcount, PCATCH, 0, 0);
 
 			if (bp != NULL) {
@@ -468,7 +486,8 @@ again:
 					bcount = fvdat->filesize - 
 					  (off_t)lbn *biosize;
 			}
-			FS_DEBUG("getting block from OS, bcount %d\n", bcount);
+			SDT_PROBE6(fuse, , io, write_biobackend_start,
+				lbn, on, n, uio, bcount, false);
 			bp = getblk(vp, lbn, bcount, PCATCH, 0, 0);
 			if (bp && uio->uio_offset + n > fvdat->filesize) {
 				err = fuse_vnode_setsize(vp, cred, 
@@ -530,7 +549,7 @@ again:
 	         */
 
 		if (bp->b_dirtyend > bcount) {
-			FS_DEBUG("FUSE append race @%lx:%d\n",
+			SDT_PROBE2(fuse, , io, write_biobackend_append_race,
 			    (long)bp->b_blkno * biosize,
 			    bp->b_dirtyend - bcount);
 			bp->b_dirtyend = bcount;
@@ -626,9 +645,6 @@ fuse_io_strategy(struct vnode *vp, struct buf *bp)
 
 	MPASS(vp->v_type == VREG || vp->v_type == VDIR);
 	MPASS(bp->b_iocmd == BIO_READ || bp->b_iocmd == BIO_WRITE);
-	FS_DEBUG("inode=%ju offset=%jd resid=%ld\n",
-	    (uintmax_t)VTOI(vp), (intmax_t)(((off_t)bp->b_blkno) * biosize),
-	    bp->b_bcount);
 
 	error = fuse_filehandle_getrw(vp,
 	    (bp->b_iocmd == BIO_READ) ? FUFH_RDONLY : FUFH_WRONLY, &fufh);
@@ -701,7 +717,8 @@ fuse_io_strategy(struct vnode *vp, struct buf *bp)
 	         * If we only need to commit, try to commit
 	         */
 		if (bp->b_flags & B_NEEDCOMMIT) {
-			FS_DEBUG("write: B_NEEDCOMMIT flags set\n");
+			SDT_PROBE2(fuse, , io, trace, 1,
+				"write: B_NEEDCOMMIT flags set");
 		}
 		/*
 	         * Setup for actual write

Modified: head/sys/fs/fuse/fuse_ipc.c
==============================================================================
--- head/sys/fs/fuse/fuse_ipc.c	Fri Mar 29 02:11:48 2019	(r345674)
+++ head/sys/fs/fuse/fuse_ipc.c	Fri Mar 29 02:13:06 2019	(r345675)
@@ -58,11 +58,10 @@
 #include <sys/cdefs.h>
 __FBSDID("$FreeBSD$");
 
-#include <sys/types.h>
+#include <sys/param.h>
 #include <sys/module.h>
 #include <sys/systm.h>
 #include <sys/errno.h>
-#include <sys/param.h>
 #include <sys/kernel.h>
 #include <sys/conf.h>
 #include <sys/uio.h>
@@ -73,6 +72,7 @@ __FBSDID("$FreeBSD$");
 #include <sys/mutex.h>
 #include <sys/proc.h>
 #include <sys/mount.h>
+#include <sys/sdt.h>
 #include <sys/vnode.h>
 #include <sys/signalvar.h>
 #include <sys/syscallsubr.h>
@@ -84,8 +84,13 @@ __FBSDID("$FreeBSD$");
 #include "fuse_ipc.h"
 #include "fuse_internal.h"
 
-#define FUSE_DEBUG_MODULE IPC
-#include "fuse_debug.h"
+SDT_PROVIDER_DECLARE(fuse);
+/* 
+ * Fuse trace probe:
+ * arg0: verbosity.  Higher numbers give more verbose messages
+ * arg1: Textual message
+ */
+SDT_PROBE_DEFINE2(fuse, , ipc, trace, "int", "char*");
 
 static struct fuse_ticket *fticket_alloc(struct fuse_data *data);
 static void fticket_refresh(struct fuse_ticket *ftick);
@@ -146,8 +151,6 @@ fiov_init(struct fuse_iov *fiov, size_t size)
 {
 	uint32_t msize = FU_AT_LEAST(size);
 
-	debug_printf("fiov=%p, size=%zd\n", fiov, size);
-
 	fiov->len = 0;
 
 	fiov->base = malloc(msize, M_FUSEMSG, M_WAITOK | M_ZERO);
@@ -159,8 +162,6 @@ fiov_init(struct fuse_iov *fiov, size_t size)
 void
 fiov_teardown(struct fuse_iov *fiov)
 {
-	debug_printf("fiov=%p\n", fiov);
-
 	MPASS(fiov->base != NULL);
 	free(fiov->base, M_FUSEMSG);
 }
@@ -168,8 +169,6 @@ fiov_teardown(struct fuse_iov *fiov)
 void
 fiov_adjust(struct fuse_iov *fiov, size_t size)
 {
-	debug_printf("fiov=%p, size=%zd\n", fiov, size);
-
 	if (fiov->allocated_size < size ||
 	    (fuse_iov_permanent_bufsize >= 0 &&
 	    fiov->allocated_size - size > fuse_iov_permanent_bufsize &&
@@ -189,8 +188,6 @@ fiov_adjust(struct fuse_iov *fiov, size_t size)
 void
 fiov_refresh(struct fuse_iov *fiov)
 {
-	debug_printf("fiov=%p\n", fiov);
-
 	bzero(fiov->base, fiov->len);
 	fiov_adjust(fiov, 0);
 }
@@ -201,8 +198,6 @@ fticket_ctor(void *mem, int size, void *arg, int flags
 	struct fuse_ticket *ftick = mem;
 	struct fuse_data *data = arg;
 
-	debug_printf("ftick=%p data=%p\n", ftick, data);
-
 	FUSE_ASSERT_MS_DONE(ftick);
 	FUSE_ASSERT_AW_DONE(ftick);
 
@@ -227,8 +222,6 @@ fticket_dtor(void *mem, int size, void *arg)
 {
 	struct fuse_ticket *ftick = mem;
 
-	debug_printf("ftick=%p\n", ftick);
-
 	FUSE_ASSERT_MS_DONE(ftick);
 	FUSE_ASSERT_AW_DONE(ftick);
 
@@ -240,8 +233,6 @@ fticket_init(void *mem, int size, int flags)
 {
 	struct fuse_ticket *ftick = mem;
 
-	FS_DEBUG("ftick=%p\n", ftick);
-
 	bzero(ftick, sizeof(struct fuse_ticket));
 
 	fiov_init(&ftick->tk_ms_fiov, sizeof(struct fuse_in_header));
@@ -259,8 +250,6 @@ fticket_fini(void *mem, int size)

*** DIFF OUTPUT TRUNCATED AT 1000 LINES ***





Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201903290213.x2T2D7kd058602>