| Message ID | 20211202181308.279592-1-plambri@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | SUNRPC: Add source address/port to rpc_socket* traces | expand |
On Thu, Dec 2, 2021 at 1:13 PM Pierguido Lambri <plambri@redhat.com> 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 <plambri@redhat.com> > --- > 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 <dwysocha@redhat.com>
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
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,
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 <plambri@redhat.com> --- include/trace/events/sunrpc.h | 52 +++++++++++++++++++++-------------- 1 file changed, 32 insertions(+), 20 deletions(-)