sunrpc.h 28.0 KB
Newer Older
1
/* SPDX-License-Identifier: GPL-2.0 */
2 3 4 5 6 7 8 9
#undef TRACE_SYSTEM
#define TRACE_SYSTEM sunrpc

#if !defined(_TRACE_SUNRPC_H) || defined(TRACE_HEADER_MULTI_READ)
#define _TRACE_SUNRPC_H

#include <linux/sunrpc/sched.h>
#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 14
#include <net/tcp_states.h>
#include <linux/net.h>
15 16
#include <linux/tracepoint.h>

17 18
DECLARE_EVENT_CLASS(rpc_task_status,

19
	TP_PROTO(const struct rpc_task *task),
20

21
	TP_ARGS(task),
22 23

	TP_STRUCT__entry(
24 25
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
26 27 28 29
		__field(int, status)
	),

	TP_fast_assign(
30 31
		__entry->task_id = task->tk_pid;
		__entry->client_id = task->tk_client->cl_clid;
32
		__entry->status = task->tk_status;
33 34
	),

35
	TP_printk("task:%u@%u status=%d",
36 37
		__entry->task_id, __entry->client_id,
		__entry->status)
38
);
39 40 41 42 43 44 45 46 47 48
#define DEFINE_RPC_STATUS_EVENT(name) \
	DEFINE_EVENT(rpc_task_status, rpc_##name##_status, \
			TP_PROTO( \
				const struct rpc_task *task \
			), \
			TP_ARGS(task))

DEFINE_RPC_STATUS_EVENT(call);
DEFINE_RPC_STATUS_EVENT(bind);
DEFINE_RPC_STATUS_EVENT(connect);
49

50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79
TRACE_EVENT(rpc_request,
	TP_PROTO(const struct rpc_task *task),

	TP_ARGS(task),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
		__field(int, version)
		__field(bool, async)
		__string(progname, task->tk_client->cl_program->name)
		__string(procname, rpc_proc_name(task))
	),

	TP_fast_assign(
		__entry->task_id = task->tk_pid;
		__entry->client_id = task->tk_client->cl_clid;
		__entry->version = task->tk_client->cl_vers;
		__entry->async = RPC_IS_ASYNC(task);
		__assign_str(progname, task->tk_client->cl_program->name)
		__assign_str(procname, rpc_proc_name(task))
	),

	TP_printk("task:%u@%u %sv%d %s (%ssync)",
		__entry->task_id, __entry->client_id,
		__get_str(progname), __entry->version,
		__get_str(procname), __entry->async ? "a": ""
		)
);

80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123
TRACE_DEFINE_ENUM(RPC_TASK_ASYNC);
TRACE_DEFINE_ENUM(RPC_TASK_SWAPPER);
TRACE_DEFINE_ENUM(RPC_CALL_MAJORSEEN);
TRACE_DEFINE_ENUM(RPC_TASK_ROOTCREDS);
TRACE_DEFINE_ENUM(RPC_TASK_DYNAMIC);
TRACE_DEFINE_ENUM(RPC_TASK_KILLED);
TRACE_DEFINE_ENUM(RPC_TASK_SOFT);
TRACE_DEFINE_ENUM(RPC_TASK_SOFTCONN);
TRACE_DEFINE_ENUM(RPC_TASK_SENT);
TRACE_DEFINE_ENUM(RPC_TASK_TIMEOUT);
TRACE_DEFINE_ENUM(RPC_TASK_NOCONNECT);
TRACE_DEFINE_ENUM(RPC_TASK_NO_RETRANS_TIMEOUT);

#define rpc_show_task_flags(flags)					\
	__print_flags(flags, "|",					\
		{ RPC_TASK_ASYNC, "ASYNC" },				\
		{ RPC_TASK_SWAPPER, "SWAPPER" },			\
		{ RPC_CALL_MAJORSEEN, "MAJORSEEN" },			\
		{ RPC_TASK_ROOTCREDS, "ROOTCREDS" },			\
		{ RPC_TASK_DYNAMIC, "DYNAMIC" },			\
		{ RPC_TASK_KILLED, "KILLED" },				\
		{ RPC_TASK_SOFT, "SOFT" },				\
		{ RPC_TASK_SOFTCONN, "SOFTCONN" },			\
		{ RPC_TASK_SENT, "SENT" },				\
		{ RPC_TASK_TIMEOUT, "TIMEOUT" },			\
		{ RPC_TASK_NOCONNECT, "NOCONNECT" },			\
		{ RPC_TASK_NO_RETRANS_TIMEOUT, "NORTO" })

TRACE_DEFINE_ENUM(RPC_TASK_RUNNING);
TRACE_DEFINE_ENUM(RPC_TASK_QUEUED);
TRACE_DEFINE_ENUM(RPC_TASK_ACTIVE);
TRACE_DEFINE_ENUM(RPC_TASK_NEED_XMIT);
TRACE_DEFINE_ENUM(RPC_TASK_NEED_RECV);
TRACE_DEFINE_ENUM(RPC_TASK_MSG_PIN_WAIT);

#define rpc_show_runstate(flags)					\
	__print_flags(flags, "|",					\
		{ (1UL << RPC_TASK_RUNNING), "RUNNING" },		\
		{ (1UL << RPC_TASK_QUEUED), "QUEUED" },			\
		{ (1UL << RPC_TASK_ACTIVE), "ACTIVE" },			\
		{ (1UL << RPC_TASK_NEED_XMIT), "NEED_XMIT" },		\
		{ (1UL << RPC_TASK_NEED_RECV), "NEED_RECV" },		\
		{ (1UL << RPC_TASK_MSG_PIN_WAIT), "MSG_PIN_WAIT" })

124 125
DECLARE_EVENT_CLASS(rpc_task_running,

126
	TP_PROTO(const struct rpc_task *task, const void *action),
127

128
	TP_ARGS(task, action),
129 130

	TP_STRUCT__entry(
131 132
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
133 134 135 136 137 138 139
		__field(const void *, action)
		__field(unsigned long, runstate)
		__field(int, status)
		__field(unsigned short, flags)
		),

	TP_fast_assign(
140 141
		__entry->client_id = task->tk_client ?
				     task->tk_client->cl_clid : -1;
142
		__entry->task_id = task->tk_pid;
143 144 145 146 147 148
		__entry->action = action;
		__entry->runstate = task->tk_runstate;
		__entry->status = task->tk_status;
		__entry->flags = task->tk_flags;
		),

149
	TP_printk("task:%u@%d flags=%s runstate=%s status=%d action=%pf",
150
		__entry->task_id, __entry->client_id,
151 152
		rpc_show_task_flags(__entry->flags),
		rpc_show_runstate(__entry->runstate),
153 154 155 156
		__entry->status,
		__entry->action
		)
);
157 158 159 160 161 162 163
#define DEFINE_RPC_RUNNING_EVENT(name) \
	DEFINE_EVENT(rpc_task_running, rpc_task_##name, \
			TP_PROTO( \
				const struct rpc_task *task, \
				const void *action \
			), \
			TP_ARGS(task, action))
164

165 166 167
DEFINE_RPC_RUNNING_EVENT(begin);
DEFINE_RPC_RUNNING_EVENT(run_action);
DEFINE_RPC_RUNNING_EVENT(complete);
168 169 170

DECLARE_EVENT_CLASS(rpc_task_queued,

171
	TP_PROTO(const struct rpc_task *task, const struct rpc_wait_queue *q),
172

173
	TP_ARGS(task, q),
174 175

	TP_STRUCT__entry(
176 177
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
178 179 180 181
		__field(unsigned long, timeout)
		__field(unsigned long, runstate)
		__field(int, status)
		__field(unsigned short, flags)
182
		__string(q_name, rpc_qname(q))
183 184 185
		),

	TP_fast_assign(
186 187
		__entry->client_id = task->tk_client ?
				     task->tk_client->cl_clid : -1;
188
		__entry->task_id = task->tk_pid;
189 190 191 192
		__entry->timeout = task->tk_timeout;
		__entry->runstate = task->tk_runstate;
		__entry->status = task->tk_status;
		__entry->flags = task->tk_flags;
193
		__assign_str(q_name, rpc_qname(q));
194 195
		),

196
	TP_printk("task:%u@%d flags=%s runstate=%s status=%d timeout=%lu queue=%s",
197
		__entry->task_id, __entry->client_id,
198 199
		rpc_show_task_flags(__entry->flags),
		rpc_show_runstate(__entry->runstate),
200 201
		__entry->status,
		__entry->timeout,
202
		__get_str(q_name)
203 204
		)
);
205 206 207 208 209 210 211
#define DEFINE_RPC_QUEUED_EVENT(name) \
	DEFINE_EVENT(rpc_task_queued, rpc_task_##name, \
			TP_PROTO( \
				const struct rpc_task *task, \
				const struct rpc_wait_queue *q \
			), \
			TP_ARGS(task, q))
212

213 214
DEFINE_RPC_QUEUED_EVENT(sleep);
DEFINE_RPC_QUEUED_EVENT(wakeup);
215

216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243
DECLARE_EVENT_CLASS(rpc_failure,

	TP_PROTO(const struct rpc_task *task),

	TP_ARGS(task),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
	),

	TP_fast_assign(
		__entry->task_id = task->tk_pid;
		__entry->client_id = task->tk_client->cl_clid;
	),

	TP_printk("task:%u@%u",
		__entry->task_id, __entry->client_id)
);

#define DEFINE_RPC_FAILURE(name)					\
	DEFINE_EVENT(rpc_failure, rpc_bad_##name,			\
			TP_PROTO(					\
				const struct rpc_task *task		\
			),						\
			TP_ARGS(task))

DEFINE_RPC_FAILURE(callhdr);
244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295
DEFINE_RPC_FAILURE(verifier);

DECLARE_EVENT_CLASS(rpc_reply_event,

	TP_PROTO(
		const struct rpc_task *task
	),

	TP_ARGS(task),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
		__field(u32, xid)
		__string(progname, task->tk_client->cl_program->name)
		__field(u32, version)
		__string(procname, rpc_proc_name(task))
		__string(servername, task->tk_xprt->servername)
	),

	TP_fast_assign(
		__entry->task_id = task->tk_pid;
		__entry->client_id = task->tk_client->cl_clid;
		__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
		__assign_str(progname, task->tk_client->cl_program->name)
		__entry->version = task->tk_client->cl_vers;
		__assign_str(procname, rpc_proc_name(task))
		__assign_str(servername, task->tk_xprt->servername)
	),

	TP_printk("task:%u@%d server=%s xid=0x%08x %sv%d %s",
		__entry->task_id, __entry->client_id, __get_str(servername),
		__entry->xid, __get_str(progname), __entry->version,
		__get_str(procname))
)

#define DEFINE_RPC_REPLY_EVENT(name)					\
	DEFINE_EVENT(rpc_reply_event, rpc__##name,			\
			TP_PROTO(					\
				const struct rpc_task *task		\
			),						\
			TP_ARGS(task))

DEFINE_RPC_REPLY_EVENT(prog_unavail);
DEFINE_RPC_REPLY_EVENT(prog_mismatch);
DEFINE_RPC_REPLY_EVENT(proc_unavail);
DEFINE_RPC_REPLY_EVENT(garbage_args);
DEFINE_RPC_REPLY_EVENT(unparsable);
DEFINE_RPC_REPLY_EVENT(mismatch);
DEFINE_RPC_REPLY_EVENT(stale_creds);
DEFINE_RPC_REPLY_EVENT(bad_creds);
DEFINE_RPC_REPLY_EVENT(auth_tooweak);
296

297 298 299 300 301 302 303 304 305 306 307 308
TRACE_EVENT(rpc_stats_latency,

	TP_PROTO(
		const struct rpc_task *task,
		ktime_t backlog,
		ktime_t rtt,
		ktime_t execute
	),

	TP_ARGS(task, backlog, rtt, execute),

	TP_STRUCT__entry(
309 310
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
311 312 313 314 315 316 317 318 319 320
		__field(u32, xid)
		__field(int, version)
		__string(progname, task->tk_client->cl_program->name)
		__string(procname, rpc_proc_name(task))
		__field(unsigned long, backlog)
		__field(unsigned long, rtt)
		__field(unsigned long, execute)
	),

	TP_fast_assign(
321 322
		__entry->client_id = task->tk_client->cl_clid;
		__entry->task_id = task->tk_pid;
323 324 325 326 327 328 329 330 331
		__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
		__entry->version = task->tk_client->cl_vers;
		__assign_str(progname, task->tk_client->cl_program->name)
		__assign_str(procname, rpc_proc_name(task))
		__entry->backlog = ktime_to_us(backlog);
		__entry->rtt = ktime_to_us(rtt);
		__entry->execute = ktime_to_us(execute);
	),

332 333
	TP_printk("task:%u@%d xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu",
		__entry->task_id, __entry->client_id, __entry->xid,
334 335 336 337
		__get_str(progname), __entry->version, __get_str(procname),
		__entry->backlog, __entry->rtt, __entry->execute)
);

338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404
TRACE_EVENT(rpc_xdr_overflow,
	TP_PROTO(
		const struct xdr_stream *xdr,
		size_t requested
	),

	TP_ARGS(xdr, requested),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
		__field(int, version)
		__field(size_t, requested)
		__field(const void *, end)
		__field(const void *, p)
		__field(const void *, head_base)
		__field(size_t, head_len)
		__field(const void *, tail_base)
		__field(size_t, tail_len)
		__field(unsigned int, page_len)
		__field(unsigned int, len)
		__string(progname,
			 xdr->rqst->rq_task->tk_client->cl_program->name)
		__string(procedure,
			 xdr->rqst->rq_task->tk_msg.rpc_proc->p_name)
	),

	TP_fast_assign(
		if (xdr->rqst) {
			const struct rpc_task *task = xdr->rqst->rq_task;

			__entry->task_id = task->tk_pid;
			__entry->client_id = task->tk_client->cl_clid;
			__assign_str(progname,
				     task->tk_client->cl_program->name)
			__entry->version = task->tk_client->cl_vers;
			__assign_str(procedure, task->tk_msg.rpc_proc->p_name)
		} else {
			__entry->task_id = 0;
			__entry->client_id = 0;
			__assign_str(progname, "unknown")
			__entry->version = 0;
			__assign_str(procedure, "unknown")
		}
		__entry->requested = requested;
		__entry->end = xdr->end;
		__entry->p = xdr->p;
		__entry->head_base = xdr->buf->head[0].iov_base,
		__entry->head_len = xdr->buf->head[0].iov_len,
		__entry->page_len = xdr->buf->page_len,
		__entry->tail_base = xdr->buf->tail[0].iov_base,
		__entry->tail_len = xdr->buf->tail[0].iov_len,
		__entry->len = xdr->buf->len;
	),

	TP_printk(
		"task:%u@%u %sv%d %s requested=%zu p=%p end=%p xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
		__entry->task_id, __entry->client_id,
		__get_str(progname), __entry->version, __get_str(procedure),
		__entry->requested, __entry->p, __entry->end,
		__entry->head_base, __entry->head_len,
		__entry->page_len,
		__entry->tail_base, __entry->tail_len,
		__entry->len
	)
);

405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463
TRACE_EVENT(rpc_xdr_alignment,
	TP_PROTO(
		const struct xdr_stream *xdr,
		size_t offset,
		unsigned int copied
	),

	TP_ARGS(xdr, offset, copied),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
		__field(int, version)
		__field(size_t, offset)
		__field(unsigned int, copied)
		__field(const void *, head_base)
		__field(size_t, head_len)
		__field(const void *, tail_base)
		__field(size_t, tail_len)
		__field(unsigned int, page_len)
		__field(unsigned int, len)
		__string(progname,
			 xdr->rqst->rq_task->tk_client->cl_program->name)
		__string(procedure,
			 xdr->rqst->rq_task->tk_msg.rpc_proc->p_name)
	),

	TP_fast_assign(
		const struct rpc_task *task = xdr->rqst->rq_task;

		__entry->task_id = task->tk_pid;
		__entry->client_id = task->tk_client->cl_clid;
		__assign_str(progname,
			     task->tk_client->cl_program->name)
		__entry->version = task->tk_client->cl_vers;
		__assign_str(procedure, task->tk_msg.rpc_proc->p_name)

		__entry->offset = offset;
		__entry->copied = copied;
		__entry->head_base = xdr->buf->head[0].iov_base,
		__entry->head_len = xdr->buf->head[0].iov_len,
		__entry->page_len = xdr->buf->page_len,
		__entry->tail_base = xdr->buf->tail[0].iov_base,
		__entry->tail_len = xdr->buf->tail[0].iov_len,
		__entry->len = xdr->buf->len;
	),

	TP_printk(
		"task:%u@%u %sv%d %s offset=%zu copied=%u xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
		__entry->task_id, __entry->client_id,
		__get_str(progname), __entry->version, __get_str(procedure),
		__entry->offset, __entry->copied,
		__entry->head_base, __entry->head_len,
		__entry->page_len,
		__entry->tail_base, __entry->tail_len,
		__entry->len
	)
);

464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479
/*
 * First define the enums in the below macros to be exported to userspace
 * via TRACE_DEFINE_ENUM().
 */
#undef EM
#undef EMe
#define EM(a, b)	TRACE_DEFINE_ENUM(a);
#define EMe(a, b)	TRACE_DEFINE_ENUM(a);

#define RPC_SHOW_SOCKET				\
	EM( SS_FREE, "FREE" )			\
	EM( SS_UNCONNECTED, "UNCONNECTED" )	\
	EM( SS_CONNECTING, "CONNECTING," )	\
	EM( SS_CONNECTED, "CONNECTED," )	\
	EMe(SS_DISCONNECTING, "DISCONNECTING" )

480
#define rpc_show_socket_state(state) \
481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496
	__print_symbolic(state, RPC_SHOW_SOCKET)

RPC_SHOW_SOCKET

#define RPC_SHOW_SOCK				\
	EM( TCP_ESTABLISHED, "ESTABLISHED" )	\
	EM( TCP_SYN_SENT, "SYN_SENT" )		\
	EM( TCP_SYN_RECV, "SYN_RECV" )		\
	EM( TCP_FIN_WAIT1, "FIN_WAIT1" )	\
	EM( TCP_FIN_WAIT2, "FIN_WAIT2" )	\
	EM( TCP_TIME_WAIT, "TIME_WAIT" )	\
	EM( TCP_CLOSE, "CLOSE" )		\
	EM( TCP_CLOSE_WAIT, "CLOSE_WAIT" )	\
	EM( TCP_LAST_ACK, "LAST_ACK" )		\
	EM( TCP_LISTEN, "LISTEN" )		\
	EMe( TCP_CLOSING, "CLOSING" )
497 498

#define rpc_show_sock_state(state) \
499 500 501 502 503 504 505 506 507 508 509 510
	__print_symbolic(state, RPC_SHOW_SOCK)

RPC_SHOW_SOCK

/*
 * Now redefine the EM() and EMe() macros to map the enums to the strings
 * that will be printed in the output.
 */
#undef EM
#undef EMe
#define EM(a, b)	{a, b},
#define EMe(a, b)	{a, b}
511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614

DECLARE_EVENT_CLASS(xs_socket_event,

		TP_PROTO(
			struct rpc_xprt *xprt,
			struct socket *socket
		),

		TP_ARGS(xprt, socket),

		TP_STRUCT__entry(
			__field(unsigned int, socket_state)
			__field(unsigned int, sock_state)
			__field(unsigned long long, ino)
			__string(dstaddr,
				xprt->address_strings[RPC_DISPLAY_ADDR])
			__string(dstport,
				xprt->address_strings[RPC_DISPLAY_PORT])
		),

		TP_fast_assign(
			struct inode *inode = SOCK_INODE(socket);
			__entry->socket_state = socket->state;
			__entry->sock_state = socket->sk->sk_state;
			__entry->ino = (unsigned long long)inode->i_ino;
			__assign_str(dstaddr,
				xprt->address_strings[RPC_DISPLAY_ADDR]);
			__assign_str(dstport,
				xprt->address_strings[RPC_DISPLAY_PORT]);
		),

		TP_printk(
			"socket:[%llu] dstaddr=%s/%s "
			"state=%u (%s) sk_state=%u (%s)",
			__entry->ino, __get_str(dstaddr), __get_str(dstport),
			__entry->socket_state,
			rpc_show_socket_state(__entry->socket_state),
			__entry->sock_state,
			rpc_show_sock_state(__entry->sock_state)
		)
);
#define DEFINE_RPC_SOCKET_EVENT(name) \
	DEFINE_EVENT(xs_socket_event, name, \
			TP_PROTO( \
				struct rpc_xprt *xprt, \
				struct socket *socket \
			), \
			TP_ARGS(xprt, socket))

DECLARE_EVENT_CLASS(xs_socket_event_done,

		TP_PROTO(
			struct rpc_xprt *xprt,
			struct socket *socket,
			int error
		),

		TP_ARGS(xprt, socket, error),

		TP_STRUCT__entry(
			__field(int, error)
			__field(unsigned int, socket_state)
			__field(unsigned int, sock_state)
			__field(unsigned long long, ino)
			__string(dstaddr,
				xprt->address_strings[RPC_DISPLAY_ADDR])
			__string(dstport,
				xprt->address_strings[RPC_DISPLAY_PORT])
		),

		TP_fast_assign(
			struct inode *inode = SOCK_INODE(socket);
			__entry->socket_state = socket->state;
			__entry->sock_state = socket->sk->sk_state;
			__entry->ino = (unsigned long long)inode->i_ino;
			__entry->error = error;
			__assign_str(dstaddr,
				xprt->address_strings[RPC_DISPLAY_ADDR]);
			__assign_str(dstport,
				xprt->address_strings[RPC_DISPLAY_PORT]);
		),

		TP_printk(
			"error=%d socket:[%llu] dstaddr=%s/%s "
			"state=%u (%s) sk_state=%u (%s)",
			__entry->error,
			__entry->ino, __get_str(dstaddr), __get_str(dstport),
			__entry->socket_state,
			rpc_show_socket_state(__entry->socket_state),
			__entry->sock_state,
			rpc_show_sock_state(__entry->sock_state)
		)
);
#define DEFINE_RPC_SOCKET_EVENT_DONE(name) \
	DEFINE_EVENT(xs_socket_event_done, name, \
			TP_PROTO( \
				struct rpc_xprt *xprt, \
				struct socket *socket, \
				int error \
			), \
			TP_ARGS(xprt, socket, error))

DEFINE_RPC_SOCKET_EVENT(rpc_socket_state_change);
DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_connect);
615
DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_error);
616 617 618 619
DEFINE_RPC_SOCKET_EVENT_DONE(rpc_socket_reset_connection);
DEFINE_RPC_SOCKET_EVENT(rpc_socket_close);
DEFINE_RPC_SOCKET_EVENT(rpc_socket_shutdown);

620
DECLARE_EVENT_CLASS(rpc_xprt_event,
621 622 623 624 625
	TP_PROTO(
		const struct rpc_xprt *xprt,
		__be32 xid,
		int status
	),
626 627 628 629

	TP_ARGS(xprt, xid, status),

	TP_STRUCT__entry(
630
		__field(u32, xid)
631 632 633 634 635 636
		__field(int, status)
		__string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
		__string(port, xprt->address_strings[RPC_DISPLAY_PORT])
	),

	TP_fast_assign(
637
		__entry->xid = be32_to_cpu(xid);
638 639 640 641 642
		__entry->status = status;
		__assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
		__assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
	),

643 644
	TP_printk("peer=[%s]:%s xid=0x%08x status=%d", __get_str(addr),
			__get_str(port), __entry->xid,
645 646
			__entry->status)
);
647 648 649 650 651 652 653 654
#define DEFINE_RPC_XPRT_EVENT(name) \
	DEFINE_EVENT(rpc_xprt_event, xprt_##name, \
			TP_PROTO( \
				const struct rpc_xprt *xprt, \
				__be32 xid, \
				int status \
			), \
			TP_ARGS(xprt, xid, status))
655

656 657 658
DEFINE_RPC_XPRT_EVENT(timer);
DEFINE_RPC_XPRT_EVENT(lookup_rqst);
DEFINE_RPC_XPRT_EVENT(complete_rqst);
659

660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711 712 713 714 715 716 717 718 719
TRACE_EVENT(xprt_transmit,
	TP_PROTO(
		const struct rpc_rqst *rqst,
		int status
	),

	TP_ARGS(rqst, status),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
		__field(u32, xid)
		__field(u32, seqno)
		__field(int, status)
	),

	TP_fast_assign(
		__entry->task_id = rqst->rq_task->tk_pid;
		__entry->client_id = rqst->rq_task->tk_client->cl_clid;
		__entry->xid = be32_to_cpu(rqst->rq_xid);
		__entry->seqno = rqst->rq_seqno;
		__entry->status = status;
	),

	TP_printk(
		"task:%u@%u xid=0x%08x seqno=%u status=%d",
		__entry->task_id, __entry->client_id, __entry->xid,
		__entry->seqno, __entry->status)
);

TRACE_EVENT(xprt_enq_xmit,
	TP_PROTO(
		const struct rpc_task *task,
		int stage
	),

	TP_ARGS(task, stage),

	TP_STRUCT__entry(
		__field(unsigned int, task_id)
		__field(unsigned int, client_id)
		__field(u32, xid)
		__field(u32, seqno)
		__field(int, stage)
	),

	TP_fast_assign(
		__entry->task_id = task->tk_pid;
		__entry->client_id = task->tk_client->cl_clid;
		__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
		__entry->seqno = task->tk_rqstp->rq_seqno;
		__entry->stage = stage;
	),

	TP_printk(
		"task:%u@%u xid=0x%08x seqno=%u stage=%d",
		__entry->task_id, __entry->client_id, __entry->xid,
		__entry->seqno, __entry->stage)
);

720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740
TRACE_EVENT(xprt_ping,
	TP_PROTO(const struct rpc_xprt *xprt, int status),

	TP_ARGS(xprt, status),

	TP_STRUCT__entry(
		__field(int, status)
		__string(addr, xprt->address_strings[RPC_DISPLAY_ADDR])
		__string(port, xprt->address_strings[RPC_DISPLAY_PORT])
	),

	TP_fast_assign(
		__entry->status = status;
		__assign_str(addr, xprt->address_strings[RPC_DISPLAY_ADDR]);
		__assign_str(port, xprt->address_strings[RPC_DISPLAY_PORT]);
	),

	TP_printk("peer=[%s]:%s status=%d",
			__get_str(addr), __get_str(port), __entry->status)
);

741 742
TRACE_EVENT(xs_stream_read_data,
	TP_PROTO(struct rpc_xprt *xprt, ssize_t err, size_t total),
743 744 745 746

	TP_ARGS(xprt, err, total),

	TP_STRUCT__entry(
747 748
		__field(ssize_t, err)
		__field(size_t, total)
749 750 751 752 753 754 755 756 757 758 759 760 761 762 763
		__string(addr, xprt ? xprt->address_strings[RPC_DISPLAY_ADDR] :
				"(null)")
		__string(port, xprt ? xprt->address_strings[RPC_DISPLAY_PORT] :
				"(null)")
	),

	TP_fast_assign(
		__entry->err = err;
		__entry->total = total;
		__assign_str(addr, xprt ?
			xprt->address_strings[RPC_DISPLAY_ADDR] : "(null)");
		__assign_str(port, xprt ?
			xprt->address_strings[RPC_DISPLAY_PORT] : "(null)");
	),

764
	TP_printk("peer=[%s]:%s err=%zd total=%zu", __get_str(addr),
765 766 767
			__get_str(port), __entry->err, __entry->total)
);

768
TRACE_EVENT(xs_stream_read_request,
769 770 771 772 773 774 775
	TP_PROTO(struct sock_xprt *xs),

	TP_ARGS(xs),

	TP_STRUCT__entry(
		__string(addr, xs->xprt.address_strings[RPC_DISPLAY_ADDR])
		__string(port, xs->xprt.address_strings[RPC_DISPLAY_PORT])
776
		__field(u32, xid)
777 778
		__field(unsigned long, copied)
		__field(unsigned int, reclen)
779
		__field(unsigned int, offset)
780 781 782 783 784
	),

	TP_fast_assign(
		__assign_str(addr, xs->xprt.address_strings[RPC_DISPLAY_ADDR]);
		__assign_str(port, xs->xprt.address_strings[RPC_DISPLAY_PORT]);
785 786 787 788
		__entry->xid = be32_to_cpu(xs->recv.xid);
		__entry->copied = xs->recv.copied;
		__entry->reclen = xs->recv.len;
		__entry->offset = xs->recv.offset;
789 790
	),

791
	TP_printk("peer=[%s]:%s xid=0x%08x copied=%lu reclen=%u offset=%u",
792
			__get_str(addr), __get_str(port), __entry->xid,
793 794 795
			__entry->copied, __entry->reclen, __entry->offset)
);

796 797 798 799
#define show_rqstp_flags(flags)						\
	__print_flags(flags, "|",					\
		{ (1UL << RQ_SECURE),		"RQ_SECURE"},		\
		{ (1UL << RQ_LOCAL),		"RQ_LOCAL"},		\
800
		{ (1UL << RQ_USEDEFERRAL),	"RQ_USEDEFERRAL"},	\
801
		{ (1UL << RQ_DROPME),		"RQ_DROPME"},		\
802
		{ (1UL << RQ_SPLICE_OK),	"RQ_SPLICE_OK"},	\
803 804
		{ (1UL << RQ_VICTIM),		"RQ_VICTIM"},		\
		{ (1UL << RQ_BUSY),		"RQ_BUSY"})
805

806
TRACE_EVENT(svc_recv,
C
Chuck Lever 已提交
807
	TP_PROTO(struct svc_rqst *rqst, int len),
808

C
Chuck Lever 已提交
809
	TP_ARGS(rqst, len),
810 811

	TP_STRUCT__entry(
812
		__field(u32, xid)
C
Chuck Lever 已提交
813
		__field(int, len)
814
		__field(unsigned long, flags)
815
		__string(addr, rqst->rq_xprt->xpt_remotebuf)
816 817 818
	),

	TP_fast_assign(
C
Chuck Lever 已提交
819 820
		__entry->xid = be32_to_cpu(rqst->rq_xid);
		__entry->len = len;
821
		__entry->flags = rqst->rq_flags;
822
		__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
823 824
	),

825 826
	TP_printk("addr=%s xid=0x%08x len=%d flags=%s",
			__get_str(addr), __entry->xid, __entry->len,
827
			show_rqstp_flags(__entry->flags))
828 829
);

830 831 832 833 834 835 836 837 838 839
TRACE_EVENT(svc_process,
	TP_PROTO(const struct svc_rqst *rqst, const char *name),

	TP_ARGS(rqst, name),

	TP_STRUCT__entry(
		__field(u32, xid)
		__field(u32, vers)
		__field(u32, proc)
		__string(service, name)
840 841
		__string(addr, rqst->rq_xprt ?
			 rqst->rq_xprt->xpt_remotebuf : "(null)")
842 843 844 845 846 847 848
	),

	TP_fast_assign(
		__entry->xid = be32_to_cpu(rqst->rq_xid);
		__entry->vers = rqst->rq_vers;
		__entry->proc = rqst->rq_proc;
		__assign_str(service, name);
849 850
		__assign_str(addr, rqst->rq_xprt ?
			     rqst->rq_xprt->xpt_remotebuf : "(null)");
851 852 853 854 855 856 857
	),

	TP_printk("addr=%s xid=0x%08x service=%s vers=%u proc=%u",
			__get_str(addr), __entry->xid,
			__get_str(service), __entry->vers, __entry->proc)
);

858 859
DECLARE_EVENT_CLASS(svc_rqst_event,

860 861 862
	TP_PROTO(
		const struct svc_rqst *rqst
	),
863 864 865 866

	TP_ARGS(rqst),

	TP_STRUCT__entry(
867
		__field(u32, xid)
868
		__field(unsigned long, flags)
869
		__string(addr, rqst->rq_xprt->xpt_remotebuf)
870 871 872
	),

	TP_fast_assign(
873
		__entry->xid = be32_to_cpu(rqst->rq_xid);
874
		__entry->flags = rqst->rq_flags;
875
		__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
876 877
	),

878 879 880
	TP_printk("addr=%s xid=0x%08x flags=%s",
			__get_str(addr), __entry->xid,
			show_rqstp_flags(__entry->flags))
881
);
882 883 884 885 886 887
#define DEFINE_SVC_RQST_EVENT(name) \
	DEFINE_EVENT(svc_rqst_event, svc_##name, \
			TP_PROTO( \
				const struct svc_rqst *rqst \
			), \
			TP_ARGS(rqst))
888

889 890
DEFINE_SVC_RQST_EVENT(defer);
DEFINE_SVC_RQST_EVENT(drop);
891

892 893 894 895 896 897 898
DECLARE_EVENT_CLASS(svc_rqst_status,

	TP_PROTO(struct svc_rqst *rqst, int status),

	TP_ARGS(rqst, status),

	TP_STRUCT__entry(
899
		__field(u32, xid)
900
		__field(int, status)
901
		__field(unsigned long, flags)
902
		__string(addr, rqst->rq_xprt->xpt_remotebuf)
903 904 905
	),

	TP_fast_assign(
906
		__entry->xid = be32_to_cpu(rqst->rq_xid);
907
		__entry->status = status;
908
		__entry->flags = rqst->rq_flags;
909
		__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
910 911
	),

912 913 914
	TP_printk("addr=%s xid=0x%08x status=%d flags=%s",
		  __get_str(addr), __entry->xid,
		  __entry->status, show_rqstp_flags(__entry->flags))
915 916 917 918 919 920
);

DEFINE_EVENT(svc_rqst_status, svc_send,
	TP_PROTO(struct svc_rqst *rqst, int status),
	TP_ARGS(rqst, status));

921 922 923 924 925 926 927 928 929 930 931 932 933
#define show_svc_xprt_flags(flags)					\
	__print_flags(flags, "|",					\
		{ (1UL << XPT_BUSY),		"XPT_BUSY"},		\
		{ (1UL << XPT_CONN),		"XPT_CONN"},		\
		{ (1UL << XPT_CLOSE),		"XPT_CLOSE"},		\
		{ (1UL << XPT_DATA),		"XPT_DATA"},		\
		{ (1UL << XPT_TEMP),		"XPT_TEMP"},		\
		{ (1UL << XPT_DEAD),		"XPT_DEAD"},		\
		{ (1UL << XPT_CHNGBUF),		"XPT_CHNGBUF"},		\
		{ (1UL << XPT_DEFERRED),	"XPT_DEFERRED"},	\
		{ (1UL << XPT_OLD),		"XPT_OLD"},		\
		{ (1UL << XPT_LISTENER),	"XPT_LISTENER"},	\
		{ (1UL << XPT_CACHE_AUTH),	"XPT_CACHE_AUTH"},	\
934 935 936
		{ (1UL << XPT_LOCAL),		"XPT_LOCAL"},		\
		{ (1UL << XPT_KILL_TEMP),	"XPT_KILL_TEMP"},	\
		{ (1UL << XPT_CONG_CTRL),	"XPT_CONG_CTRL"})
937 938 939 940 941 942 943 944

TRACE_EVENT(svc_xprt_do_enqueue,
	TP_PROTO(struct svc_xprt *xprt, struct svc_rqst *rqst),

	TP_ARGS(xprt, rqst),

	TP_STRUCT__entry(
		__field(struct svc_xprt *, xprt)
945 946
		__field(int, pid)
		__field(unsigned long, flags)
947
		__string(addr, xprt->xpt_remotebuf)
948 949 950 951
	),

	TP_fast_assign(
		__entry->xprt = xprt;
952
		__entry->pid = rqst? rqst->rq_task->pid : 0;
953 954
		__entry->flags = xprt->xpt_flags;
		__assign_str(addr, xprt->xpt_remotebuf);
955 956
	),

957 958 959
	TP_printk("xprt=%p addr=%s pid=%d flags=%s",
			__entry->xprt, __get_str(addr),
			__entry->pid, show_svc_xprt_flags(__entry->flags))
960 961
);

962
DECLARE_EVENT_CLASS(svc_xprt_event,
963 964 965 966 967 968 969
	TP_PROTO(struct svc_xprt *xprt),

	TP_ARGS(xprt),

	TP_STRUCT__entry(
		__field(struct svc_xprt *, xprt)
		__field(unsigned long, flags)
970
		__string(addr, xprt->xpt_remotebuf)
971 972 973
	),

	TP_fast_assign(
974
		__entry->xprt = xprt;
975
		__entry->flags = xprt->xpt_flags;
976
		__assign_str(addr, xprt->xpt_remotebuf);
977 978
	),

979 980 981
	TP_printk("xprt=%p addr=%s flags=%s",
			__entry->xprt, __get_str(addr),
			show_svc_xprt_flags(__entry->flags))
982 983
);

984 985 986 987
DEFINE_EVENT(svc_xprt_event, svc_xprt_no_write_space,
	TP_PROTO(struct svc_xprt *xprt),
	TP_ARGS(xprt));

C
Chuck Lever 已提交
988 989 990 991 992 993 994 995 996 997 998 999 1000 1001 1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012 1013
TRACE_EVENT(svc_xprt_dequeue,
	TP_PROTO(struct svc_rqst *rqst),

	TP_ARGS(rqst),

	TP_STRUCT__entry(
		__field(struct svc_xprt *, xprt)
		__field(unsigned long, flags)
		__field(unsigned long, wakeup)
		__string(addr, rqst->rq_xprt->xpt_remotebuf)
	),

	TP_fast_assign(
		__entry->xprt = rqst->rq_xprt;
		__entry->flags = rqst->rq_xprt->xpt_flags;
		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
							rqst->rq_qtime));
		__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
	),

	TP_printk("xprt=%p addr=%s flags=%s wakeup-us=%lu",
			__entry->xprt, __get_str(addr),
			show_svc_xprt_flags(__entry->flags),
			__entry->wakeup)
);

1014 1015 1016 1017 1018 1019 1020 1021 1022 1023 1024 1025 1026 1027 1028 1029 1030 1031 1032 1033 1034 1035 1036 1037
TRACE_EVENT(svc_wake_up,
	TP_PROTO(int pid),

	TP_ARGS(pid),

	TP_STRUCT__entry(
		__field(int, pid)
	),

	TP_fast_assign(
		__entry->pid = pid;
	),

	TP_printk("pid=%d", __entry->pid)
);

TRACE_EVENT(svc_handle_xprt,
	TP_PROTO(struct svc_xprt *xprt, int len),

	TP_ARGS(xprt, len),

	TP_STRUCT__entry(
		__field(struct svc_xprt *, xprt)
		__field(int, len)
1038
		__field(unsigned long, flags)
1039
		__string(addr, xprt->xpt_remotebuf)
1040 1041 1042 1043 1044
	),

	TP_fast_assign(
		__entry->xprt = xprt;
		__entry->len = len;
1045 1046
		__entry->flags = xprt->xpt_flags;
		__assign_str(addr, xprt->xpt_remotebuf);
1047 1048
	),

1049 1050
	TP_printk("xprt=%p addr=%s len=%d flags=%s",
		__entry->xprt, __get_str(addr),
1051
		__entry->len, show_svc_xprt_flags(__entry->flags))
1052
);
1053

1054 1055 1056 1057 1058 1059 1060 1061 1062 1063 1064 1065 1066 1067 1068 1069 1070 1071 1072 1073 1074
TRACE_EVENT(svc_stats_latency,
	TP_PROTO(const struct svc_rqst *rqst),

	TP_ARGS(rqst),

	TP_STRUCT__entry(
		__field(u32, xid)
		__field(unsigned long, execute)
		__string(addr, rqst->rq_xprt->xpt_remotebuf)
	),

	TP_fast_assign(
		__entry->xid = be32_to_cpu(rqst->rq_xid);
		__entry->execute = ktime_to_us(ktime_sub(ktime_get(),
							 rqst->rq_stime));
		__assign_str(addr, rqst->rq_xprt->xpt_remotebuf);
	),

	TP_printk("addr=%s xid=0x%08x execute-us=%lu",
		__get_str(addr), __entry->xid, __entry->execute)
);
1075 1076

DECLARE_EVENT_CLASS(svc_deferred_event,
1077 1078 1079
	TP_PROTO(
		const struct svc_deferred_req *dr
	),
1080 1081 1082 1083

	TP_ARGS(dr),

	TP_STRUCT__entry(
1084
		__field(u32, xid)
1085
		__string(addr, dr->xprt->xpt_remotebuf)
1086 1087 1088
	),

	TP_fast_assign(
1089 1090
		__entry->xid = be32_to_cpu(*(__be32 *)(dr->args +
						       (dr->xprt_hlen>>2)));
1091
		__assign_str(addr, dr->xprt->xpt_remotebuf);
1092 1093
	),

1094
	TP_printk("addr=%s xid=0x%08x", __get_str(addr), __entry->xid)
1095
);
1096 1097 1098 1099 1100 1101 1102 1103 1104
#define DEFINE_SVC_DEFERRED_EVENT(name) \
	DEFINE_EVENT(svc_deferred_event, svc_##name##_deferred, \
			TP_PROTO( \
				const struct svc_deferred_req *dr \
			), \
			TP_ARGS(dr))

DEFINE_SVC_DEFERRED_EVENT(drop);
DEFINE_SVC_DEFERRED_EVENT(revisit);
1105

1106 1107 1108
#endif /* _TRACE_SUNRPC_H */

#include <trace/define_trace.h>