[PATCH 14/15] io_uring: add tracepoints for the handoff operation

[Jens Axboe]

Add tracepoints for a handoff, a handoff that didn't happen with the
reason, and the promoted task resuming the submission.

Signed-off-by: Jens Axboe <axboe@xxxxxxxxx>
---
 include/trace/events/io_uring.h | 114 ++++++++++++++++++++++++++++++++
 io_uring/handoff.c              |  42 +++++++++---
 2 files changed, 147 insertions(+), 9 deletions(-)

diff --git a/include/trace/events/io_uring.h b/include/trace/events/io_uring.h
index 34b31a855ea4..6043c5d46dbd 100644
--- a/include/trace/events/io_uring.h
+++ b/include/trace/events/io_uring.h
@@ -671,6 +671,120 @@ TRACE_EVENT(io_uring_local_work_run,
 	TP_printk("ring %p, count %d, loops %u", __entry->ctx, __entry->count, __entry->loops)
 );
 
+/**
+ * io_uring_handoff - a blocked submitter hands its identity to a worker
+ *
+ * @req:	pointer to a submitted request
+ * @dst:	the idle io-wq worker task taking over
+ */
+TRACE_EVENT(io_uring_handoff,
+
+	TP_PROTO(struct io_kiocb *req, struct task_struct *dst),
+
+	TP_ARGS(req, dst),
+
+	TP_STRUCT__entry (
+		__field(  void *,	ctx		)
+		__field(  void *,	req		)
+		__field(  u64,		user_data	)
+		__field(  u8,		opcode		)
+		__field(  pid_t,	src_pid		)
+		__field(  pid_t,	dst_pid		)
+
+		__string( op_str, io_uring_get_opcode(req->opcode)	)
+	),
+
+	TP_fast_assign(
+		__entry->ctx		= req->ctx;
+		__entry->req		= req;
+		__entry->user_data	= req->cqe.user_data;
+		__entry->opcode		= req->opcode;
+		__entry->src_pid	= task_pid_nr(current);
+		__entry->dst_pid	= task_pid_nr(dst);
+
+		__assign_str(op_str);
+	),
+
+	TP_printk("ring %p, request %p, user_data 0x%llx, opcode %s, identity %d handed to worker %d",
+		__entry->ctx, __entry->req, __entry->user_data,
+		__get_str(op_str), __entry->src_pid, __entry->dst_pid)
+);
+
+/**
+ * io_uring_handoff_fail - a handoff didn't happen for a request
+ *
+ * @req:	pointer to the request being issued
+ * @reason:	why. "lock", "prepare" and "worker" mean the task blocked in
+ *		place, anything else that it took the io-wq punt path instead.
+ */
+TRACE_EVENT(io_uring_handoff_fail,
+
+	TP_PROTO(struct io_kiocb *req, const char *reason),
+
+	TP_ARGS(req, reason),
+
+	TP_STRUCT__entry (
+		__field(  void *,	ctx		)
+		__field(  void *,	req		)
+		__field(  u64,		user_data	)
+		__field(  u8,		opcode		)
+
+		__string( op_str, io_uring_get_opcode(req->opcode)	)
+		__string( reason, reason			)
+	),
+
+	TP_fast_assign(
+		__entry->ctx		= req->ctx;
+		__entry->req		= req;
+		__entry->user_data	= req->cqe.user_data;
+		__entry->opcode		= req->opcode;
+
+		__assign_str(op_str);
+		__assign_str(reason);
+	),
+
+	TP_printk("ring %p, request %p, user_data 0x%llx, opcode %s, %s",
+		__entry->ctx, __entry->req, __entry->user_data,
+		__get_str(op_str), __get_str(reason))
+);
+
+/**
+ * io_uring_handoff_resume - a promoted worker continues the submission
+ *
+ * @ctx:	pointer to a ring context structure
+ * @req:	the request that blocked, owned by the demoted task by now
+ * @worker:	pid the demoted task now runs under
+ * @consumed:	SQEs consumed by earlier handoffs of this syscall
+ * @to_submit:	SQE count the syscall asked for
+ */
+TRACE_EVENT(io_uring_handoff_resume,
+
+	TP_PROTO(void *ctx, void *req, pid_t worker, unsigned int consumed,
+		 unsigned int to_submit),
+
+	TP_ARGS(ctx, req, worker, consumed, to_submit),
+
+	TP_STRUCT__entry (
+		__field(  void *,	ctx		)
+		__field(  void *,	req		)
+		__field(  pid_t,	worker		)
+		__field(  unsigned int,	consumed	)
+		__field(  unsigned int,	to_submit	)
+	),
+
+	TP_fast_assign(
+		__entry->ctx		= ctx;
+		__entry->req		= req;
+		__entry->worker		= worker;
+		__entry->consumed	= consumed;
+		__entry->to_submit	= to_submit;
+	),
+
+	TP_printk("ring %p, request %p now on worker %d, consumed %u, to_submit %u",
+		__entry->ctx, __entry->req, __entry->worker,
+		__entry->consumed, __entry->to_submit)
+);
+
 #endif /* _TRACE_IO_URING_H */
 
 /* This part must be outside protection */
diff --git a/io_uring/handoff.c b/io_uring/handoff.c
index 9c9bb7ba99f0..8aefea5d326e 100644
--- a/io_uring/handoff.c
+++ b/io_uring/handoff.c
@@ -20,6 +20,7 @@
 #include <linux/fs.h>
 #include <linux/file.h>
 #include <asm/syscall.h>
+#include <trace/events/io_uring.h>
 
 #include "io_uring.h"
 #include "io-wq.h"
@@ -52,28 +53,40 @@ bool io_handoff_possible(struct io_kiocb *req)
 		return false;
 	/* IOPOLL/SQPOLL issue differently, SQ_REWIND can't resume mid-batch */
 	if (ctx->flags & (IORING_SETUP_IOPOLL | IORING_SETUP_SQPOLL |
-			  IORING_SETUP_SQ_REWIND))
+			  IORING_SETUP_SQ_REWIND)) {
+		trace_io_uring_handoff_fail(req, "ring");
 		return false;
+	}
 	/* pollable files keep the nonblocking issue + poll retry path */
-	if (io_file_can_poll(req))
+	if (io_file_can_poll(req)) {
+		trace_io_uring_handoff_fail(req, "poll");
 		return false;
+	}
 	/* FMODE_NOWAIT files have a working nonblocking path, keep using it */
 	if ((def->pollin || def->pollout) && req->file &&
-	    (req->file->f_mode & FMODE_NOWAIT))
+	    (req->file->f_mode & FMODE_NOWAIT)) {
+		trace_io_uring_handoff_fail(req, "nowait-file");
 		return false;
+	}
 	if (!tctx->io_wq)
 		return false;
 	/* an intermediate task's own user state doesn't matter, it stays */
-	if (!tctx->handoff.src && !thread_handoff_allowed(current))
+	if (!tctx->handoff.src && !thread_handoff_allowed(current)) {
+		trace_io_uring_handoff_fail(req, "task");
 		return false;
+	}
 	/* the SQ head is published while we may still be running */
-	if (io_req_sqe_copy(req, IO_URING_F_INLINE))
+	if (io_req_sqe_copy(req, IO_URING_F_INLINE)) {
+		trace_io_uring_handoff_fail(req, "sqe");
 		return false;
+	}
 	req->flags |= REQ_F_HANDOFF;
 check_spare:
 	/* have a worker ready to take over */
-	if (!io_wq_handoff_spare(tctx->io_wq, !io_req_unbound(req), false))
+	if (!io_wq_handoff_spare(tctx->io_wq, !io_req_unbound(req), false)) {
+		trace_io_uring_handoff_fail(req, "spare");
 		return false;
+	}
 	return true;
 }
 
@@ -122,8 +135,10 @@ bool __io_handoff_begin(struct io_kiocb *req)
 	if (!io_handoff_possible(req))
 		return false;
 	/* would interrupt the issue right away, and can't be handled here */
-	if (task_sigpending(current))
+	if (task_sigpending(current)) {
+		trace_io_uring_handoff_fail(req, "signal");
 		return false;
+	}
 
 	ho->req = req;
 	io_handoff_block_signals(ho);
@@ -240,10 +255,14 @@ void io_uring_task_sleeping(struct task_struct *tsk)
 	WARN_ON_ONCE(tsk != current);
 
 	/* the issue path is touching state that needs the ring lock held */
-	if (ctx->submit_lock_depth)
+	if (ctx->submit_lock_depth) {
+		trace_io_uring_handoff_fail(req, "lock");
 		return;
-	if (src == tsk && !thread_handoff_prepare(tsk))
+	}
+	if (src == tsk && !thread_handoff_prepare(tsk)) {
+		trace_io_uring_handoff_fail(req, "prepare");
 		return;
+	}
 
 	/* don't let the woken worker preempt us before we've committed */
 	preempt_disable();
@@ -251,6 +270,7 @@ void io_uring_task_sleeping(struct task_struct *tsk)
 	dst = io_wq_handoff_claim(tctx->io_wq, bound, io_handoff_resume, src);
 	if (!dst) {
 		preempt_enable();
+		trace_io_uring_handoff_fail(req, "worker");
 		return;
 	}
 
@@ -262,6 +282,7 @@ void io_uring_task_sleeping(struct task_struct *tsk)
 	/* our accounting follows the identity, an intermediate's doesn't */
 	if (src == tsk)
 		thread_handoff_stats_take(&ho->stats);
+	trace_io_uring_handoff(req, dst);
 
 	io_handoff_release_ring(ctx, ho);
 	io_handoff_move_tctx(tctx, tsk, dst);
@@ -306,6 +327,9 @@ static long io_handoff_resume(void)
 	bool bound = ho->bound;
 	long ret;
 
+	trace_io_uring_handoff_resume(ctx, ho->req, task_pid_nr(prev),
+				      ho->consumed, ho->to_submit);
+
 	/* enough of the identity to issue requests on its behalf */
 	thread_handoff_adopt_creds(src);
 	put_task_struct_many(prev, ho->prev_refs);
-- 
2.55.0