1 /* SPDX-License-Identifier: GPL-2.0 */
3 #define TRACE_SYSTEM sunrpc
5 #if !defined(_TRACE_SUNRPC_H) || defined(TRACE_HEADER_MULTI_READ)
6 #define _TRACE_SUNRPC_H
8 #include <linux/sunrpc/sched.h>
9 #include <linux/sunrpc/clnt.h>
10 #include <linux/sunrpc/svc.h>
11 #include <linux/sunrpc/xprtsock.h>
12 #include <linux/sunrpc/svc_xprt.h>
13 #include <net/tcp_states.h>
14 #include <linux/net.h>
15 #include <linux/tracepoint.h>
17 DECLARE_EVENT_CLASS(rpc_task_status,
19 TP_PROTO(const struct rpc_task *task),
24 __field(unsigned int, task_id)
25 __field(unsigned int, client_id)
30 __entry->task_id = task->tk_pid;
31 __entry->client_id = task->tk_client->cl_clid;
32 __entry->status = task->tk_status;
35 TP_printk("task:%u@%u status=%d",
36 __entry->task_id, __entry->client_id,
39 #define DEFINE_RPC_STATUS_EVENT(name) \
40 DEFINE_EVENT(rpc_task_status, rpc_##name##_status, \
42 const struct rpc_task *task \
46 DEFINE_RPC_STATUS_EVENT(call);
47 DEFINE_RPC_STATUS_EVENT(bind);
48 DEFINE_RPC_STATUS_EVENT(connect);
50 TRACE_EVENT(rpc_request,
51 TP_PROTO(const struct rpc_task *task),
56 __field(unsigned int, task_id)
57 __field(unsigned int, client_id)
60 __string(progname, task->tk_client->cl_program->name)
61 __string(procname, rpc_proc_name(task))
65 __entry->task_id = task->tk_pid;
66 __entry->client_id = task->tk_client->cl_clid;
67 __entry->version = task->tk_client->cl_vers;
68 __entry->async = RPC_IS_ASYNC(task);
69 __assign_str(progname, task->tk_client->cl_program->name)
70 __assign_str(procname, rpc_proc_name(task))
73 TP_printk("task:%u@%u %sv%d %s (%ssync)",
74 __entry->task_id, __entry->client_id,
75 __get_str(progname), __entry->version,
76 __get_str(procname), __entry->async ? "a": ""
80 DECLARE_EVENT_CLASS(rpc_task_running,
82 TP_PROTO(const struct rpc_task *task, const void *action),
84 TP_ARGS(task, action),
87 __field(unsigned int, task_id)
88 __field(unsigned int, client_id)
89 __field(const void *, action)
90 __field(unsigned long, runstate)
92 __field(unsigned short, flags)
96 __entry->client_id = task->tk_client ?
97 task->tk_client->cl_clid : -1;
98 __entry->task_id = task->tk_pid;
99 __entry->action = action;
100 __entry->runstate = task->tk_runstate;
101 __entry->status = task->tk_status;
102 __entry->flags = task->tk_flags;
105 TP_printk("task:%u@%d flags=%4.4x state=%4.4lx status=%d action=%pf",
106 __entry->task_id, __entry->client_id,
113 #define DEFINE_RPC_RUNNING_EVENT(name) \
114 DEFINE_EVENT(rpc_task_running, rpc_task_##name, \
116 const struct rpc_task *task, \
119 TP_ARGS(task, action))
121 DEFINE_RPC_RUNNING_EVENT(begin);
122 DEFINE_RPC_RUNNING_EVENT(run_action);
123 DEFINE_RPC_RUNNING_EVENT(complete);
125 DECLARE_EVENT_CLASS(rpc_task_queued,
127 TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q),
132 __field(unsigned int, task_id)
133 __field(unsigned int, client_id)
134 __field(unsigned long, timeout)
135 __field(unsigned long, runstate)
137 __field(unsigned short, flags)
138 __string(q_name, rpc_qname(q))
142 __entry->client_id = task->tk_client ?
143 task->tk_client->cl_clid : -1;
144 __entry->task_id = task->tk_pid;
145 __entry->timeout = task->tk_timeout;
146 __entry->runstate = task->tk_runstate;
147 __entry->status = task->tk_status;
148 __entry->flags = task->tk_flags;
149 __assign_str(q_name, rpc_qname(q));
152 TP_printk("task:%u@%d flags=%4.4x state=%4.4lx status=%d timeout=%lu queue=%s",
153 __entry->task_id, __entry->client_id,
161 #define DEFINE_RPC_QUEUED_EVENT(name) \
162 DEFINE_EVENT(rpc_task_queued, rpc_task_##name, \
164 const struct rpc_task *task, \
165 const struct rpc_wait_queue *q \
169 DEFINE_RPC_QUEUED_EVENT(sleep);
170 DEFINE_RPC_QUEUED_EVENT(wakeup);
172 TRACE_EVENT(rpc_stats_latency,
175 const struct rpc_task *task,
181 TP_ARGS(task, backlog, rtt, execute),
184 __field(unsigned int, task_id)
185 __field(unsigned int, client_id)
187 __field(int, version)
188 __string(progname, task->tk_client->cl_program->name)
189 __string(procname, rpc_proc_name(task))
190 __field(unsigned long, backlog)
191 __field(unsigned long, rtt)
192 __field(unsigned long, execute)
196 __entry->client_id = task->tk_client->cl_clid;
197 __entry->task_id = task->tk_pid;
198 __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
199 __entry->version = task->tk_client->cl_vers;
200 __assign_str(progname, task->tk_client->cl_program->name)
201 __assign_str(procname, rpc_proc_name(task))
202 __entry->backlog = ktime_to_us(backlog);
203 __entry->rtt = ktime_to_us(rtt);
204 __entry->execute = ktime_to_us(execute);
207 TP_printk("task:%u@%d xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu",
208 __entry->task_id, __entry->client_id, __entry->xid,
209 __get_str(progname), __entry->version, __get_str(procname),
210 __entry->backlog, __entry->rtt, __entry->execute)
214 * First define the enums in the below macros to be exported to userspace
215 * via TRACE_DEFINE_ENUM().
219 #define EM(a, b) TRACE_DEFINE_ENUM(a);
220 #define EMe(a, b) TRACE_DEFINE_ENUM(a);
222 #define RPC_SHOW_SOCKET \
223 EM( SS_FREE, "FREE" ) \
224 EM( SS_UNCONNECTED, "UNCONNECTED" ) \
225 EM( SS_CONNECTING, "CONNECTING," ) \
226 EM( SS_CONNECTED, "CONNECTED," ) \
227 EMe(SS_DISCONNECTING, "DISCONNECTING" )
229 #define rpc_show_socket_state(state) \
230 __print_symbolic(state, RPC_SHOW_SOCKET)
234 #define RPC_SHOW_SOCK \
235 EM( TCP_ESTABLISHED, "ESTABLISHED" ) \
236 EM( TCP_SYN_SENT, "SYN_SENT" ) \
237 EM( TCP_SYN_RECV, "SYN_RECV" ) \
238 EM( TCP_FIN_WAIT1, "FIN_WAIT1" ) \
239 EM( TCP_FIN_WAIT2, "FIN_WAIT2" ) \
240 EM( TCP_TIME_WAIT, "TIME_WAIT" ) \
241 EM( TCP_CLOSE, "CLOSE" ) \
242 EM( TCP_CLOSE_WAIT, "CLOSE_WAIT" ) \
243 EM( TCP_LAST_ACK, "LAST_ACK" ) \
244 EM( TCP_LISTEN, "LISTEN" ) \
245 EMe( TCP_CLOSING, "CLOSING" )
247 #define rpc_show_sock_state(state) \
248 __print_symbolic(state, RPC_SHOW_SOCK)
253 * Now redefine the EM() and EMe() macros to map the enums to the strings
254 * that will be printed in the output.
258 #define EM(a, b) {a, b},
259 #define EMe(a, b) {a, b}
261 DECLARE_EVENT_CLASS(xs_socket_event,
264 struct rpc_xprt *xprt,
265 struct socket *socket
268 TP_ARGS(xprt, socket),
271 __field(unsigned int, socket_state)
272 __field(unsigned int, sock_state)
273 __field(unsigned long long, ino)
275 xprt->address_strings[RPC_DISPLAY_ADDR])
277 xprt->address_strings[RPC_DISPLAY_PORT])
281 struct inode *inode = SOCK_INODE(socket);
282 __entry->socket_state = socket->state;
283 __entry->sock_state = socket->sk->sk_state;
284 __entry->ino = (unsigned long long)inode->i_ino;
285 __assign_str(dstaddr,
286 xprt->address_strings[RPC_DISPLAY_ADDR]);
287 __assign_str(dstport,
288 xprt->address_strings[RPC_DISPLAY_PORT]);
292 "socket:[%llu] dstaddr=%s/%s "
293 "state=%u (%s) sk_state=%u (%s)",
294 __entry->ino, __get_str(dstaddr), __get_str(dstport),
295 __entry->socket_state,
296 rpc_show_socket_state(__entry->socket_state),
298 rpc_show_sock_state(__entry->sock_state)
301 #define DEFINE_RPC_SOCKET_EVENT(name) \
302 DEFINE_EVENT(xs_socket_event, name, \
304 struct rpc_xprt *xprt, \
305 struct socket *socket \
307 TP_ARGS(xprt, socket))
309 DECLARE_EVENT_CLASS(xs_socket_event_done,
312 struct rpc_xprt *xprt,
313 struct socket *socket,
317 TP_ARGS(xprt, socket, error),
321 __field(unsigned int, socket_state)
322 __field(unsigned int, sock_state)
323 __field(unsigned long long, ino)
325 xprt->address_strings[RPC_DISPLAY_ADDR])
327 xprt->address_strings[RPC_DISPLAY_PORT])
331 struct inode *inode = SOCK_INODE(socket);
332 __entry->socket_state = socket->state;
333 __entry->sock_state = socket->sk->sk_state;
334 __entry->ino = (unsigned long long)inode->i_ino;
335 __entry->error = error;
336 __assign_str(dstaddr,
337 xprt->address_strings[RPC_DISPLAY_ADDR]);
338 __assign_str(dstport,
339 xprt->address_strings[RPC_DISPLAY_PORT]);
343 "error=%d socket:[%llu] dstaddr=%s/%s "
344 "state=%u (%s) sk_state=%u (%s)",
346 __entry->ino, __get_str(dstaddr), __get_str(dstport),
347 __entry->socket_state,
348 rpc_show_socket_state(__entry->socket_state),
350 rpc_show_sock_state(__entry->sock_state)
353 #define DEFINE_RPC_SOCKET_EVENT_DONE(name) \
354 DEFINE_EVENT(xs_socket_event_done, name, \
356 struct rpc_xprt *xprt, \
357 struct socket *socket, \
360 TP_ARGS(xprt, socket, error))
362 DEFINE_RPC_SOCKET_EVENT(rpc_socket_state_change);
363 DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_connect);
364 DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_error);
365 DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection);
366 DEFINE_RPC_SOCKET_EVENT(rpc_socket_close);
367 DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown);
369 DECLARE_EVENT_CLASS(rpc_xprt_event,
371 const struct rpc_xprt *xprt,
376 TP_ARGS(xprt, xid, status),
381 __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
382 __string(port, xprt->address_strings[RPC_DISPLAY_PORT])
386 __entry->xid = be32_to_cpu(xid);
387 __entry->status = status;
388 __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
389 __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
392 TP_printk("peer=[%s]:%s xid=0x%08x status=%d", __get_str(addr),
393 __get_str(port), __entry->xid,
396 #define DEFINE_RPC_XPRT_EVENT(name) \
397 DEFINE_EVENT(rpc_xprt_event, xprt_##name, \
399 const struct rpc_xprt *xprt, \
403 TP_ARGS(xprt, xid, status))
405 DEFINE_RPC_XPRT_EVENT(timer);
406 DEFINE_RPC_XPRT_EVENT(lookup_rqst);
407 DEFINE_RPC_XPRT_EVENT(transmit);
408 DEFINE_RPC_XPRT_EVENT(complete_rqst);
410 TRACE_EVENT(xprt_ping,
411 TP_PROTO(const struct rpc_xprt *xprt, int status),
413 TP_ARGS(xprt, status),
417 __string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
418 __string(port, xprt->address_strings[RPC_DISPLAY_PORT])
422 __entry->status = status;
423 __assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
424 __assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
427 TP_printk("peer=[%s]:%s status=%d",
428 __get_str(addr), __get_str(port), __entry->status)
431 TRACE_EVENT(xs_stream_read_data,
432 TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
434 TP_ARGS(xprt, err, total),
437 __field(ssize_t, err)
438 __field(size_t, total)
439 __string(addr, xprt ? xprt->address_strings[RPC_DISPLAY_ADDR] :
441 __string(port, xprt ? xprt->address_strings[RPC_DISPLAY_PORT] :
447 __entry->total = total;
448 __assign_str(addr, xprt ?
449 xprt->address_strings[RPC_DISPLAY_ADDR] : "(null)");
450 __assign_str(port, xprt ?
451 xprt->address_strings[RPC_DISPLAY_PORT] : "(null)");
454 TP_printk("peer=[%s]:%s err=%zd total=%zu", __get_str(addr),
455 __get_str(port), __entry->err, __entry->total)
458 TRACE_EVENT(xs_stream_read_request,
459 TP_PROTO(struct sock_xprt *xs),
464 __string(addr, xs->xprt.address_strings[RPC_DISPLAY_ADDR])
465 __string(port, xs->xprt.address_strings[RPC_DISPLAY_PORT])
467 __field(unsigned long, copied)
468 __field(unsigned int, reclen)
469 __field(unsigned int, offset)
473 __assign_str(addr, xs->xprt.address_strings[RPC_DISPLAY_ADDR]);
474 __assign_str(port, xs->xprt.address_strings[RPC_DISPLAY_PORT]);
475 __entry->xid = be32_to_cpu(xs->recv.xid);
476 __entry->copied = xs->recv.copied;
477 __entry->reclen = xs->recv.len;
478 __entry->offset = xs->recv.offset;
481 TP_printk("peer=[%s]:%s xid=0x%08x copied=%lu reclen=%u offset=%u",
482 __get_str(addr), __get_str(port), __entry->xid,
483 __entry->copied, __entry->reclen, __entry->offset)
486 #define show_rqstp_flags(flags) \
487 __print_flags(flags, "|", \
488 { (1UL << RQ_SECURE), "RQ_SECURE"}, \
489 { (1UL << RQ_LOCAL), "RQ_LOCAL"}, \
490 { (1UL << RQ_USEDEFERRAL), "RQ_USEDEFERRAL"}, \
491 { (1UL << RQ_DROPME), "RQ_DROPME"}, \
492 { (1UL << RQ_SPLICE_OK), "RQ_SPLICE_OK"}, \
493 { (1UL << RQ_VICTIM), "RQ_VICTIM"}, \
494 { (1UL << RQ_BUSY), "RQ_BUSY"})
496 TRACE_EVENT(svc_recv,
497 TP_PROTO(struct svc_rqst *rqst, int len),
504 __field(unsigned long, flags)
505 __string(addr, rqst->rq_xprt->xpt_remotebuf)
509 __entry->xid = be32_to_cpu(rqst->rq_xid);
511 __entry->flags = rqst->rq_flags;
512 __assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
515 TP_printk("addr=%s xid=0x%08x len=%d flags=%s",
516 __get_str(addr), __entry->xid, __entry->len,
517 show_rqstp_flags(__entry->flags))
520 TRACE_EVENT(svc_process,
521 TP_PROTO(const struct svc_rqst *rqst, const char *name),
529 __string(service, name)
530 __string(addr, rqst->rq_xprt->xpt_remotebuf)
534 __entry->xid = be32_to_cpu(rqst->rq_xid);
535 __entry->vers = rqst->rq_vers;
536 __entry->proc = rqst->rq_proc;
537 __assign_str(service, name);
538 __assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
541 TP_printk("addr=%s xid=0x%08x service=%s vers=%u proc=%u",
542 __get_str(addr), __entry->xid,
543 __get_str(service), __entry->vers, __entry->proc)
546 DECLARE_EVENT_CLASS(svc_rqst_event,
549 const struct svc_rqst *rqst
556 __field(unsigned long, flags)
557 __string(addr, rqst->rq_xprt->xpt_remotebuf)
561 __entry->xid = be32_to_cpu(rqst->rq_xid);
562 __entry->flags = rqst->rq_flags;
563 __assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
566 TP_printk("addr=%s xid=0x%08x flags=%s",
567 __get_str(addr), __entry->xid,
568 show_rqstp_flags(__entry->flags))
570 #define DEFINE_SVC_RQST_EVENT(name) \
571 DEFINE_EVENT(svc_rqst_event, svc_##name, \
573 const struct svc_rqst *rqst \
577 DEFINE_SVC_RQST_EVENT(defer);
578 DEFINE_SVC_RQST_EVENT(drop);
580 DECLARE_EVENT_CLASS(svc_rqst_status,
582 TP_PROTO(struct svc_rqst *rqst, int status),
584 TP_ARGS(rqst, status),
589 __field(unsigned long, flags)
590 __string(addr, rqst->rq_xprt->xpt_remotebuf)
594 __entry->xid = be32_to_cpu(rqst->rq_xid);
595 __entry->status = status;
596 __entry->flags = rqst->rq_flags;
597 __assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
600 TP_printk("addr=%s xid=0x%08x status=%d flags=%s",
601 __get_str(addr), __entry->xid,
602 __entry->status, show_rqstp_flags(__entry->flags))
605 DEFINE_EVENT(svc_rqst_status, svc_send,
606 TP_PROTO(struct svc_rqst *rqst, int status),
607 TP_ARGS(rqst, status));
609 #define show_svc_xprt_flags(flags) \
610 __print_flags(flags, "|", \
611 { (1UL << XPT_BUSY), "XPT_BUSY"}, \
612 { (1UL << XPT_CONN), "XPT_CONN"}, \
613 { (1UL << XPT_CLOSE), "XPT_CLOSE"}, \
614 { (1UL << XPT_DATA), "XPT_DATA"}, \
615 { (1UL << XPT_TEMP), "XPT_TEMP"}, \
616 { (1UL << XPT_DEAD), "XPT_DEAD"}, \
617 { (1UL << XPT_CHNGBUF), "XPT_CHNGBUF"}, \
618 { (1UL << XPT_DEFERRED), "XPT_DEFERRED"}, \
619 { (1UL << XPT_OLD), "XPT_OLD"}, \
620 { (1UL << XPT_LISTENER), "XPT_LISTENER"}, \
621 { (1UL << XPT_CACHE_AUTH), "XPT_CACHE_AUTH"}, \
622 { (1UL << XPT_LOCAL), "XPT_LOCAL"}, \
623 { (1UL << XPT_KILL_TEMP), "XPT_KILL_TEMP"}, \
624 { (1UL << XPT_CONG_CTRL), "XPT_CONG_CTRL"})
626 TRACE_EVENT(svc_xprt_do_enqueue,
627 TP_PROTO(struct svc_xprt *xprt, struct svc_rqst *rqst),
632 __field(struct svc_xprt *, xprt)
634 __field(unsigned long, flags)
635 __string(addr, xprt->xpt_remotebuf)
639 __entry->xprt = xprt;
640 __entry->pid = rqst? rqst->rq_task->pid : 0;
641 __entry->flags = xprt->xpt_flags;
642 __assign_str(addr, xprt->xpt_remotebuf);
645 TP_printk("xprt=%p addr=%s pid=%d flags=%s",
646 __entry->xprt, __get_str(addr),
647 __entry->pid, show_svc_xprt_flags(__entry->flags))
650 DECLARE_EVENT_CLASS(svc_xprt_event,
651 TP_PROTO(struct svc_xprt *xprt),
656 __field(struct svc_xprt *, xprt)
657 __field(unsigned long, flags)
658 __string(addr, xprt->xpt_remotebuf)
662 __entry->xprt = xprt;
663 __entry->flags = xprt->xpt_flags;
664 __assign_str(addr, xprt->xpt_remotebuf);
667 TP_printk("xprt=%p addr=%s flags=%s",
668 __entry->xprt, __get_str(addr),
669 show_svc_xprt_flags(__entry->flags))
672 DEFINE_EVENT(svc_xprt_event, svc_xprt_no_write_space,
673 TP_PROTO(struct svc_xprt *xprt),
676 TRACE_EVENT(svc_xprt_dequeue,
677 TP_PROTO(struct svc_rqst *rqst),
682 __field(struct svc_xprt *, xprt)
683 __field(unsigned long, flags)
684 __field(unsigned long, wakeup)
685 __string(addr, rqst->rq_xprt->xpt_remotebuf)
689 __entry->xprt = rqst->rq_xprt;
690 __entry->flags = rqst->rq_xprt->xpt_flags;
691 __entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
693 __assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
696 TP_printk("xprt=%p addr=%s flags=%s wakeup-us=%lu",
697 __entry->xprt, __get_str(addr),
698 show_svc_xprt_flags(__entry->flags),
702 TRACE_EVENT(svc_wake_up,
715 TP_printk("pid=%d", __entry->pid)
718 TRACE_EVENT(svc_handle_xprt,
719 TP_PROTO(struct svc_xprt *xprt, int len),
724 __field(struct svc_xprt *, xprt)
726 __field(unsigned long, flags)
727 __string(addr, xprt->xpt_remotebuf)
731 __entry->xprt = xprt;
733 __entry->flags = xprt->xpt_flags;
734 __assign_str(addr, xprt->xpt_remotebuf);
737 TP_printk("xprt=%p addr=%s len=%d flags=%s",
738 __entry->xprt, __get_str(addr),
739 __entry->len, show_svc_xprt_flags(__entry->flags))
742 TRACE_EVENT(svc_stats_latency,
743 TP_PROTO(const struct svc_rqst *rqst),
749 __field(unsigned long, execute)
750 __string(addr, rqst->rq_xprt->xpt_remotebuf)
754 __entry->xid = be32_to_cpu(rqst->rq_xid);
755 __entry->execute = ktime_to_us(ktime_sub(ktime_get(),
757 __assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
760 TP_printk("addr=%s xid=0x%08x execute-us=%lu",
761 __get_str(addr), __entry->xid, __entry->execute)
764 DECLARE_EVENT_CLASS(svc_deferred_event,
766 const struct svc_deferred_req *dr
773 __string(addr, dr->xprt->xpt_remotebuf)
777 __entry->xid = be32_to_cpu(*(__be32 *)(dr->args +
778 (dr->xprt_hlen>>2)));
779 __assign_str(addr, dr->xprt->xpt_remotebuf);
782 TP_printk("addr=%s xid=0x%08x", __get_str(addr), __entry->xid)
784 #define DEFINE_SVC_DEFERRED_EVENT(name) \
785 DEFINE_EVENT(svc_deferred_event, svc_##name##_deferred, \
787 const struct svc_deferred_req *dr \
791 DEFINE_SVC_DEFERRED_EVENT(drop);
792 DEFINE_SVC_DEFERRED_EVENT(revisit);
794 #endif /* _TRACE_SUNRPC_H */
796 #include <trace/define_trace.h>