This series updates observability around socket creation and
destruction to help troubleshoot issues such as:
https://lore.kernel.org/linux-nfs/[email protected]/T/#t
I plan to apply these to nfsd-next.
---
Chuck Lever (4):
SUNRPC: Fix an incorrect comment
SUNRPC: Remove dprintk() in svc_handle_xprt()
SUNRPC: Improve observability in svc_tcp_accept()
SUNRPC: Trace struct svc_sock lifetime events
include/trace/events/sunrpc.h | 39 ++++++++++++++++++++++++-----------
net/sunrpc/svc_xprt.c | 3 ---
net/sunrpc/svcsock.c | 15 ++++++--------
3 files changed, 33 insertions(+), 24 deletions(-)
--
Chuck Lever
From: Chuck Lever <[email protected]>
When enabled, this dprintk() fires for every incoming RPC, which is
an enormous amount of log traffic. These days, after the first few
hundred log messages, the system journald is just going to mute it,
along with all other NFSD debug output.
Let's rely on trace points for this high-traffic information
instead.
Signed-off-by: Chuck Lever <[email protected]>
---
net/sunrpc/svc_xprt.c | 3 ---
1 file changed, 3 deletions(-)
diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
index 84e5d7d31481..b3564afc53b7 100644
--- a/net/sunrpc/svc_xprt.c
+++ b/net/sunrpc/svc_xprt.c
@@ -833,9 +833,6 @@ static int svc_handle_xprt(struct svc_rqst *rqstp, struct svc_xprt *xprt)
svc_xprt_received(xprt);
} else if (svc_xprt_reserve_slot(rqstp, xprt)) {
/* XPT_DATA|XPT_DEFERRED case: */
- dprintk("svc: server %p, pool %u, transport %p, inuse=%d\n",
- rqstp, rqstp->rq_pool->sp_id, xprt,
- kref_read(&xprt->xpt_ref));
rqstp->rq_deferred = svc_deferred_dequeue(xprt);
if (rqstp->rq_deferred)
len = svc_deferred_recv(rqstp);
From: Chuck Lever <[email protected]>
Capture a timestamp and pointer address during the creation and
destruction of struct svc_sock to record its lifetime. This helps
to diagnose transport reference counting issues.
Signed-off-by: Chuck Lever <[email protected]>
---
include/trace/events/sunrpc.h | 39 +++++++++++++++++++++++++++------------
net/sunrpc/svcsock.c | 4 +++-
2 files changed, 30 insertions(+), 13 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 31bc7025cb44..69e42ef30979 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -2104,31 +2104,46 @@ DEFINE_SVC_DEFERRED_EVENT(drop);
DEFINE_SVC_DEFERRED_EVENT(queue);
DEFINE_SVC_DEFERRED_EVENT(recv);
-TRACE_EVENT(svcsock_new_socket,
+DECLARE_EVENT_CLASS(svcsock_lifetime_class,
TP_PROTO(
+ const void *svsk,
const struct socket *socket
),
-
- TP_ARGS(socket),
-
+ TP_ARGS(svsk, socket),
TP_STRUCT__entry(
+ __field(unsigned int, netns_ino)
+ __field(const void *, svsk)
+ __field(const void *, sk)
__field(unsigned long, type)
__field(unsigned long, family)
- __field(bool, listener)
+ __field(unsigned long, state)
),
-
TP_fast_assign(
+ struct sock *sk = socket->sk;
+
+ __entry->netns_ino = sock_net(sk)->ns.inum;
+ __entry->svsk = svsk;
+ __entry->sk = sk;
__entry->type = socket->type;
- __entry->family = socket->sk->sk_family;
- __entry->listener = (socket->sk->sk_state == TCP_LISTEN);
+ __entry->family = sk->sk_family;
+ __entry->state = sk->sk_state;
),
-
- TP_printk("type=%s family=%s%s",
- show_socket_type(__entry->type),
+ TP_printk("svsk=%p type=%s family=%s%s",
+ __entry->svsk, show_socket_type(__entry->type),
rpc_show_address_family(__entry->family),
- __entry->listener ? " (listener)" : ""
+ __entry->state == TCP_LISTEN ? " (listener)" : ""
)
);
+#define DEFINE_SVCSOCK_LIFETIME_EVENT(name) \
+ DEFINE_EVENT(svcsock_lifetime_class, name, \
+ TP_PROTO( \
+ const void *svsk, \
+ const struct socket *socket \
+ ), \
+ TP_ARGS(svsk, socket))
+
+DEFINE_SVCSOCK_LIFETIME_EVENT(svcsock_new);
+DEFINE_SVCSOCK_LIFETIME_EVENT(svcsock_free);
TRACE_EVENT(svcsock_marker,
TP_PROTO(
diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index 2058641ab9f6..e30716248989 100644
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -1476,7 +1476,7 @@ static struct svc_sock *svc_setup_socket(struct svc_serv *serv,
else
svc_tcp_init(svsk, serv);
- trace_svcsock_new_socket(sock);
+ trace_svcsock_new(svsk, sock);
return svsk;
}
@@ -1669,6 +1669,8 @@ static void svc_sock_free(struct svc_xprt *xprt)
struct svc_sock *svsk = container_of(xprt, struct svc_sock, sk_xprt);
struct socket *sock = svsk->sk_sock;
+ trace_svcsock_free(svsk, sock);
+
tls_handshake_cancel(sock->sk);
if (sock->file)
sockfd_put(sock);
On Mon, 2023-05-15 at 09:32 -0400, Chuck Lever wrote:
> This series updates observability around socket creation and
> destruction to help troubleshoot issues such as:
>
> https://lore.kernel.org/linux-nfs/[email protected]/T/#t
>
> I plan to apply these to nfsd-next.
>
> ---
>
> Chuck Lever (4):
> SUNRPC: Fix an incorrect comment
> SUNRPC: Remove dprintk() in svc_handle_xprt()
> SUNRPC: Improve observability in svc_tcp_accept()
> SUNRPC: Trace struct svc_sock lifetime events
>
>
> include/trace/events/sunrpc.h | 39 ++++++++++++++++++++++++-----------
> net/sunrpc/svc_xprt.c | 3 ---
> net/sunrpc/svcsock.c | 15 ++++++--------
> 3 files changed, 33 insertions(+), 24 deletions(-)
>
> --
> Chuck Lever
>
These all look fine to me. I had one nit about a conditional tracepoint,
but your call on whether you want to respin it that way.
Reviewed-by: Jeff Layton <[email protected]>
> On May 15, 2023, at 12:56 PM, Jeff Layton <[email protected]> wrote:
>
> On Mon, 2023-05-15 at 09:32 -0400, Chuck Lever wrote:
>> This series updates observability around socket creation and
>> destruction to help troubleshoot issues such as:
>>
>> https://lore.kernel.org/linux-nfs/[email protected]/T/#t
>>
>> I plan to apply these to nfsd-next.
>>
>> ---
>>
>> Chuck Lever (4):
>> SUNRPC: Fix an incorrect comment
>> SUNRPC: Remove dprintk() in svc_handle_xprt()
>> SUNRPC: Improve observability in svc_tcp_accept()
>> SUNRPC: Trace struct svc_sock lifetime events
>>
>>
>> include/trace/events/sunrpc.h | 39 ++++++++++++++++++++++++-----------
>> net/sunrpc/svc_xprt.c | 3 ---
>> net/sunrpc/svcsock.c | 15 ++++++--------
>> 3 files changed, 33 insertions(+), 24 deletions(-)
>>
>> --
>> Chuck Lever
>>
>
> These all look fine to me. I had one nit about a conditional tracepoint,
> but your call on whether you want to respin it that way.
Great minds, and all that... I had considered it, but decided
it wasn't worth bothering. I appreciate your time and comments!
> Reviewed-by: Jeff Layton <[email protected]>
--
Chuck Lever