The rpc_socket* traces now show also the source address
and port. An example is:
kworker/u17:1-951 [005] 134218.925343: rpc_socket_close:
socket:[46913] srcaddr=192.168.100.187:793 dstaddr=192.168.100.129:2049
state=4 (DISCONNECTING) sk_state=7 (CLOSE)
kworker/u17:0-242 [006] 134360.841370: rpc_socket_connect:
error=-115 socket:[56322] srcaddr=192.168.100.187:769
dstaddr=192.168.100.129:2049 state=2 (CONNECTING) sk_state=2 (SYN_SENT)
<idle>-0 [006] 134360.841859: rpc_socket_state_change: socket:[56322]
srcaddr=192.168.100.187:769 dstaddr=192.168.100.129:2049 state=2 (CONNECTING)
sk_state=1 (ESTABLISHED)
Signed-off-by: Pierguido Lambri <[email protected]>
---
include/trace/events/sunrpc.h | 52 +++++++++++++++++++++--------------
1 file changed, 32 insertions(+), 20 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 3a99358c262b..c9a5babf3be8 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -794,6 +794,9 @@ RPC_SHOW_SOCKET
RPC_SHOW_SOCK
+
+#include <trace/events/net_probe_common.h>
+
/*
* Now redefine the EM() and EMe() macros to map the enums to the strings
* that will be printed in the output.
@@ -816,27 +819,32 @@ DECLARE_EVENT_CLASS(xs_socket_event,
__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])
+ __array(__u8, saddr, sizeof(struct sockaddr_in6))
+ __array(__u8, daddr, sizeof(struct sockaddr_in6))
),
TP_fast_assign(
struct inode *inode = SOCK_INODE(socket);
+ const struct sock *sk = socket->sk;
+ const struct inet_sock *inet = inet_sk(sk);
+
+ memset(__entry->saddr, 0, sizeof(struct sockaddr_in6));
+ memset(__entry->daddr, 0, sizeof(struct sockaddr_in6));
+
+ TP_STORE_ADDR_PORTS(__entry, inet, sk);
+
__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 "
+ "socket:[%llu] srcaddr=%pISpc dstaddr=%pISpcst "
"state=%u (%s) sk_state=%u (%s)",
- __entry->ino, __get_str(dstaddr), __get_str(dstport),
+ __entry->ino,
+ __entry->saddr,
+ __entry->daddr,
__entry->socket_state,
rpc_show_socket_state(__entry->socket_state),
__entry->sock_state,
@@ -866,29 +874,33 @@ DECLARE_EVENT_CLASS(xs_socket_event_done,
__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])
+ __array(__u8, saddr, sizeof(struct sockaddr_in6))
+ __array(__u8, daddr, sizeof(struct sockaddr_in6))
),
TP_fast_assign(
struct inode *inode = SOCK_INODE(socket);
+ const struct sock *sk = socket->sk;
+ const struct inet_sock *inet = inet_sk(sk);
+
+ memset(__entry->saddr, 0, sizeof(struct sockaddr_in6));
+ memset(__entry->daddr, 0, sizeof(struct sockaddr_in6));
+
+ TP_STORE_ADDR_PORTS(__entry, inet, sk);
+
__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 "
+ "error=%d socket:[%llu] srcaddr=%pISpc dstaddr=%pISpc "
"state=%u (%s) sk_state=%u (%s)",
__entry->error,
- __entry->ino, __get_str(dstaddr), __get_str(dstport),
+ __entry->ino,
+ __entry->saddr,
+ __entry->daddr,
__entry->socket_state,
rpc_show_socket_state(__entry->socket_state),
__entry->sock_state,
--
2.33.1
On Thu, Dec 2, 2021 at 1:13 PM Pierguido Lambri <[email protected]> wrote:
>
> The rpc_socket* traces now show also the source address
> and port. An example is:
>
> kworker/u17:1-951 [005] 134218.925343: rpc_socket_close:
> socket:[46913] srcaddr=192.168.100.187:793 dstaddr=192.168.100.129:2049
> state=4 (DISCONNECTING) sk_state=7 (CLOSE)
> kworker/u17:0-242 [006] 134360.841370: rpc_socket_connect:
> error=-115 socket:[56322] srcaddr=192.168.100.187:769
> dstaddr=192.168.100.129:2049 state=2 (CONNECTING) sk_state=2 (SYN_SENT)
> <idle>-0 [006] 134360.841859: rpc_socket_state_change: socket:[56322]
> srcaddr=192.168.100.187:769 dstaddr=192.168.100.129:2049 state=2 (CONNECTING)
> sk_state=1 (ESTABLISHED)
>
> Signed-off-by: Pierguido Lambri <[email protected]>
> ---
> include/trace/events/sunrpc.h | 52 +++++++++++++++++++++--------------
> 1 file changed, 32 insertions(+), 20 deletions(-)
>
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index 3a99358c262b..c9a5babf3be8 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -794,6 +794,9 @@ RPC_SHOW_SOCKET
>
> RPC_SHOW_SOCK
>
> +
> +#include <trace/events/net_probe_common.h>
> +
> /*
> * Now redefine the EM() and EMe() macros to map the enums to the strings
> * that will be printed in the output.
> @@ -816,27 +819,32 @@ DECLARE_EVENT_CLASS(xs_socket_event,
> __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])
> + __array(__u8, saddr, sizeof(struct sockaddr_in6))
> + __array(__u8, daddr, sizeof(struct sockaddr_in6))
> ),
>
> TP_fast_assign(
> struct inode *inode = SOCK_INODE(socket);
> + const struct sock *sk = socket->sk;
> + const struct inet_sock *inet = inet_sk(sk);
> +
> + memset(__entry->saddr, 0, sizeof(struct sockaddr_in6));
> + memset(__entry->daddr, 0, sizeof(struct sockaddr_in6));
> +
> + TP_STORE_ADDR_PORTS(__entry, inet, sk);
> +
> __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 "
> + "socket:[%llu] srcaddr=%pISpc dstaddr=%pISpcst "
Shouldn't the above scan code be the same as dstaddr below: "dstaddr=%pISpc "
> "state=%u (%s) sk_state=%u (%s)",
> - __entry->ino, __get_str(dstaddr), __get_str(dstport),
> + __entry->ino,
> + __entry->saddr,
> + __entry->daddr,
> __entry->socket_state,
> rpc_show_socket_state(__entry->socket_state),
> __entry->sock_state,
> @@ -866,29 +874,33 @@ DECLARE_EVENT_CLASS(xs_socket_event_done,
> __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])
> + __array(__u8, saddr, sizeof(struct sockaddr_in6))
> + __array(__u8, daddr, sizeof(struct sockaddr_in6))
> ),
>
> TP_fast_assign(
> struct inode *inode = SOCK_INODE(socket);
> + const struct sock *sk = socket->sk;
> + const struct inet_sock *inet = inet_sk(sk);
> +
> + memset(__entry->saddr, 0, sizeof(struct sockaddr_in6));
> + memset(__entry->daddr, 0, sizeof(struct sockaddr_in6));
> +
> + TP_STORE_ADDR_PORTS(__entry, inet, sk);
> +
> __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 "
> + "error=%d socket:[%llu] srcaddr=%pISpc dstaddr=%pISpc "
> "state=%u (%s) sk_state=%u (%s)",
> __entry->error,
> - __entry->ino, __get_str(dstaddr), __get_str(dstport),
> + __entry->ino,
> + __entry->saddr,
> + __entry->daddr,
> __entry->socket_state,
> rpc_show_socket_state(__entry->socket_state),
> __entry->sock_state,
> --
> 2.33.1
>
This patch is useful for troubleshooting reconnect issues, making it
easier to match up tcpdumps with kernel traces.
Acked-and-tested-by: Dave Wysochanski <[email protected]>
On Mon, Dec 06, 2021 at 09:54:30AM -0500, David Wysochanski wrote:
> > TP_printk(
> > - "socket:[%llu] dstaddr=%s/%s "
> > + "socket:[%llu] srcaddr=%pISpc dstaddr=%pISpcst "
>
> Shouldn't the above scan code be the same as dstaddr below: "dstaddr=%pISpc "
Yes, not sure why the extra "st", but it should be "dstaddr=%pISpc"
indeed. I can resend it with the correct format.
Thanks,
Pier