[PATCH 0/4] Socket creation observability

[PATCH 0/4] Socket creation observability

[Chuck Lever]

This series updates observability around socket creation and
destruction to help troubleshoot issues such as:

https://lore.kernel.org/linux-nfs/65AFD2EF-E5D3-4461-B23A-D294486D5F65@oracle.com/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

[PATCH 1/4] SUNRPC: Fix an incorrect comment

[Chuck Lever]

From: Chuck Lever <chuck.lever@oracle.com>

The correct function name is svc_tcp_listen_data_ready().

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svcsock.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index 9aca6e1e78e4..e0fb65e90af2 100644
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -1469,7 +1469,7 @@ static struct svc_sock *svc_setup_socket(struct svc_serv *serv,
 	svsk->sk_owspace = inet->sk_write_space;
 	/*
 	 * This barrier is necessary in order to prevent race condition
-	 * with svc_data_ready(), svc_listen_data_ready() and others
+	 * with svc_data_ready(), svc_tcp_listen_data_ready(), and others
 	 * when calling callbacks above.
 	 */
 	wmb();

[PATCH 2/4] SUNRPC: Remove dprintk() in svc_handle_xprt()

[Chuck Lever]

From: Chuck Lever <chuck.lever@oracle.com>

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 <chuck.lever@oracle.com>
---
 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);

[PATCH 3/4] SUNRPC: Improve observability in svc_tcp_accept()

[Chuck Lever]

From: Chuck Lever <chuck.lever@oracle.com>

The -ENOMEM arm could fire repeatedly if the system runs low on
memory, so remove it.

Don't bother to trace -EAGAIN error events, since those fire after
a listener is created (with no work done) and once again after an
accept has been handled successfully (again, with no work done).

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 net/sunrpc/svcsock.c |    9 ++-------
 1 file changed, 2 insertions(+), 7 deletions(-)

diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index e0fb65e90af2..2058641ab9f6 100644
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -885,13 +885,8 @@ static struct svc_xprt *svc_tcp_accept(struct svc_xprt *xprt)
 	clear_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
 	err = kernel_accept(sock, &newsock, O_NONBLOCK);
 	if (err < 0) {
-		if (err == -ENOMEM)
-			printk(KERN_WARNING "%s: no more sockets!\n",
-			       serv->sv_name);
-		else if (err != -EAGAIN)
-			net_warn_ratelimited("%s: accept failed (err %d)!\n",
-					     serv->sv_name, -err);
-		trace_svcsock_accept_err(xprt, serv->sv_name, err);
+		if (err != -EAGAIN)
+			trace_svcsock_accept_err(xprt, serv->sv_name, err);
 		return NULL;
 	}
 	set_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);

Re: [PATCH 3/4] SUNRPC: Improve observability in svc_tcp_accept()

[Jeff Layton]

On Mon, 2023-05-15 at 09:32 -0400, Chuck Lever wrote:
> From: Chuck Lever <chuck.lever@oracle.com>
> 
> The -ENOMEM arm could fire repeatedly if the system runs low on
> memory, so remove it.
> 
> Don't bother to trace -EAGAIN error events, since those fire after
> a listener is created (with no work done) and once again after an
> accept has been handled successfully (again, with no work done).
> 
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
>  net/sunrpc/svcsock.c |    9 ++-------
>  1 file changed, 2 insertions(+), 7 deletions(-)
> 
> diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
> index e0fb65e90af2..2058641ab9f6 100644
> --- a/net/sunrpc/svcsock.c
> +++ b/net/sunrpc/svcsock.c
> @@ -885,13 +885,8 @@ static struct svc_xprt *svc_tcp_accept(struct svc_xprt *xprt)
>  	clear_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
>  	err = kernel_accept(sock, &newsock, O_NONBLOCK);
>  	if (err < 0) {
> -		if (err == -ENOMEM)
> -			printk(KERN_WARNING "%s: no more sockets!\n",
> -			       serv->sv_name);
> -		else if (err != -EAGAIN)
> -			net_warn_ratelimited("%s: accept failed (err %d)!\n",
> -					     serv->sv_name, -err);
> -		trace_svcsock_accept_err(xprt, serv->sv_name, err);
> +		if (err != -EAGAIN)
> +			trace_svcsock_accept_err(xprt, serv->sv_name, err);

Would this be better done as a TP_CONDITION tracepoint?

>  		return NULL;
>  	}
>  	set_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
> 
> 

-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH 3/4] SUNRPC: Improve observability in svc_tcp_accept()

[Chuck Lever III]

> On May 15, 2023, at 12:54 PM, Jeff Layton <jlayton@kernel.org> wrote:
> 
> On Mon, 2023-05-15 at 09:32 -0400, Chuck Lever wrote:
>> From: Chuck Lever <chuck.lever@oracle.com>
>> 
>> The -ENOMEM arm could fire repeatedly if the system runs low on
>> memory, so remove it.
>> 
>> Don't bother to trace -EAGAIN error events, since those fire after
>> a listener is created (with no work done) and once again after an
>> accept has been handled successfully (again, with no work done).
>> 
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> net/sunrpc/svcsock.c |    9 ++-------
>> 1 file changed, 2 insertions(+), 7 deletions(-)
>> 
>> diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
>> index e0fb65e90af2..2058641ab9f6 100644
>> --- a/net/sunrpc/svcsock.c
>> +++ b/net/sunrpc/svcsock.c
>> @@ -885,13 +885,8 @@ static struct svc_xprt *svc_tcp_accept(struct svc_xprt *xprt)
>> clear_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
>> err = kernel_accept(sock, &newsock, O_NONBLOCK);
>> if (err < 0) {
>> - if (err == -ENOMEM)
>> - printk(KERN_WARNING "%s: no more sockets!\n",
>> -        serv->sv_name);
>> - else if (err != -EAGAIN)
>> - net_warn_ratelimited("%s: accept failed (err %d)!\n",
>> -      serv->sv_name, -err);
>> - trace_svcsock_accept_err(xprt, serv->sv_name, err);
>> + if (err != -EAGAIN)
>> + trace_svcsock_accept_err(xprt, serv->sv_name, err);
> 
> Would this be better done as a TP_CONDITION tracepoint?

I looked at doing that.

svcsock_accept_err is in a declared class. I would need to
split that into two trace events, one CONDITIONAL and the
other not. svc_tcp_accept() is not a hot path, so it really
isn't worth a whole lot of churn.

Let me know if there's some benefit aside from a bit of
code cleanliness that I forgot.


>> return NULL;
>> }
>> set_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
>> 
>> 
> 
> -- 
> Jeff Layton <jlayton@kernel.org>


--
Chuck Lever

[PATCH 4/4] SUNRPC: Trace struct svc_sock lifetime events

[Chuck Lever]

From: Chuck Lever <chuck.lever@oracle.com>

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 <chuck.lever@oracle.com>
---
 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);

Re: [PATCH 0/4] Socket creation observability

[Jeff Layton]

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/65AFD2EF-E5D3-4461-B23A-D294486D5F65@oracle.com/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 <jlayton@kernel.org>

Re: [PATCH 0/4] Socket creation observability

[Chuck Lever III]

> On May 15, 2023, at 12:56 PM, Jeff Layton <jlayton@kernel.org> 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/65AFD2EF-E5D3-4461-B23A-D294486D5F65@oracle.com/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 <jlayton@kernel.org>

--
Chuck Lever