[Virtio-fs] [PATCH 0/3] virtio-fs: Add some tracepoints

[Virtio-fs] [PATCH 0/3] virtio-fs: Add some tracepoints

[Masayoshi Mizuma]

From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>

This patch series introduce some tracepoints. It will be
useful to debug the I/O request flow.

New trace events:

  - virtio_fs_request_dispatched
  - virtio_fs_request_done
  - virtio_fs_hiprio_request_dispatched
  - virtio_fs_hiprio_request_done

Above trace events is added to the following functions as
the tracepoints:

  - virtio_fs_enqueue_req
  - virtio_fs_requests_done_work
  - virtio_fs_hiprio_dispatch_work
  - virtio_fs_hiprio_done_work

Example of the trace record:

  cat-1432        [006] .... 37.592694: virtio_fs_request_dispatched:
      opcode FUSE_READ unique 0x1a nodeid 0x2 in.len 80 flags
      ISREPLY|WAITING|SENT notify 1
  kworker/4:1-103 [004] .... 37.592809: virtio_fs_request_done:
      opcode FUSE_READ unique 0x1a nodeid 0x2 in.len 80 flags
      ISREPLY|WAITING

Changelog:
 From RFC:
 - Change the string and the file name from virtiofs to virtio_fs.
 - Separate the fuse macros to the other file to get useful for
   generic fuse trace.

Masayoshi Mizuma (3):
  fuse: add some macros for ftrace
  virtio-fs: add ftrace events
  virtio-fs: add tracepoints

 fs/fuse/virtio_fs.c                |  21 +++++
 include/trace/events/fuse_common.h |  67 +++++++++++++++
 include/trace/events/virtio_fs.h   | 131 +++++++++++++++++++++++++++++
 3 files changed, 219 insertions(+)
 create mode 100644 include/trace/events/fuse_common.h
 create mode 100644 include/trace/events/virtio_fs.h

-- 
2.18.1

[Virtio-fs] [PATCH 1/3] fuse: add some macros for ftrace

[Masayoshi Mizuma]

From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>

Add some macros for ftrace. These macros is useful for generic fuse.

Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
---
 include/trace/events/fuse_common.h | 67 ++++++++++++++++++++++++++++++
 1 file changed, 67 insertions(+)
 create mode 100644 include/trace/events/fuse_common.h

diff --git a/include/trace/events/fuse_common.h b/include/trace/events/fuse_common.h
new file mode 100644
index 000000000..0805ec4ab
--- /dev/null
+++ b/include/trace/events/fuse_common.h
@@ -0,0 +1,67 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#include <uapi/linux/fuse.h>
+
+#define fuse_opcode_name(opcode)	{ opcode, #opcode }
+#define show_opcode_name(val)				\
+	__print_symbolic(val,				\
+		fuse_opcode_name(FUSE_LOOKUP),		\
+		fuse_opcode_name(FUSE_FORGET),		\
+		fuse_opcode_name(FUSE_GETATTR),		\
+		fuse_opcode_name(FUSE_SETATTR),		\
+		fuse_opcode_name(FUSE_READLINK),	\
+		fuse_opcode_name(FUSE_SYMLINK),		\
+		fuse_opcode_name(FUSE_MKNOD),		\
+		fuse_opcode_name(FUSE_MKDIR),		\
+		fuse_opcode_name(FUSE_UNLINK),		\
+		fuse_opcode_name(FUSE_RMDIR),		\
+		fuse_opcode_name(FUSE_RENAME),		\
+		fuse_opcode_name(FUSE_LINK),		\
+		fuse_opcode_name(FUSE_OPEN),		\
+		fuse_opcode_name(FUSE_READ),		\
+		fuse_opcode_name(FUSE_WRITE),		\
+		fuse_opcode_name(FUSE_STATFS),		\
+		fuse_opcode_name(FUSE_RELEASE),		\
+		fuse_opcode_name(FUSE_FSYNC),		\
+		fuse_opcode_name(FUSE_SETXATTR),	\
+		fuse_opcode_name(FUSE_GETXATTR),	\
+		fuse_opcode_name(FUSE_LISTXATTR),	\
+		fuse_opcode_name(FUSE_REMOVEXATTR),	\
+		fuse_opcode_name(FUSE_FLUSH),		\
+		fuse_opcode_name(FUSE_INIT),		\
+		fuse_opcode_name(FUSE_OPENDIR),		\
+		fuse_opcode_name(FUSE_READDIR),		\
+		fuse_opcode_name(FUSE_RELEASEDIR),	\
+		fuse_opcode_name(FUSE_FSYNCDIR),	\
+		fuse_opcode_name(FUSE_GETLK),		\
+		fuse_opcode_name(FUSE_SETLK),		\
+		fuse_opcode_name(FUSE_SETLKW),		\
+		fuse_opcode_name(FUSE_ACCESS),		\
+		fuse_opcode_name(FUSE_CREATE),		\
+		fuse_opcode_name(FUSE_INTERRUPT),	\
+		fuse_opcode_name(FUSE_BMAP),		\
+		fuse_opcode_name(FUSE_DESTROY),		\
+		fuse_opcode_name(FUSE_IOCTL),		\
+		fuse_opcode_name(FUSE_POLL),		\
+		fuse_opcode_name(FUSE_NOTIFY_REPLY),	\
+		fuse_opcode_name(FUSE_BATCH_FORGET),	\
+		fuse_opcode_name(FUSE_FALLOCATE),	\
+		fuse_opcode_name(FUSE_READDIRPLUS),	\
+		fuse_opcode_name(FUSE_RENAME2),		\
+		fuse_opcode_name(FUSE_LSEEK),		\
+		fuse_opcode_name(FUSE_COPY_FILE_RANGE),	\
+		fuse_opcode_name(FUSE_SETUPMAPPING),	\
+		fuse_opcode_name(FUSE_REMOVEMAPPING))
+
+#define show_req_flag(flags) __print_flags(flags, "|",	\
+	{ (1UL << FR_ISREPLY),		"ISREPLY"},	\
+	{ (1UL << FR_FORCE),		"FORCE"},	\
+	{ (1UL << FR_BACKGROUND),	"BACKGROUND"},	\
+	{ (1UL << FR_WAITING),		"WAITING"},	\
+	{ (1UL << FR_ABORTED),		"ABORTED"},	\
+	{ (1UL << FR_INTERRUPTED),	"INTERRUPTED"},	\
+	{ (1UL << FR_LOCKED),		"LOCKED"},	\
+	{ (1UL << FR_PENDING),		"PENDING"},	\
+	{ (1UL << FR_SENT),		"SENT"},	\
+	{ (1UL << FR_FINISHED),		"FINISHED"},	\
+	{ (1UL << FR_PRIVATE),		"PRIVATE"})
-- 
2.18.1

[Virtio-fs] [PATCH 2/3] virtio-fs: add ftrace events

[Masayoshi Mizuma]

From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>

Introduce the following ftrace events.

  - virtio_fs_request_dispatched
  - virtio_fs_request_done
  - virtio_fs_hiprio_request_dispatched
  - virtio_fs_hiprio_request_done

Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
---
 include/trace/events/virtio_fs.h | 131 +++++++++++++++++++++++++++++++
 1 file changed, 131 insertions(+)
 create mode 100644 include/trace/events/virtio_fs.h

diff --git a/include/trace/events/virtio_fs.h b/include/trace/events/virtio_fs.h
new file mode 100644
index 000000000..84ccfa7eb
--- /dev/null
+++ b/include/trace/events/virtio_fs.h
@@ -0,0 +1,131 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM virtio_fs
+
+#if !defined(_TRACE_VIRTIO_FS_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_VIRTIO_FS_H
+
+#include <linux/tracepoint.h>
+#include <trace/events/fuse_common.h>
+
+TRACE_EVENT(virtio_fs_request_dispatched,
+
+	TP_PROTO(uint32_t opcode, uint64_t unique, uint64_t nodeid,
+		uint32_t inlen, unsigned long flags, bool notify),
+
+	TP_ARGS(opcode, unique, nodeid, inlen, flags, notify),
+
+	TP_STRUCT__entry(
+		__field(uint32_t,	opcode)
+		__field(uint64_t,	unique)
+		__field(uint64_t,	nodeid)
+		__field(uint32_t,	inlen)
+		__field(unsigned long,	flags)
+		__field(bool,		notify)
+	),
+
+	TP_fast_assign(
+		__entry->opcode	=	opcode;
+		__entry->unique	=	unique;
+		__entry->nodeid	=	nodeid;
+		__entry->inlen	=	inlen;
+		__entry->flags	=	flags;
+		__entry->notify	=	notify;
+	),
+
+	TP_printk("opcode %s unique %#llx nodeid %#llx in.len %u flags %s notify %d\n",
+			show_opcode_name(__entry->opcode),
+			__entry->unique, __entry->nodeid,
+			__entry->inlen, show_req_flag(__entry->flags),
+			__entry->notify)
+);
+
+TRACE_EVENT(virtio_fs_request_done,
+
+	TP_PROTO(uint32_t opcode, uint64_t unique, uint64_t nodeid,
+		uint32_t inlen, unsigned long flags),
+
+	TP_ARGS(opcode, unique, nodeid, inlen, flags),
+
+	TP_STRUCT__entry(
+		__field(uint32_t,	opcode)
+		__field(uint64_t,	unique)
+		__field(uint64_t,	nodeid)
+		__field(uint32_t,	inlen)
+		__field(unsigned long,	flags)
+	),
+
+	TP_fast_assign(
+		__entry->opcode	=	opcode;
+		__entry->unique	=	unique;
+		__entry->nodeid	=	nodeid;
+		__entry->inlen	=	inlen;
+		__entry->flags	=	flags;
+	),
+
+	TP_printk("opcode %s unique %#llx nodeid %#llx in.len %u flags %s\n",
+			show_opcode_name(__entry->opcode),
+			__entry->unique, __entry->nodeid,
+			__entry->inlen, show_req_flag(__entry->flags))
+);
+
+TRACE_EVENT(virtio_fs_hiprio_request_dispatched,
+
+	TP_PROTO(uint32_t opcode, uint64_t unique, uint64_t nodeid,
+		uint32_t inlen, bool notify),
+
+	TP_ARGS(opcode, unique, nodeid, inlen, notify),
+
+	TP_STRUCT__entry(
+		__field(uint32_t,	opcode)
+		__field(uint64_t,	unique)
+		__field(uint64_t,	nodeid)
+		__field(uint32_t,	inlen)
+		__field(bool,		notify)
+	),
+
+	TP_fast_assign(
+		__entry->opcode	=	opcode;
+		__entry->unique	=	unique;
+		__entry->nodeid	=	nodeid;
+		__entry->inlen	=	inlen;
+		__entry->notify	=	notify;
+	),
+
+	TP_printk("opcode %s unique %#llx nodeid %#llx in.len %u notify %d\n",
+			show_opcode_name(__entry->opcode),
+			__entry->unique, __entry->nodeid,
+			__entry->inlen,  __entry->notify)
+);
+
+TRACE_EVENT(virtio_fs_hiprio_request_done,
+
+	TP_PROTO(uint32_t opcode, uint64_t unique, uint64_t nodeid,
+		uint32_t inlen),
+
+	TP_ARGS(opcode, unique, nodeid, inlen),
+
+	TP_STRUCT__entry(
+		__field(uint32_t,	opcode)
+		__field(uint64_t,	unique)
+		__field(uint64_t,	nodeid)
+		__field(uint32_t,	inlen)
+	),
+
+	TP_fast_assign(
+		__entry->opcode	=	opcode;
+		__entry->unique	=	unique;
+		__entry->nodeid	=	nodeid;
+		__entry->inlen	=	inlen;
+	),
+
+	TP_printk("opcode %s unique %#llx nodeid %#llx in.len %u\n",
+			show_opcode_name(__entry->opcode),
+			__entry->unique, __entry->nodeid,
+			__entry->inlen)
+);
+
+#endif /* _TRACE_VIRTIO_FS_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.18.1

[Virtio-fs] [PATCH 3/3] virtio-fs: add tracepoints

[Masayoshi Mizuma]

From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>

Add tracepoint to the following function. It will be useful
to debug the I/O request flow.

  - virtio_fs_enqueue_req
  - virtio_fs_requests_done_work
  - virtio_fs_hiprio_dispatch_work
  - virtio_fs_hiprio_done_work

Example of the trace record:

  cat-1432        [006] .... 37.592694: virtio_fs_request_dispatched:
      opcode FUSE_READ unique 0x1a nodeid 0x2 in.len 80 flags
      ISREPLY|WAITING|SENT notify 1
  kworker/4:1-103 [004] .... 37.592809: virtio_fs_request_done:
      opcode FUSE_READ unique 0x1a nodeid 0x2 in.len 80 flags
      ISREPLY|WAITING

Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
---
 fs/fuse/virtio_fs.c | 21 +++++++++++++++++++++
 1 file changed, 21 insertions(+)

diff --git a/fs/fuse/virtio_fs.c b/fs/fuse/virtio_fs.c
index 558d090af..c348f745e 100644
--- a/fs/fuse/virtio_fs.c
+++ b/fs/fuse/virtio_fs.c
@@ -14,6 +14,9 @@
 #include <linux/delay.h>
 #include "fuse_i.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/virtio_fs.h>
+
 /* List of virtio-fs device instances and a lock for the list */
 static DEFINE_MUTEX(virtio_fs_mutex);
 static LIST_HEAD(virtio_fs_instances);
@@ -175,6 +178,7 @@ static void virtio_fs_hiprio_done_work(struct work_struct *work)
 	struct virtio_fs_vq *fsvq = container_of(work, struct virtio_fs_vq,
 						 done_work);
 	struct virtqueue *vq = fsvq->vq;
+	struct virtio_fs_forget *forget;
 
 	/* Free completed FUSE_FORGET requests */
 	spin_lock(&fsvq->lock);
@@ -185,6 +189,10 @@ static void virtio_fs_hiprio_done_work(struct work_struct *work)
 		virtqueue_disable_cb(vq);
 
 		while ((req = virtqueue_get_buf(vq, &len)) != NULL) {
+			forget = (struct virtio_fs_forget *)req;
+			trace_virtio_fs_hiprio_request_done(
+				forget->ih.opcode, forget->ih.unique,
+				forget->ih.nodeid, forget->ih.len);
 			kfree(req);
 			fsvq->in_flight--;
 		}
@@ -251,6 +259,11 @@ static void virtio_fs_hiprio_dispatch_work(struct work_struct *work)
 		notify = virtqueue_kick_prepare(vq);
 		spin_unlock(&fsvq->lock);
 
+		trace_virtio_fs_hiprio_request_dispatched(
+			forget->ih.opcode, forget->ih.unique,
+			forget->ih.nodeid, forget->ih.len,
+			notify);
+
 		if (notify)
 			virtqueue_notify(vq);
 		pr_debug("worker virtio_fs_hiprio_dispatch_work() dispatched one forget request.\n");
@@ -364,6 +377,10 @@ static void virtio_fs_requests_done_work(struct work_struct *work)
 		list_del_init(&req->list);
 		spin_unlock(&fpq->lock);
 
+		trace_virtio_fs_request_done(
+			req->in.h.opcode, req->in.h.unique,
+			req->in.h.nodeid, req->in.h.len, req->flags);
+
 		fuse_request_end(fc, req);
 	}
 }
@@ -914,6 +931,10 @@ static int virtio_fs_enqueue_req(struct virtqueue *vq, struct fuse_req *req)
 
 	spin_unlock(&fsvq->lock);
 
+	trace_virtio_fs_request_dispatched(
+		req->in.h.opcode, req->in.h.unique,
+		req->in.h.nodeid, req->in.h.len, req->flags, notify);
+
 	if (notify)
 		virtqueue_notify(vq);
 
-- 
2.18.1

Re: [Virtio-fs] [PATCH 3/3] virtio-fs: add tracepoints

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1302 bytes --]

On Mon, Aug 12, 2019 at 05:04:55PM -0400, Masayoshi Mizuma wrote:
> @@ -251,6 +259,11 @@ static void virtio_fs_hiprio_dispatch_work(struct work_struct *work)
>  		notify = virtqueue_kick_prepare(vq);
>  		spin_unlock(&fsvq->lock);
>  
> +		trace_virtio_fs_hiprio_request_dispatched(
> +			forget->ih.opcode, forget->ih.unique,
> +			forget->ih.nodeid, forget->ih.len,
> +			notify);
> +

It is safer to trace the request before placing it in the queue and
before releasing fsvq->lock.  I'm concerned that a fast device may
complete the request and invoke virtio_fs_hiprio_done_work() so that
kfree(req) is called before we've finished tracing it.

(We cannot rely on virtqueue_notify() because devices may poll the
virtqueue, so as soon as the request has been added to the virtqueue it
may be completed.)

> @@ -914,6 +931,10 @@ static int virtio_fs_enqueue_req(struct virtqueue *vq, struct fuse_req *req)
>  
>  	spin_unlock(&fsvq->lock);
>  
> +	trace_virtio_fs_request_dispatched(
> +		req->in.h.opcode, req->in.h.unique,
> +		req->in.h.nodeid, req->in.h.len, req->flags, notify);
> +
>  	if (notify)
>  		virtqueue_notify(vq);

Same here, we no longer control the lifetime of req so it's not safe to
access it after virtqueue_add_sgs() + spin_unlock(&fsvq->lock).

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [Virtio-fs] [PATCH 0/3] virtio-fs: Add some tracepoints

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1793 bytes --]

On Mon, Aug 12, 2019 at 05:04:52PM -0400, Masayoshi Mizuma wrote:
> From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
> 
> This patch series introduce some tracepoints. It will be
> useful to debug the I/O request flow.
> 
> New trace events:
> 
>   - virtio_fs_request_dispatched
>   - virtio_fs_request_done
>   - virtio_fs_hiprio_request_dispatched
>   - virtio_fs_hiprio_request_done
> 
> Above trace events is added to the following functions as
> the tracepoints:
> 
>   - virtio_fs_enqueue_req
>   - virtio_fs_requests_done_work
>   - virtio_fs_hiprio_dispatch_work
>   - virtio_fs_hiprio_done_work
> 
> Example of the trace record:
> 
>   cat-1432        [006] .... 37.592694: virtio_fs_request_dispatched:
>       opcode FUSE_READ unique 0x1a nodeid 0x2 in.len 80 flags
>       ISREPLY|WAITING|SENT notify 1
>   kworker/4:1-103 [004] .... 37.592809: virtio_fs_request_done:
>       opcode FUSE_READ unique 0x1a nodeid 0x2 in.len 80 flags
>       ISREPLY|WAITING
> 
> Changelog:
>  From RFC:
>  - Change the string and the file name from virtiofs to virtio_fs.
>  - Separate the fuse macros to the other file to get useful for
>    generic fuse trace.
> 
> Masayoshi Mizuma (3):
>   fuse: add some macros for ftrace
>   virtio-fs: add ftrace events
>   virtio-fs: add tracepoints
> 
>  fs/fuse/virtio_fs.c                |  21 +++++
>  include/trace/events/fuse_common.h |  67 +++++++++++++++
>  include/trace/events/virtio_fs.h   | 131 +++++++++++++++++++++++++++++
>  3 files changed, 219 insertions(+)
>  create mode 100644 include/trace/events/fuse_common.h
>  create mode 100644 include/trace/events/virtio_fs.h
> 
> -- 
> 2.18.1
> 

Looks useful, thanks.  I'm concerned about use-after-frees, please see
my other email reply.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [Virtio-fs] [PATCH 3/3] virtio-fs: add tracepoints

[Masayoshi Mizuma]

On Tue, Aug 20, 2019 at 11:06:43AM +0100, Stefan Hajnoczi wrote:
> On Mon, Aug 12, 2019 at 05:04:55PM -0400, Masayoshi Mizuma wrote:
> > @@ -251,6 +259,11 @@ static void virtio_fs_hiprio_dispatch_work(struct work_struct *work)
> >  		notify = virtqueue_kick_prepare(vq);
> >  		spin_unlock(&fsvq->lock);
> >  
> > +		trace_virtio_fs_hiprio_request_dispatched(
> > +			forget->ih.opcode, forget->ih.unique,
> > +			forget->ih.nodeid, forget->ih.len,
> > +			notify);
> > +
> 
> It is safer to trace the request before placing it in the queue and
> before releasing fsvq->lock.  I'm concerned that a fast device may
> complete the request and invoke virtio_fs_hiprio_done_work() so that
> kfree(req) is called before we've finished tracing it.
> 
> (We cannot rely on virtqueue_notify() because devices may poll the
> virtqueue, so as soon as the request has been added to the virtqueue it
> may be completed.)
> 
> > @@ -914,6 +931,10 @@ static int virtio_fs_enqueue_req(struct virtqueue *vq, struct fuse_req *req)
> >  
> >  	spin_unlock(&fsvq->lock);
> >  
> > +	trace_virtio_fs_request_dispatched(
> > +		req->in.h.opcode, req->in.h.unique,
> > +		req->in.h.nodeid, req->in.h.len, req->flags, notify);
> > +
> >  	if (notify)
> >  		virtqueue_notify(vq);
> 
> Same here, we no longer control the lifetime of req so it's not safe to
> access it after virtqueue_add_sgs() + spin_unlock(&fsvq->lock).

Thank you for your review. I'll move the trace before
spin_unlock(&fsvq->lock).

Thanks!
Masa