xref: /linux/include/trace/events/sunrpc.h (revision 4949009eb8d40a441dcddcd96e101e77d31cf1b2)
1 #undef TRACE_SYSTEM
2 #define TRACE_SYSTEM sunrpc
3 
4 #if !defined(_TRACE_SUNRPC_H) || defined(TRACE_HEADER_MULTI_READ)
5 #define _TRACE_SUNRPC_H
6 
7 #include <linux/sunrpc/sched.h>
8 #include <linux/sunrpc/clnt.h>
9 #include <linux/sunrpc/svc.h>
10 #include <linux/sunrpc/xprtsock.h>
11 #include <linux/sunrpc/svc_xprt.h>
12 #include <net/tcp_states.h>
13 #include <linux/net.h>
14 #include <linux/tracepoint.h>
15 
16 DECLARE_EVENT_CLASS(rpc_task_status,
17 
18 	TP_PROTO(struct rpc_task *task),
19 
20 	TP_ARGS(task),
21 
22 	TP_STRUCT__entry(
23 		__field(unsigned int, task_id)
24 		__field(unsigned int, client_id)
25 		__field(int, status)
26 	),
27 
28 	TP_fast_assign(
29 		__entry->task_id = task->tk_pid;
30 		__entry->client_id = task->tk_client->cl_clid;
31 		__entry->status = task->tk_status;
32 	),
33 
34 	TP_printk("task:%u@%u, status %d",
35 		__entry->task_id, __entry->client_id,
36 		__entry->status)
37 );
38 
39 DEFINE_EVENT(rpc_task_status, rpc_call_status,
40 	TP_PROTO(struct rpc_task *task),
41 
42 	TP_ARGS(task)
43 );
44 
45 DEFINE_EVENT(rpc_task_status, rpc_bind_status,
46 	TP_PROTO(struct rpc_task *task),
47 
48 	TP_ARGS(task)
49 );
50 
51 TRACE_EVENT(rpc_connect_status,
52 	TP_PROTO(struct rpc_task *task, int status),
53 
54 	TP_ARGS(task, status),
55 
56 	TP_STRUCT__entry(
57 		__field(unsigned int, task_id)
58 		__field(unsigned int, client_id)
59 		__field(int, status)
60 	),
61 
62 	TP_fast_assign(
63 		__entry->task_id = task->tk_pid;
64 		__entry->client_id = task->tk_client->cl_clid;
65 		__entry->status = status;
66 	),
67 
68 	TP_printk("task:%u@%u, status %d",
69 		__entry->task_id, __entry->client_id,
70 		__entry->status)
71 );
72 
73 DECLARE_EVENT_CLASS(rpc_task_running,
74 
75 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
76 
77 	TP_ARGS(clnt, task, action),
78 
79 	TP_STRUCT__entry(
80 		__field(unsigned int, task_id)
81 		__field(unsigned int, client_id)
82 		__field(const void *, action)
83 		__field(unsigned long, runstate)
84 		__field(int, status)
85 		__field(unsigned short, flags)
86 		),
87 
88 	TP_fast_assign(
89 		__entry->client_id = clnt ? clnt->cl_clid : -1;
90 		__entry->task_id = task->tk_pid;
91 		__entry->action = action;
92 		__entry->runstate = task->tk_runstate;
93 		__entry->status = task->tk_status;
94 		__entry->flags = task->tk_flags;
95 		),
96 
97 	TP_printk("task:%u@%d flags=%4.4x state=%4.4lx status=%d action=%pf",
98 		__entry->task_id, __entry->client_id,
99 		__entry->flags,
100 		__entry->runstate,
101 		__entry->status,
102 		__entry->action
103 		)
104 );
105 
106 DEFINE_EVENT(rpc_task_running, rpc_task_begin,
107 
108 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
109 
110 	TP_ARGS(clnt, task, action)
111 
112 );
113 
114 DEFINE_EVENT(rpc_task_running, rpc_task_run_action,
115 
116 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
117 
118 	TP_ARGS(clnt, task, action)
119 
120 );
121 
122 DEFINE_EVENT(rpc_task_running, rpc_task_complete,
123 
124 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const void *action),
125 
126 	TP_ARGS(clnt, task, action)
127 
128 );
129 
130 DECLARE_EVENT_CLASS(rpc_task_queued,
131 
132 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
133 
134 	TP_ARGS(clnt, task, q),
135 
136 	TP_STRUCT__entry(
137 		__field(unsigned int, task_id)
138 		__field(unsigned int, client_id)
139 		__field(unsigned long, timeout)
140 		__field(unsigned long, runstate)
141 		__field(int, status)
142 		__field(unsigned short, flags)
143 		__string(q_name, rpc_qname(q))
144 		),
145 
146 	TP_fast_assign(
147 		__entry->client_id = clnt->cl_clid;
148 		__entry->task_id = task->tk_pid;
149 		__entry->timeout = task->tk_timeout;
150 		__entry->runstate = task->tk_runstate;
151 		__entry->status = task->tk_status;
152 		__entry->flags = task->tk_flags;
153 		__assign_str(q_name, rpc_qname(q));
154 		),
155 
156 	TP_printk("task:%u@%u flags=%4.4x state=%4.4lx status=%d timeout=%lu queue=%s",
157 		__entry->task_id, __entry->client_id,
158 		__entry->flags,
159 		__entry->runstate,
160 		__entry->status,
161 		__entry->timeout,
162 		__get_str(q_name)
163 		)
164 );
165 
166 DEFINE_EVENT(rpc_task_queued, rpc_task_sleep,
167 
168 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
169 
170 	TP_ARGS(clnt, task, q)
171 
172 );
173 
174 DEFINE_EVENT(rpc_task_queued, rpc_task_wakeup,
175 
176 	TP_PROTO(const struct rpc_clnt *clnt, const struct rpc_task *task, const struct rpc_wait_queue *q),
177 
178 	TP_ARGS(clnt, task, q)
179 
180 );
181 
182 #define rpc_show_socket_state(state) \
183 	__print_symbolic(state, \
184 		{ SS_FREE, "FREE" }, \
185 		{ SS_UNCONNECTED, "UNCONNECTED" }, \
186 		{ SS_CONNECTING, "CONNECTING," }, \
187 		{ SS_CONNECTED, "CONNECTED," }, \
188 		{ SS_DISCONNECTING, "DISCONNECTING" })
189 
190 #define rpc_show_sock_state(state) \
191 	__print_symbolic(state, \
192 		{ TCP_ESTABLISHED, "ESTABLISHED" }, \
193 		{ TCP_SYN_SENT, "SYN_SENT" }, \
194 		{ TCP_SYN_RECV, "SYN_RECV" }, \
195 		{ TCP_FIN_WAIT1, "FIN_WAIT1" }, \
196 		{ TCP_FIN_WAIT2, "FIN_WAIT2" }, \
197 		{ TCP_TIME_WAIT, "TIME_WAIT" }, \
198 		{ TCP_CLOSE, "CLOSE" }, \
199 		{ TCP_CLOSE_WAIT, "CLOSE_WAIT" }, \
200 		{ TCP_LAST_ACK, "LAST_ACK" }, \
201 		{ TCP_LISTEN, "LISTEN" }, \
202 		{ TCP_CLOSING, "CLOSING" })
203 
204 DECLARE_EVENT_CLASS(xs_socket_event,
205 
206 		TP_PROTO(
207 			struct rpc_xprt *xprt,
208 			struct socket *socket
209 		),
210 
211 		TP_ARGS(xprt, socket),
212 
213 		TP_STRUCT__entry(
214 			__field(unsigned int, socket_state)
215 			__field(unsigned int, sock_state)
216 			__field(unsigned long long, ino)
217 			__string(dstaddr,
218 				xprt->address_strings[RPC_DISPLAY_ADDR])
219 			__string(dstport,
220 				xprt->address_strings[RPC_DISPLAY_PORT])
221 		),
222 
223 		TP_fast_assign(
224 			struct inode *inode = SOCK_INODE(socket);
225 			__entry->socket_state = socket->state;
226 			__entry->sock_state = socket->sk->sk_state;
227 			__entry->ino = (unsigned long long)inode->i_ino;
228 			__assign_str(dstaddr,
229 				xprt->address_strings[RPC_DISPLAY_ADDR]);
230 			__assign_str(dstport,
231 				xprt->address_strings[RPC_DISPLAY_PORT]);
232 		),
233 
234 		TP_printk(
235 			"socket:[%llu] dstaddr=%s/%s "
236 			"state=%u (%s) sk_state=%u (%s)",
237 			__entry->ino, __get_str(dstaddr), __get_str(dstport),
238 			__entry->socket_state,
239 			rpc_show_socket_state(__entry->socket_state),
240 			__entry->sock_state,
241 			rpc_show_sock_state(__entry->sock_state)
242 		)
243 );
244 #define DEFINE_RPC_SOCKET_EVENT(name) \
245 	DEFINE_EVENT(xs_socket_event, name, \
246 			TP_PROTO( \
247 				struct rpc_xprt *xprt, \
248 				struct socket *socket \
249 			), \
250 			TP_ARGS(xprt, socket))
251 
252 DECLARE_EVENT_CLASS(xs_socket_event_done,
253 
254 		TP_PROTO(
255 			struct rpc_xprt *xprt,
256 			struct socket *socket,
257 			int error
258 		),
259 
260 		TP_ARGS(xprt, socket, error),
261 
262 		TP_STRUCT__entry(
263 			__field(int, error)
264 			__field(unsigned int, socket_state)
265 			__field(unsigned int, sock_state)
266 			__field(unsigned long long, ino)
267 			__string(dstaddr,
268 				xprt->address_strings[RPC_DISPLAY_ADDR])
269 			__string(dstport,
270 				xprt->address_strings[RPC_DISPLAY_PORT])
271 		),
272 
273 		TP_fast_assign(
274 			struct inode *inode = SOCK_INODE(socket);
275 			__entry->socket_state = socket->state;
276 			__entry->sock_state = socket->sk->sk_state;
277 			__entry->ino = (unsigned long long)inode->i_ino;
278 			__entry->error = error;
279 			__assign_str(dstaddr,
280 				xprt->address_strings[RPC_DISPLAY_ADDR]);
281 			__assign_str(dstport,
282 				xprt->address_strings[RPC_DISPLAY_PORT]);
283 		),
284 
285 		TP_printk(
286 			"error=%d socket:[%llu] dstaddr=%s/%s "
287 			"state=%u (%s) sk_state=%u (%s)",
288 			__entry->error,
289 			__entry->ino, __get_str(dstaddr), __get_str(dstport),
290 			__entry->socket_state,
291 			rpc_show_socket_state(__entry->socket_state),
292 			__entry->sock_state,
293 			rpc_show_sock_state(__entry->sock_state)
294 		)
295 );
296 #define DEFINE_RPC_SOCKET_EVENT_DONE(name) \
297 	DEFINE_EVENT(xs_socket_event_done, name, \
298 			TP_PROTO( \
299 				struct rpc_xprt *xprt, \
300 				struct socket *socket, \
301 				int error \
302 			), \
303 			TP_ARGS(xprt, socket, error))
304 
305 DEFINE_RPC_SOCKET_EVENT(rpc_socket_state_change);
306 DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_connect);
307 DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_error);
308 DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection);
309 DEFINE_RPC_SOCKET_EVENT(rpc_socket_close);
310 DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown);
311 
312 DECLARE_EVENT_CLASS(rpc_xprt_event,
313 	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),
314 
315 	TP_ARGS(xprt, xid, status),
316 
317 	TP_STRUCT__entry(
318 		__field(__be32, xid)
319 		__field(int, status)
320 		__string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
321 		__string(port, xprt->address_strings[RPC_DISPLAY_PORT])
322 	),
323 
324 	TP_fast_assign(
325 		__entry->xid = xid;
326 		__entry->status = status;
327 		__assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
328 		__assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
329 	),
330 
331 	TP_printk("peer=[%s]:%s xid=0x%x status=%d", __get_str(addr),
332 			__get_str(port), be32_to_cpu(__entry->xid),
333 			__entry->status)
334 );
335 
336 DEFINE_EVENT(rpc_xprt_event, xprt_lookup_rqst,
337 	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),
338 	TP_ARGS(xprt, xid, status));
339 
340 DEFINE_EVENT(rpc_xprt_event, xprt_transmit,
341 	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),
342 	TP_ARGS(xprt, xid, status));
343 
344 DEFINE_EVENT(rpc_xprt_event, xprt_complete_rqst,
345 	TP_PROTO(struct rpc_xprt *xprt, __be32 xid, int status),
346 	TP_ARGS(xprt, xid, status));
347 
348 TRACE_EVENT(xs_tcp_data_ready,
349 	TP_PROTO(struct rpc_xprt *xprt, int err, unsigned int total),
350 
351 	TP_ARGS(xprt, err, total),
352 
353 	TP_STRUCT__entry(
354 		__field(int, err)
355 		__field(unsigned int, total)
356 		__string(addr, xprt ? xprt->address_strings[RPC_DISPLAY_ADDR] :
357 				"(null)")
358 		__string(port, xprt ? xprt->address_strings[RPC_DISPLAY_PORT] :
359 				"(null)")
360 	),
361 
362 	TP_fast_assign(
363 		__entry->err = err;
364 		__entry->total = total;
365 		__assign_str(addr, xprt ?
366 			xprt->address_strings[RPC_DISPLAY_ADDR] : "(null)");
367 		__assign_str(port, xprt ?
368 			xprt->address_strings[RPC_DISPLAY_PORT] : "(null)");
369 	),
370 
371 	TP_printk("peer=[%s]:%s err=%d total=%u", __get_str(addr),
372 			__get_str(port), __entry->err, __entry->total)
373 );
374 
375 #define rpc_show_sock_xprt_flags(flags) \
376 	__print_flags(flags, "|", \
377 		{ TCP_RCV_LAST_FRAG, "TCP_RCV_LAST_FRAG" }, \
378 		{ TCP_RCV_COPY_FRAGHDR, "TCP_RCV_COPY_FRAGHDR" }, \
379 		{ TCP_RCV_COPY_XID, "TCP_RCV_COPY_XID" }, \
380 		{ TCP_RCV_COPY_DATA, "TCP_RCV_COPY_DATA" }, \
381 		{ TCP_RCV_READ_CALLDIR, "TCP_RCV_READ_CALLDIR" }, \
382 		{ TCP_RCV_COPY_CALLDIR, "TCP_RCV_COPY_CALLDIR" }, \
383 		{ TCP_RPC_REPLY, "TCP_RPC_REPLY" })
384 
385 TRACE_EVENT(xs_tcp_data_recv,
386 	TP_PROTO(struct sock_xprt *xs),
387 
388 	TP_ARGS(xs),
389 
390 	TP_STRUCT__entry(
391 		__string(addr, xs->xprt.address_strings[RPC_DISPLAY_ADDR])
392 		__string(port, xs->xprt.address_strings[RPC_DISPLAY_PORT])
393 		__field(__be32, xid)
394 		__field(unsigned long, flags)
395 		__field(unsigned long, copied)
396 		__field(unsigned int, reclen)
397 		__field(unsigned long, offset)
398 	),
399 
400 	TP_fast_assign(
401 		__assign_str(addr, xs->xprt.address_strings[RPC_DISPLAY_ADDR]);
402 		__assign_str(port, xs->xprt.address_strings[RPC_DISPLAY_PORT]);
403 		__entry->xid = xs->tcp_xid;
404 		__entry->flags = xs->tcp_flags;
405 		__entry->copied = xs->tcp_copied;
406 		__entry->reclen = xs->tcp_reclen;
407 		__entry->offset = xs->tcp_offset;
408 	),
409 
410 	TP_printk("peer=[%s]:%s xid=0x%x flags=%s copied=%lu reclen=%u offset=%lu",
411 			__get_str(addr), __get_str(port), be32_to_cpu(__entry->xid),
412 			rpc_show_sock_xprt_flags(__entry->flags),
413 			__entry->copied, __entry->reclen, __entry->offset)
414 );
415 
416 #define show_rqstp_flags(flags)						\
417 	__print_flags(flags, "|",					\
418 		{ (1UL << RQ_SECURE),		"RQ_SECURE"},		\
419 		{ (1UL << RQ_LOCAL),		"RQ_LOCAL"},		\
420 		{ (1UL << RQ_USEDEFERRAL),	"RQ_USEDEFERRAL"},	\
421 		{ (1UL << RQ_DROPME),		"RQ_DROPME"},		\
422 		{ (1UL << RQ_SPLICE_OK),	"RQ_SPLICE_OK"},	\
423 		{ (1UL << RQ_VICTIM),		"RQ_VICTIM"},		\
424 		{ (1UL << RQ_BUSY),		"RQ_BUSY"})
425 
426 TRACE_EVENT(svc_recv,
427 	TP_PROTO(struct svc_rqst *rqst, int status),
428 
429 	TP_ARGS(rqst, status),
430 
431 	TP_STRUCT__entry(
432 		__field(struct sockaddr *, addr)
433 		__field(__be32, xid)
434 		__field(int, status)
435 		__field(unsigned long, flags)
436 	),
437 
438 	TP_fast_assign(
439 		__entry->addr = (struct sockaddr *)&rqst->rq_addr;
440 		__entry->xid = status > 0 ? rqst->rq_xid : 0;
441 		__entry->status = status;
442 		__entry->flags = rqst->rq_flags;
443 	),
444 
445 	TP_printk("addr=%pIScp xid=0x%x status=%d flags=%s", __entry->addr,
446 			be32_to_cpu(__entry->xid), __entry->status,
447 			show_rqstp_flags(__entry->flags))
448 );
449 
450 DECLARE_EVENT_CLASS(svc_rqst_status,
451 
452 	TP_PROTO(struct svc_rqst *rqst, int status),
453 
454 	TP_ARGS(rqst, status),
455 
456 	TP_STRUCT__entry(
457 		__field(struct sockaddr *, addr)
458 		__field(__be32, xid)
459 		__field(int, dropme)
460 		__field(int, status)
461 		__field(unsigned long, flags)
462 	),
463 
464 	TP_fast_assign(
465 		__entry->addr = (struct sockaddr *)&rqst->rq_addr;
466 		__entry->xid = rqst->rq_xid;
467 		__entry->status = status;
468 		__entry->flags = rqst->rq_flags;
469 	),
470 
471 	TP_printk("addr=%pIScp rq_xid=0x%x status=%d flags=%s",
472 		__entry->addr, be32_to_cpu(__entry->xid),
473 		__entry->status, show_rqstp_flags(__entry->flags))
474 );
475 
476 DEFINE_EVENT(svc_rqst_status, svc_process,
477 	TP_PROTO(struct svc_rqst *rqst, int status),
478 	TP_ARGS(rqst, status));
479 
480 DEFINE_EVENT(svc_rqst_status, svc_send,
481 	TP_PROTO(struct svc_rqst *rqst, int status),
482 	TP_ARGS(rqst, status));
483 
484 #define show_svc_xprt_flags(flags)					\
485 	__print_flags(flags, "|",					\
486 		{ (1UL << XPT_BUSY),		"XPT_BUSY"},		\
487 		{ (1UL << XPT_CONN),		"XPT_CONN"},		\
488 		{ (1UL << XPT_CLOSE),		"XPT_CLOSE"},		\
489 		{ (1UL << XPT_DATA),		"XPT_DATA"},		\
490 		{ (1UL << XPT_TEMP),		"XPT_TEMP"},		\
491 		{ (1UL << XPT_DEAD),		"XPT_DEAD"},		\
492 		{ (1UL << XPT_CHNGBUF),		"XPT_CHNGBUF"},		\
493 		{ (1UL << XPT_DEFERRED),	"XPT_DEFERRED"},	\
494 		{ (1UL << XPT_OLD),		"XPT_OLD"},		\
495 		{ (1UL << XPT_LISTENER),	"XPT_LISTENER"},	\
496 		{ (1UL << XPT_CACHE_AUTH),	"XPT_CACHE_AUTH"},	\
497 		{ (1UL << XPT_LOCAL),		"XPT_LOCAL"})
498 
499 TRACE_EVENT(svc_xprt_do_enqueue,
500 	TP_PROTO(struct svc_xprt *xprt, struct svc_rqst *rqst),
501 
502 	TP_ARGS(xprt, rqst),
503 
504 	TP_STRUCT__entry(
505 		__field(struct svc_xprt *, xprt)
506 		__field(struct svc_rqst *, rqst)
507 	),
508 
509 	TP_fast_assign(
510 		__entry->xprt = xprt;
511 		__entry->rqst = rqst;
512 	),
513 
514 	TP_printk("xprt=0x%p addr=%pIScp pid=%d flags=%s", __entry->xprt,
515 		(struct sockaddr *)&__entry->xprt->xpt_remote,
516 		__entry->rqst ? __entry->rqst->rq_task->pid : 0,
517 		show_svc_xprt_flags(__entry->xprt->xpt_flags))
518 );
519 
520 TRACE_EVENT(svc_xprt_dequeue,
521 	TP_PROTO(struct svc_xprt *xprt),
522 
523 	TP_ARGS(xprt),
524 
525 	TP_STRUCT__entry(
526 		__field(struct svc_xprt *, xprt)
527 		__field_struct(struct sockaddr_storage, ss)
528 		__field(unsigned long, flags)
529 	),
530 
531 	TP_fast_assign(
532 		__entry->xprt = xprt,
533 		xprt ? memcpy(&__entry->ss, &xprt->xpt_remote, sizeof(__entry->ss)) : memset(&__entry->ss, 0, sizeof(__entry->ss));
534 		__entry->flags = xprt ? xprt->xpt_flags : 0;
535 	),
536 
537 	TP_printk("xprt=0x%p addr=%pIScp flags=%s", __entry->xprt,
538 		(struct sockaddr *)&__entry->ss,
539 		show_svc_xprt_flags(__entry->flags))
540 );
541 
542 TRACE_EVENT(svc_wake_up,
543 	TP_PROTO(int pid),
544 
545 	TP_ARGS(pid),
546 
547 	TP_STRUCT__entry(
548 		__field(int, pid)
549 	),
550 
551 	TP_fast_assign(
552 		__entry->pid = pid;
553 	),
554 
555 	TP_printk("pid=%d", __entry->pid)
556 );
557 
558 TRACE_EVENT(svc_handle_xprt,
559 	TP_PROTO(struct svc_xprt *xprt, int len),
560 
561 	TP_ARGS(xprt, len),
562 
563 	TP_STRUCT__entry(
564 		__field(struct svc_xprt *, xprt)
565 		__field(int, len)
566 	),
567 
568 	TP_fast_assign(
569 		__entry->xprt = xprt;
570 		__entry->len = len;
571 	),
572 
573 	TP_printk("xprt=0x%p addr=%pIScp len=%d flags=%s", __entry->xprt,
574 		(struct sockaddr *)&__entry->xprt->xpt_remote, __entry->len,
575 		show_svc_xprt_flags(__entry->xprt->xpt_flags))
576 );
577 #endif /* _TRACE_SUNRPC_H */
578 
579 #include <trace/define_trace.h>
580