Make sonewconn() overflow messages have per-socket rate-limits and values.

sonewconn() emits debug-level messages when a listen socket's queue
overflows. Currently, sonewconn() tracks overflows on a global basis. It
will only log one message every 60 seconds, regardless of how many sockets
experience overflows. And, when it next logs at the end of the 60 seconds,
it records a single message referencing a single PCB with the total number
of overflows across all sockets.

This commit changes to per-socket overflow tracking. The code will now
log one message every 60 seconds per socket. And, the code will provide
per-socket queue length and overflow counts. It also provides a way to
change the period between log messages using a sysctl.

Reviewed by:	jhb (previous version), bcr (manpages)
MFC after:	2 weeks
Sponsored by:	Netflix, Inc.
Differential Revision:	https://reviews.freebsd.org/D24316

lib/libc/sys/listen.2

@@ -28,7 +28,7 @@
 .\"	From: @(#)listen.2	8.2 (Berkeley) 12/11/93
 .\" $FreeBSD$
 .\"
-.Dd August 18, 2016
+.Dd April 14, 2020
 .Dt LISTEN 2
 .Os
 .Sh NAME
@@ -110,6 +110,13 @@ or less than zero is specified,
 .Fa backlog
 is silently forced to
 .Va kern.ipc.soacceptqueue .
+.Pp
+If the listen queue overflows, the kernel will emit a LOG_DEBUG syslog message.
+The
+.Xr sysctl 3
+MIB variable
+.Va kern.ipc.sooverinterval
+specifies a per-socket limit on how often the kernel will emit these messages.
 .Sh INTERACTION WITH ACCEPT FILTERS
 When accept filtering is used on a socket, a second queue will
 be used to hold sockets that have connected, but have not yet

sys/kern/uipc_socket.c

@@ -575,6 +575,11 @@ SYSCTL_INT(_regression, OID_AUTO, sonewconn_earlytest, CTLFLAG_RW,
     &regression_sonewconn_earlytest, 0, "Perform early sonewconn limit test");
 #endif
 
+static struct timeval overinterval = { 60, 0 };
+SYSCTL_TIMEVAL_SEC(_kern_ipc, OID_AUTO, sooverinterval, CTLFLAG_RW,
+    &overinterval,
+    "Delay in seconds between warnings for listen socket overflows");
+
 /*
  * When an attempt at a new connection is noted on a socket which accepts
  * connections, sonewconn is called.  If the connection is possible (subject
@@ -587,14 +592,10 @@ SYSCTL_INT(_regression, OID_AUTO, sonewconn_earlytest, CTLFLAG_RW,
 struct socket *
 sonewconn(struct socket *head, int connstatus)
 {
-	static struct timeval lastover;
-	static struct timeval overinterval = { 60, 0 };
-	static int overcount;
-
 	struct sbuf descrsb;
 	struct socket *so;
-	u_int over;
+	int len, overcount;
-	int len;
+	u_int qlen;
 	const char localprefix[] = "local:";
 	char descrbuf[SUNPATHLEN + sizeof(localprefix)];
 #if defined(INET6)
@@ -602,18 +603,31 @@ sonewconn(struct socket *head, int connstatus)
 #elif defined(INET)
 	char addrbuf[INET_ADDRSTRLEN];
 #endif
+	bool dolog, over;
 
 	SOLISTEN_LOCK(head);
 	over = (head->sol_qlen > 3 * head->sol_qlimit / 2);
-	SOLISTEN_UNLOCK(head);
 #ifdef REGRESSION
 	if (regression_sonewconn_earlytest && over) {
 #else
 	if (over) {
 #endif
-		overcount++;
+		head->sol_overcount++;
+		dolog = !!ratecheck(&head->sol_lastover, &overinterval);
 
-		if (ratecheck(&lastover, &overinterval)) {
+		/*
+		 * If we're going to log, copy the overflow count and queue
+		 * length from the listen socket before dropping the lock.
+		 * Also, reset the overflow count.
+		 */
+		if (dolog) {
+			overcount = head->sol_overcount;
+			head->sol_overcount = 0;
+			qlen = head->sol_qlen;
+		}
+		SOLISTEN_UNLOCK(head);
+
+		if (dolog) {
 			/*
 			 * Try to print something descriptive about the
 			 * socket for the error message.
@@ -686,7 +700,7 @@ sonewconn(struct socket *head, int connstatus)
 			    "%i already in queue awaiting acceptance "
 			    "(%d occurrences)\n",
 			    __func__, head->so_pcb, sbuf_data(&descrsb),
-			    head->sol_qlen, overcount);
+			    qlen, overcount);
 			sbuf_delete(&descrsb);
 
 			overcount = 0;
@@ -694,6 +708,7 @@ sonewconn(struct socket *head, int connstatus)
 
 		return (NULL);
 	}
+	SOLISTEN_UNLOCK(head);
 	VNET_ASSERT(head->so_vnet != NULL, ("%s: so %p vnet is NULL",
 	    __func__, head));
 	so = soalloc(head->so_vnet);

sys/sys/socketvar.h

@@ -172,6 +172,10 @@ struct socket {
 			short		sol_sbsnd_flags;
 			sbintime_t	sol_sbrcv_timeo;
 			sbintime_t	sol_sbsnd_timeo;
+
+			/* Information tracking listen queue overflows. */
+			struct timeval	sol_lastover;	/* (e) */
+			int		sol_overcount;	/* (e) */
 		};
 	};
 };