From owner-svn-src-projects@freebsd.org Thu Feb 28 19:27:57 2019 Return-Path: Delivered-To: svn-src-projects@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id A2E3615152E5 for ; Thu, 28 Feb 2019 19:27:56 +0000 (UTC) (envelope-from asomers@FreeBSD.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) server-signature RSA-PSS (4096 bits) client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 20E6B83FEE; Thu, 28 Feb 2019 19:27:56 +0000 (UTC) (envelope-from asomers@FreeBSD.org) Received: from repo.freebsd.org (repo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id 114B197DC; Thu, 28 Feb 2019 19:27:56 +0000 (UTC) (envelope-from asomers@FreeBSD.org) Received: from repo.freebsd.org ([127.0.1.37]) by repo.freebsd.org (8.15.2/8.15.2) with ESMTP id x1SJRuhc040608; Thu, 28 Feb 2019 19:27:56 GMT (envelope-from asomers@FreeBSD.org) Received: (from asomers@localhost) by repo.freebsd.org (8.15.2/8.15.2/Submit) id x1SJRsrg040599; Thu, 28 Feb 2019 19:27:54 GMT (envelope-from asomers@FreeBSD.org) Message-Id: <201902281927.x1SJRsrg040599@repo.freebsd.org> X-Authentication-Warning: repo.freebsd.org: asomers set sender to asomers@FreeBSD.org using -f From: Alan Somers Date: Thu, 28 Feb 2019 19:27:54 +0000 (UTC) To: src-committers@freebsd.org, svn-src-projects@freebsd.org Subject: svn commit: r344664 - projects/fuse2/sys/fs/fuse X-SVN-Group: projects X-SVN-Commit-Author: asomers X-SVN-Commit-Paths: projects/fuse2/sys/fs/fuse X-SVN-Commit-Revision: 344664 X-SVN-Commit-Repository: base MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-Rspamd-Queue-Id: 20E6B83FEE X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org X-Spamd-Result: default: False [-2.97 / 15.00]; local_wl_from(0.00)[FreeBSD.org]; NEURAL_HAM_MEDIUM(-1.00)[-0.999,0]; NEURAL_HAM_SHORT(-0.97)[-0.974,0]; NEURAL_HAM_LONG(-1.00)[-1.000,0] X-BeenThere: svn-src-projects@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: "SVN commit messages for the src " projects" tree" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 28 Feb 2019 19:27:57 -0000 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 #include #include +#include #include #include #include @@ -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 __FBSDID("$FreeBSD$"); -#include +#include #include #include #include -#include #include #include #include @@ -74,6 +73,7 @@ __FBSDID("$FreeBSD$"); #include #include #include +#include #include #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 __FBSDID("$FreeBSD$"); -#include +#include #include #include #include -#include #include #include #include @@ -70,6 +69,7 @@ __FBSDID("$FreeBSD$"); #include #include #include +#include #include #include #include @@ -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 __FBSDID("$FreeBSD$"); -#include +#include #include #include #include -#include #include #include #include #include +#include #include #include #include #include #include #include +#include #include +#include #include #include #include @@ -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 #include #include +#include #include #include #include #include #include *** DIFF OUTPUT TRUNCATED AT 1000 LINES ***