[PATCH][RESEND] fuse: add simple request tracepoints

[PATCH][RESEND] fuse: add simple request tracepoints

[Josef Bacik]

I've been timing various fuse operations and it's quite annoying to do
with kprobes.  Add two tracepoints for sending and ending fuse requests
to make it easier to debug and time various operations.

Signed-off-by: Josef Bacik <josef@toxicpanda.com>
---
 fs/fuse/Makefile     |   3 +
 fs/fuse/dev.c        |   6 ++
 fs/fuse/fuse_trace.h | 132 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 141 insertions(+)
 create mode 100644 fs/fuse/fuse_trace.h

diff --git a/fs/fuse/Makefile b/fs/fuse/Makefile
index 6e0228c6d0cb..ce0ff7a9007b 100644
--- a/fs/fuse/Makefile
+++ b/fs/fuse/Makefile
@@ -3,6 +3,9 @@
 # Makefile for the FUSE filesystem.
 #
 
+# Needed for trace events
+ccflags-y = -I$(src)
+
 obj-$(CONFIG_FUSE_FS) += fuse.o
 obj-$(CONFIG_CUSE) += cuse.o
 obj-$(CONFIG_VIRTIO_FS) += virtiofs.o
diff --git a/fs/fuse/dev.c b/fs/fuse/dev.c
index 9eb191b5c4de..d303bfd31450 100644
--- a/fs/fuse/dev.c
+++ b/fs/fuse/dev.c
@@ -22,6 +22,9 @@
 #include <linux/splice.h>
 #include <linux/sched.h>
 
+#define CREATE_TRACE_POINTS
+#include "fuse_trace.h"
+
 MODULE_ALIAS_MISCDEV(FUSE_MINOR);
 MODULE_ALIAS("devname:fuse");
 
@@ -230,6 +233,7 @@ __releases(fiq->lock)
 		fuse_len_args(req->args->in_numargs,
 			      (struct fuse_arg *) req->args->in_args);
 	list_add_tail(&req->list, &fiq->pending);
+	trace_fuse_request_send(req);
 	fiq->ops->wake_pending_and_unlock(fiq);
 }
 
@@ -286,6 +290,8 @@ void fuse_request_end(struct fuse_req *req)
 	if (test_and_set_bit(FR_FINISHED, &req->flags))
 		goto put_request;
 
+	trace_fuse_request_end(req);
+
 	/*
 	 * test_and_set_bit() implies smp_mb() between bit
 	 * changing and below FR_INTERRUPTED check. Pairs with
diff --git a/fs/fuse/fuse_trace.h b/fs/fuse/fuse_trace.h
new file mode 100644
index 000000000000..bbe9ddd8c716
--- /dev/null
+++ b/fs/fuse/fuse_trace.h
@@ -0,0 +1,132 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM fuse
+
+#if !defined(_TRACE_FUSE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_FUSE_H
+
+#include <linux/tracepoint.h>
+
+#define OPCODES							\
+	EM( FUSE_LOOKUP,		"FUSE_LOOKUP")		\
+	EM( FUSE_FORGET,		"FUSE_FORGET")		\
+	EM( FUSE_GETATTR,		"FUSE_GETATTR")		\
+	EM( FUSE_SETATTR,		"FUSE_SETATTR")		\
+	EM( FUSE_READLINK,		"FUSE_READLINK")	\
+	EM( FUSE_SYMLINK,		"FUSE_SYMLINK")		\
+	EM( FUSE_MKNOD,			"FUSE_MKNOD")		\
+	EM( FUSE_MKDIR,			"FUSE_MKDIR")		\
+	EM( FUSE_UNLINK,		"FUSE_UNLINK")		\
+	EM( FUSE_RMDIR,			"FUSE_RMDIR")		\
+	EM( FUSE_RENAME,		"FUSE_RENAME")		\
+	EM( FUSE_LINK,			"FUSE_LINK")		\
+	EM( FUSE_OPEN,			"FUSE_OPEN")		\
+	EM( FUSE_READ,			"FUSE_READ")		\
+	EM( FUSE_WRITE,			"FUSE_WRITE")		\
+	EM( FUSE_STATFS,		"FUSE_STATFS")		\
+	EM( FUSE_RELEASE,		"FUSE_RELEASE")		\
+	EM( FUSE_FSYNC,			"FUSE_FSYNC")		\
+	EM( FUSE_SETXATTR,		"FUSE_SETXATTR")	\
+	EM( FUSE_GETXATTR,		"FUSE_GETXATTR")	\
+	EM( FUSE_LISTXATTR,		"FUSE_LISTXATTR")	\
+	EM( FUSE_REMOVEXATTR,		"FUSE_REMOVEXATTR")	\
+	EM( FUSE_FLUSH,			"FUSE_FLUSH")		\
+	EM( FUSE_INIT,			"FUSE_INIT")		\
+	EM( FUSE_OPENDIR,		"FUSE_OPENDIR")		\
+	EM( FUSE_READDIR,		"FUSE_READDIR")		\
+	EM( FUSE_RELEASEDIR,		"FUSE_RELEASEDIR")	\
+	EM( FUSE_FSYNCDIR,		"FUSE_FSYNCDIR")	\
+	EM( FUSE_GETLK,			"FUSE_GETLK")		\
+	EM( FUSE_SETLK,			"FUSE_SETLK")		\
+	EM( FUSE_SETLKW,		"FUSE_SETLKW")		\
+	EM( FUSE_ACCESS,		"FUSE_ACCESS")		\
+	EM( FUSE_CREATE,		"FUSE_CREATE")		\
+	EM( FUSE_INTERRUPT,		"FUSE_INTERRUPT")	\
+	EM( FUSE_BMAP,			"FUSE_BMAP")		\
+	EM( FUSE_DESTROY,		"FUSE_DESTROY")		\
+	EM( FUSE_IOCTL,			"FUSE_IOCTL")		\
+	EM( FUSE_POLL,			"FUSE_POLL")		\
+	EM( FUSE_NOTIFY_REPLY,		"FUSE_NOTIFY_REPLY")	\
+	EM( FUSE_BATCH_FORGET,		"FUSE_BATCH_FORGET")	\
+	EM( FUSE_FALLOCATE,		"FUSE_FALLOCATE")	\
+	EM( FUSE_READDIRPLUS,		"FUSE_READDIRPLUS")	\
+	EM( FUSE_RENAME2,		"FUSE_RENAME2")		\
+	EM( FUSE_LSEEK,			"FUSE_LSEEK")		\
+	EM( FUSE_COPY_FILE_RANGE,	"FUSE_COPY_FILE_RANGE")	\
+	EM( FUSE_SETUPMAPPING,		"FUSE_SETUPMAPPING")	\
+	EM( FUSE_REMOVEMAPPING,		"FUSE_REMOVEMAPPING")	\
+	EM( FUSE_SYNCFS,		"FUSE_SYNCFS")		\
+	EM( FUSE_TMPFILE,		"FUSE_TMPFILE")		\
+	EM( FUSE_STATX,			"FUSE_STATX")		\
+	EMe(CUSE_INIT,			"CUSE_INIT")
+
+/*
+ * This will turn the above table into TRACE_DEFINE_ENUM() for each of the
+ * entries.
+ */
+#undef EM
+#undef EMe
+#define EM(a, b)	TRACE_DEFINE_ENUM(a);
+#define EMe(a, b)	TRACE_DEFINE_ENUM(a);
+
+OPCODES
+
+/* Now we redfine it with the table that __print_symbolic needs. */
+#undef EM
+#undef EMe
+#define EM(a, b)	{a, b},
+#define EMe(a, b)	{a, b}
+
+TRACE_EVENT(fuse_request_send,
+	TP_PROTO(const struct fuse_req *req),
+
+	TP_ARGS(req),
+
+	TP_STRUCT__entry(
+		__field(dev_t,			connection)
+		__field(uint64_t,		unique)
+		__field(enum fuse_opcode,	opcode)
+		__field(uint32_t,		len)
+	),
+
+	TP_fast_assign(
+		__entry->connection	=	req->fm->fc->dev;
+		__entry->unique		=	req->in.h.unique;
+		__entry->opcode		=	req->in.h.opcode;
+		__entry->len		=	req->in.h.len;
+	),
+
+	TP_printk("connection %u req %llu opcode %u (%s) len %u ",
+		  __entry->connection, __entry->unique, __entry->opcode,
+		  __print_symbolic(__entry->opcode, OPCODES), __entry->len)
+);
+
+TRACE_EVENT(fuse_request_end,
+	TP_PROTO(const struct fuse_req *req),
+
+	TP_ARGS(req),
+
+	TP_STRUCT__entry(
+		__field(dev_t,		connection)
+		__field(uint64_t,	unique)
+		__field(uint32_t,	len)
+		__field(int32_t,	error)
+	),
+
+	TP_fast_assign(
+		__entry->connection	=	req->fm->fc->dev;
+		__entry->unique		=	req->in.h.unique;
+		__entry->len		=	req->out.h.len;
+		__entry->error		=	req->out.h.error;
+	),
+
+	TP_printk("connection %u req %llu len %u error %d", __entry->connection,
+		  __entry->unique, __entry->len, __entry->error)
+);
+
+#endif /* _TRACE_FUSE_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE fuse_trace
+#include <trace/define_trace.h>
-- 
2.43.0

Re: [PATCH][RESEND] fuse: add simple request tracepoints

[Bernd Schubert]

On 7/3/24 16:38, Josef Bacik wrote:
> I've been timing various fuse operations and it's quite annoying to do
> with kprobes.  Add two tracepoints for sending and ending fuse requests
> to make it easier to debug and time various operations.

Thanks, this is super helpful.

[...]
> 
> +	EM( FUSE_STATX,			"FUSE_STATX")		\
> +	EMe(CUSE_INIT,			"CUSE_INIT")
> +
> +/*
> + * This will turn the above table into TRACE_DEFINE_ENUM() for each of the
> + * entries.
> + */
> +#undef EM
> +#undef EMe
> +#define EM(a, b)	TRACE_DEFINE_ENUM(a);
> +#define EMe(a, b)	TRACE_DEFINE_ENUM(a);


I'm not super familiar with tracepoints and I'm a bit list why "EMe" is 
needed
in addition to EM? CUSE_INIT is just another number?


Thanks,
Bernd

Re: [PATCH][RESEND] fuse: add simple request tracepoints

[Josef Bacik]

On Thu, Jul 04, 2024 at 07:20:16PM +0200, Bernd Schubert wrote:
> 
> 
> On 7/3/24 16:38, Josef Bacik wrote:
> > I've been timing various fuse operations and it's quite annoying to do
> > with kprobes.  Add two tracepoints for sending and ending fuse requests
> > to make it easier to debug and time various operations.
> 
> Thanks, this is super helpful.
> 
> [...]
> > 
> > +	EM( FUSE_STATX,			"FUSE_STATX")		\
> > +	EMe(CUSE_INIT,			"CUSE_INIT")
> > +
> > +/*
> > + * This will turn the above table into TRACE_DEFINE_ENUM() for each of the
> > + * entries.
> > + */
> > +#undef EM
> > +#undef EMe
> > +#define EM(a, b)	TRACE_DEFINE_ENUM(a);
> > +#define EMe(a, b)	TRACE_DEFINE_ENUM(a);
> 
> 
> I'm not super familiar with tracepoints and I'm a bit list why "EMe" is
> needed
> in addition to EM? CUSE_INIT is just another number?

This is just obnoxious preprocessor abuse, so you're right this first iteration
of EMe() is the same as EM(), but if you look right below that you have

/* Now we redfine it with the table that __print_symbolic needs. */
#undef EM
#undef EMe
#define EM(a, b)        {a, b},
#define EMe(a, b)       {a, b}

so later when we do

__print_symbolic(__entry->opcode, OPCODES)

OPCODES gets turned intoo

__print_symbolic(__entry->opcode,
		{FUSE_LOOKUP, "FUSE_LOOKUP"},{...},{CUSE_INIT, "CUSE_INIT"})

it's subtle and annoying, but the cleanest way to have these big opcode tables
that are easy to add/remove stuff from for clean output.  Thanks,

Josef

Re: [PATCH][RESEND] fuse: add simple request tracepoints

[Bernd Schubert]

On 7/5/24 16:52, Josef Bacik wrote:
> On Thu, Jul 04, 2024 at 07:20:16PM +0200, Bernd Schubert wrote:
>>
>>
>> On 7/3/24 16:38, Josef Bacik wrote:
>>> I've been timing various fuse operations and it's quite annoying to do
>>> with kprobes.  Add two tracepoints for sending and ending fuse requests
>>> to make it easier to debug and time various operations.
>>
>> Thanks, this is super helpful.
>>
>> [...]
>>>
>>> +	EM( FUSE_STATX,			"FUSE_STATX")		\
>>> +	EMe(CUSE_INIT,			"CUSE_INIT")
>>> +
>>> +/*
>>> + * This will turn the above table into TRACE_DEFINE_ENUM() for each of the
>>> + * entries.
>>> + */
>>> +#undef EM
>>> +#undef EMe
>>> +#define EM(a, b)	TRACE_DEFINE_ENUM(a);
>>> +#define EMe(a, b)	TRACE_DEFINE_ENUM(a);
>>
>>
>> I'm not super familiar with tracepoints and I'm a bit list why "EMe" is
>> needed
>> in addition to EM? CUSE_INIT is just another number?
> 
> This is just obnoxious preprocessor abuse, so you're right this first iteration
> of EMe() is the same as EM(), but if you look right below that you have
> 
> /* Now we redfine it with the table that __print_symbolic needs. */
> #undef EM
> #undef EMe
> #define EM(a, b)        {a, b},
> #define EMe(a, b)       {a, b}
> 
> so later when we do
> 
> __print_symbolic(__entry->opcode, OPCODES)
> 
> OPCODES gets turned intoo
> 
> __print_symbolic(__entry->opcode,
> 		{FUSE_LOOKUP, "FUSE_LOOKUP"},{...},{CUSE_INIT, "CUSE_INIT"})
> 
> it's subtle and annoying, but the cleanest way to have these big opcode tables
> that are easy to add/remove stuff from for clean output.  Thanks,

Ah, I had missed the comma difference, sorry for the noise!
Looks good and very useful to me (I'm also using it now).


Reviewed-by: Bernd Schubert <bschubert@ddn.com>

Re: [PATCH][RESEND] fuse: add simple request tracepoints

[Miklos Szeredi]

On Wed, 3 Jul 2024 at 16:39, Josef Bacik <josef@toxicpanda.com> wrote:
>
> I've been timing various fuse operations and it's quite annoying to do
> with kprobes.  Add two tracepoints for sending and ending fuse requests
> to make it easier to debug and time various operations.
>
> Signed-off-by: Josef Bacik <josef@toxicpanda.com>

Applied, thanks.

Miklos