svn commit: r344664 - projects/fuse2/sys/fs/fuse
Alan Somers
asomers at FreeBSD.org
Thu Feb 28 19:27:57 UTC 2019
Author: asomers
Date: Thu Feb 28 19:27:54 2019
New Revision: 344664
URL: https://svnweb.freebsd.org/changeset/base/344664
Log:
fuse(4): 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.
Sponsored by: The FreeBSD Foundation
Deleted:
projects/fuse2/sys/fs/fuse/fuse_debug.h
Modified:
projects/fuse2/sys/fs/fuse/fuse_device.c
projects/fuse2/sys/fs/fuse/fuse_file.c
projects/fuse2/sys/fs/fuse/fuse_internal.c
projects/fuse2/sys/fs/fuse/fuse_io.c
projects/fuse2/sys/fs/fuse/fuse_ipc.c
projects/fuse2/sys/fs/fuse/fuse_main.c
projects/fuse2/sys/fs/fuse/fuse_node.c
projects/fuse2/sys/fs/fuse/fuse_vfsops.c
projects/fuse2/sys/fs/fuse/fuse_vnops.c
Modified: projects/fuse2/sys/fs/fuse/fuse_device.c
==============================================================================
--- projects/fuse2/sys/fs/fuse/fuse_device.c Thu Feb 28 19:19:02 2019 (r344663)
+++ projects/fuse2/sys/fs/fuse/fuse_device.c Thu Feb 28 19:27:54 2019 (r344664)
@@ -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: projects/fuse2/sys/fs/fuse/fuse_file.c
==============================================================================
--- projects/fuse2/sys/fs/fuse/fuse_file.c Thu Feb 28 19:19:02 2019 (r344663)
+++ projects/fuse2/sys/fs/fuse/fuse_file.c Thu Feb 28 19:27:54 2019 (r344664)
@@ -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: projects/fuse2/sys/fs/fuse/fuse_internal.c
==============================================================================
--- projects/fuse2/sys/fs/fuse/fuse_internal.c Thu Feb 28 19:19:02 2019 (r344663)
+++ projects/fuse2/sys/fs/fuse/fuse_internal.c Thu Feb 28 19:27:54 2019 (r344664)
@@ -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);
@@ -209,8 +212,6 @@ fuse_internal_access(struct vnode *vp,
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 +228,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 +385,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 +439,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);
@@ -526,9 +521,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 +566,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: projects/fuse2/sys/fs/fuse/fuse_io.c
==============================================================================
--- projects/fuse2/sys/fs/fuse/fuse_io.c Thu Feb 28 19:19:02 2019 (r344663)
+++ projects/fuse2/sys/fs/fuse/fuse_io.c Thu Feb 28 19:27:54 2019 (r344664)
@@ -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;
@@ -380,6 +388,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 +405,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 +431,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 +444,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 +475,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 +538,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 +634,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 +706,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: projects/fuse2/sys/fs/fuse/fuse_ipc.c
==============================================================================
--- projects/fuse2/sys/fs/fuse/fuse_ipc.c Thu Feb 28 19:19:02 2019 (r344663)
+++ projects/fuse2/sys/fs/fuse/fuse_ipc.c Thu Feb 28 19:27:54 2019 (r344664)
@@ -58,22 +58,24 @@
#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>
#include <sys/malloc.h>
+#include <sys/param.h>
#include <sys/queue.h>
#include <sys/lock.h>
#include <sys/sx.h>
#include <sys/mutex.h>
#include <sys/proc.h>
#include <sys/mount.h>
+#include <sys/sdt.h>
#include <sys/vnode.h>
+#include <sys/sdt.h>
#include <sys/signalvar.h>
#include <sys/syscallsubr.h>
#include <sys/sysctl.h>
@@ -84,8 +86,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 +153,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 +164,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 +171,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 +190,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 +200,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 +224,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 +235,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 +252,6 @@ fticket_fini(void *mem, int size)
{
struct fuse_ticket *ftick = mem;
- FS_DEBUG("ftick=%p\n", ftick);
-
fiov_teardown(&ftick->tk_ms_fiov);
fiov_teardown(&ftick->tk_aw_fiov);
mtx_destroy(&ftick->tk_aw_mtx);
@@ -282,8 +273,6 @@ static inline
void
fticket_refresh(struct fuse_ticket *ftick)
{
- debug_printf("ftick=%p\n", ftick);
-
FUSE_ASSERT_MS_DONE(ftick);
FUSE_ASSERT_AW_DONE(ftick);
@@ -310,9 +299,6 @@ fticket_wait_answer(struct fuse_ticket *ftick)
int err = 0;
struct fuse_data *data;
- debug_printf("ftick=%p\n", ftick);
- fuse_lck_mtx_lock(ftick->tk_aw_mtx);
-
if (fticket_answered(ftick)) {
goto out;
}
@@ -338,7 +324,8 @@ fticket_wait_answer(struct fuse_ticket *ftick)
}
out:
if (!(err || fticket_answered(ftick))) {
- debug_printf("FUSE: requester was woken up but still no answer");
+ SDT_PROBE2(fuse, , ipc, trace, 1,
+ "FUSE: requester was woken up but still no answer");
err = ENXIO;
}
fuse_lck_mtx_unlock(ftick->tk_aw_mtx);
@@ -353,29 +340,16 @@ fticket_aw_pull_uio(struct fuse_ticket *ftick, struct
int err = 0;
size_t len = uio_resid(uio);
- debug_printf("ftick=%p, uio=%p\n", ftick, uio);
-
if (len) {
switch (ftick->tk_aw_type) {
case FT_A_FIOV:
fiov_adjust(fticket_resp(ftick), len);
err = uiomove(fticket_resp(ftick)->base, len, uio);
- if (err) {
- debug_printf("FUSE: FT_A_FIOV: error is %d"
- " (%p, %zd, %p)\n",
- err, fticket_resp(ftick)->base,
- len, uio);
- }
break;
case FT_A_BUF:
ftick->tk_aw_bufsize = len;
err = uiomove(ftick->tk_aw_bufdata, len, uio);
- if (err) {
- debug_printf("FUSE: FT_A_BUF: error is %d"
- " (%p, %zd, %p)\n",
- err, ftick->tk_aw_bufdata, len, uio);
- }
break;
default:
@@ -390,8 +364,6 @@ fticket_pull(struct fuse_ticket *ftick, struct uio *ui
{
int err = 0;
- debug_printf("ftick=%p, uio=%p\n", ftick, uio);
-
if (ftick->tk_aw_ohead.error) {
return 0;
}
@@ -407,8 +379,6 @@ fdata_alloc(struct cdev *fdev, struct ucred *cred)
{
struct fuse_data *data;
- debug_printf("fdev=%p\n", fdev);
-
data = malloc(sizeof(struct fuse_data), M_FUSEMSG, M_WAITOK | M_ZERO);
data->fdev = fdev;
@@ -427,10 +397,6 @@ fdata_alloc(struct cdev *fdev, struct ucred *cred)
void
fdata_trydestroy(struct fuse_data *data)
{
- FS_DEBUG("data=%p data.mp=%p data.fdev=%p data.flags=%04x\n",
- data, data->mp, data->fdev, data->dataflags);
-
- FS_DEBUG("destroy: data=%p\n", data);
data->ref--;
MPASS(data->ref >= 0);
if (data->ref != 0)
@@ -449,8 +415,6 @@ fdata_trydestroy(struct fuse_data *data)
void
fdata_set_dead(struct fuse_data *data)
{
- debug_printf("data=%p\n", data);
-
FUSE_LOCK();
if (fdata_get_dead(data)) {
FUSE_UNLOCK();
@@ -471,8 +435,6 @@ fuse_ticket_fetch(struct fuse_data *data)
int err = 0;
struct fuse_ticket *ftick;
- debug_printf("data=%p\n", data);
-
ftick = fticket_alloc(data);
if (!(data->dataflags & FSESS_INITED)) {
@@ -495,7 +457,6 @@ fuse_ticket_drop(struct fuse_ticket *ftick)
int die;
die = refcount_release(&ftick->tk_refcount);
- debug_printf("ftick=%p refcount=%d\n", ftick, ftick->tk_refcount);
if (die)
fticket_destroy(ftick);
@@ -505,9 +466,6 @@ fuse_ticket_drop(struct fuse_ticket *ftick)
void
fuse_insert_callback(struct fuse_ticket *ftick, fuse_handler_t * handler)
{
- debug_printf("ftick=%p, handler=%p data=%p\n", ftick, ftick->tk_data,
- handler);
-
if (fdata_get_dead(ftick->tk_data)) {
return;
}
@@ -521,8 +479,6 @@ fuse_insert_callback(struct fuse_ticket *ftick, fuse_h
void
fuse_insert_message(struct fuse_ticket *ftick)
{
- debug_printf("ftick=%p\n", ftick);
-
if (ftick->tk_flag & FT_DIRTY) {
panic("FUSE: ticket reused without being refreshed");
}
@@ -544,8 +500,6 @@ fuse_body_audit(struct fuse_ticket *ftick, size_t blen
int err = 0;
enum fuse_opcode opcode;
- debug_printf("ftick=%p, blen = %zu\n", ftick, blen);
-
opcode = fticket_opcode(ftick);
switch (opcode) {
@@ -719,9 +673,6 @@ fuse_setup_ihead(struct fuse_in_header *ihead, struct
ihead->nodeid = nid;
ihead->opcode = op;
- debug_printf("ihead=%p, ftick=%p, nid=%ju, op=%d, blen=%zu\n",
- ihead, ftick, (uintmax_t)nid, op, blen);
-
ihead->pid = pid;
ihead->uid = cred->cr_uid;
ihead->gid = cred->cr_rgid;
@@ -738,8 +689,6 @@ fuse_standard_handler(struct fuse_ticket *ftick, struc
{
int err = 0;
- debug_printf("ftick=%p, uio=%p\n", ftick, uio);
-
err = fticket_pull(ftick, uio);
fuse_lck_mtx_lock(ftick->tk_aw_mtx);
@@ -760,9 +709,6 @@ fdisp_make_pid(struct fuse_dispatcher *fdip, enum fuse
{
struct fuse_data *data = fuse_get_mpdata(mp);
- debug_printf("fdip=%p, op=%d, mp=%p, nid=%ju\n",
- fdip, op, mp, (uintmax_t)nid);
-
if (fdip->tick) {
fticket_refresh(fdip->tick);
} else {
@@ -788,12 +734,13 @@ void
fdisp_make_vp(struct fuse_dispatcher *fdip, enum fuse_opcode op,
struct vnode *vp, struct thread *td, struct ucred *cred)
{
- debug_printf("fdip=%p, op=%d, vp=%p\n", fdip, op, vp);
RECTIFY_TDCR(td, cred);
return fdisp_make_pid(fdip, op, vnode_mount(vp), VTOI(vp),
td->td_proc->p_pid, cred);
}
+SDT_PROBE_DEFINE2(fuse, , ipc, fdisp_wait_answ_error, "char*", "int");
+
int
fdisp_wait_answ(struct fuse_dispatcher *fdip)
{
@@ -804,8 +751,6 @@ fdisp_wait_answ(struct fuse_dispatcher *fdip)
fuse_insert_message(fdip->tick);
if ((err = fticket_wait_answer(fdip->tick))) {
- debug_printf("IPC: interrupted, err = %d\n", err);
-
fuse_lck_mtx_lock(fdip->tick->tk_aw_mtx);
if (fticket_answered(fdip->tick)) {
@@ -814,7 +759,8 @@ fdisp_wait_answ(struct fuse_dispatcher *fdip)
* the standard handler has completed his job.
* So we drop the ticket and exit as usual.
*/
- debug_printf("IPC: already answered\n");
+ SDT_PROBE2(fuse, , ipc, fdisp_wait_answ_error,
+ "IPC: interrupted, already answered", err);
fuse_lck_mtx_unlock(fdip->tick->tk_aw_mtx);
goto out;
} else {
@@ -823,23 +769,23 @@ fdisp_wait_answ(struct fuse_dispatcher *fdip)
* Then by setting the answered flag we get *him*
* to drop the ticket.
*/
- debug_printf("IPC: setting to answered\n");
+ SDT_PROBE2(fuse, , ipc, fdisp_wait_answ_error,
+ "IPC: interrupted, setting to answered", err);
fticket_set_answered(fdip->tick);
fuse_lck_mtx_unlock(fdip->tick->tk_aw_mtx);
return err;
}
}
- debug_printf("IPC: not interrupted, err = %d\n", err);
if (fdip->tick->tk_aw_errno) {
- debug_printf("IPC: explicit EIO-ing, tk_aw_errno = %d\n",
- fdip->tick->tk_aw_errno);
+ SDT_PROBE2(fuse, , ipc, fdisp_wait_answ_error,
+ "IPC: explicit EIO-ing", fdip->tick->tk_aw_errno);
err = EIO;
goto out;
}
if ((err = fdip->tick->tk_aw_ohead.error)) {
- debug_printf("IPC: setting status to %d\n",
- fdip->tick->tk_aw_ohead.error);
+ SDT_PROBE2(fuse, , ipc, fdisp_wait_answ_error,
+ "IPC: setting status", fdip->tick->tk_aw_ohead.error);
/*
* This means a "proper" fuse syscall error.
* We record this value so the caller will
@@ -855,13 +801,9 @@ fdisp_wait_answ(struct fuse_dispatcher *fdip)
fdip->answ = fticket_resp(fdip->tick)->base;
fdip->iosize = fticket_resp(fdip->tick)->len;
- debug_printf("IPC: all is well\n");
-
return 0;
out:
- debug_printf("IPC: dropping ticket, err = %d\n", err);
-
return err;
}
Modified: projects/fuse2/sys/fs/fuse/fuse_main.c
==============================================================================
--- projects/fuse2/sys/fs/fuse/fuse_main.c Thu Feb 28 19:19:02 2019 (r344663)
+++ projects/fuse2/sys/fs/fuse/fuse_main.c Thu Feb 28 19:27:54 2019 (r344664)
@@ -67,11 +67,13 @@ __FBSDID("$FreeBSD$");
#include <sys/conf.h>
#include <sys/mutex.h>
#include <sys/proc.h>
+#include <sys/queue.h>
#include <sys/mount.h>
#include <sys/vnode.h>
#include <sys/stat.h>
#include <sys/file.h>
#include <sys/buf.h>
*** DIFF OUTPUT TRUNCATED AT 1000 LINES ***
More information about the svn-src-projects
mailing list