When the NFS client is under extreme load the rpc_wait_queue.qlen counter
can be overflowed. Here is an instant of the backlog queue overflow in a
real world environment shown by drgn helper:
rpc_task_stats(rpc_clnt):
-------------------------
rpc_clnt: 0xffff92b65d2bae00
rpc_xprt: 0xffff9275db64f000
Queue: sending[64887] pending[524] backlog[30441] binding[0]
XMIT task: 0xffff925c6b1d8e98
WRITE: 750654
__dta_call_status_580: 65463
__dta_call_transmit_status_579: 1
call_reserveresult: 685189
nfs_client_init_is_complete: 1
COMMIT: 584
call_reserveresult: 573
__dta_call_status_580: 11
ACCESS: 1
__dta_call_status_580: 1
GETATTR: 10
__dta_call_status_580: 4
call_reserveresult: 6
751249 tasks for server 111.222.333.444
Total tasks: 751249
count_rpc_wait_queues(xprt):
----------------------------
**** rpc_xprt: 0xffff9275db64f000 num_reqs: 65511
wait_queue: xprt_binding[0] cnt: 0
wait_queue: xprt_binding[1] cnt: 0
wait_queue: xprt_binding[2] cnt: 0
wait_queue: xprt_binding[3] cnt: 0
rpc_wait_queue[xprt_binding].qlen: 0 maxpriority: 0
wait_queue: xprt_sending[0] cnt: 0
wait_queue: xprt_sending[1] cnt: 64887
wait_queue: xprt_sending[2] cnt: 0
wait_queue: xprt_sending[3] cnt: 0
rpc_wait_queue[xprt_sending].qlen: 64887 maxpriority: 3
wait_queue: xprt_pending[0] cnt: 524
wait_queue: xprt_pending[1] cnt: 0
wait_queue: xprt_pending[2] cnt: 0
wait_queue: xprt_pending[3] cnt: 0
rpc_wait_queue[xprt_pending].qlen: 524 maxpriority: 0
wait_queue: xprt_backlog[0] cnt: 0
wait_queue: xprt_backlog[1] cnt: 685801
wait_queue: xprt_backlog[2] cnt: 0
wait_queue: xprt_backlog[3] cnt: 0
rpc_wait_queue[xprt_backlog].qlen: 30441 maxpriority: 3 [task cnt mismatch]
There is no effect on operations when this overflow occurs. However
it causes confusion when trying to diagnose the performance problem.
Signed-off-by: Dai Ngo <[email protected]>
---
include/linux/sunrpc/sched.h | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
index 8ada7dc802d3..8f9bee0e21c3 100644
--- a/include/linux/sunrpc/sched.h
+++ b/include/linux/sunrpc/sched.h
@@ -186,7 +186,7 @@ struct rpc_wait_queue {
unsigned char maxpriority; /* maximum priority (0 if queue is not a priority queue) */
unsigned char priority; /* current priority */
unsigned char nr; /* # tasks remaining for cookie */
- unsigned short qlen; /* total # tasks waiting in queue */
+ unsigned int qlen; /* total # tasks waiting in queue */
struct rpc_timer timer_list;
#if IS_ENABLED(CONFIG_SUNRPC_DEBUG) || IS_ENABLED(CONFIG_TRACEPOINTS)
const char * name;
--
2.39.3
On Tue, 2024-01-30 at 11:38 -0800, Dai Ngo wrote:
> When the NFS client is under extreme load the rpc_wait_queue.qlen counter
> can be overflowed. Here is an instant of the backlog queue overflow in a
> real world environment shown by drgn helper:
>
> rpc_task_stats(rpc_clnt):
> -------------------------
> rpc_clnt: 0xffff92b65d2bae00
> rpc_xprt: 0xffff9275db64f000
> Queue: sending[64887] pending[524] backlog[30441] binding[0]
> XMIT task: 0xffff925c6b1d8e98
> WRITE: 750654
> __dta_call_status_580: 65463
> __dta_call_transmit_status_579: 1
> call_reserveresult: 685189
> nfs_client_init_is_complete: 1
> COMMIT: 584
> call_reserveresult: 573
> __dta_call_status_580: 11
> ACCESS: 1
> __dta_call_status_580: 1
> GETATTR: 10
> __dta_call_status_580: 4
> call_reserveresult: 6
> 751249 tasks for server 111.222.333.444
> Total tasks: 751249
>
> count_rpc_wait_queues(xprt):
> ----------------------------
> **** rpc_xprt: 0xffff9275db64f000 num_reqs: 65511
> wait_queue: xprt_binding[0] cnt: 0
> wait_queue: xprt_binding[1] cnt: 0
> wait_queue: xprt_binding[2] cnt: 0
> wait_queue: xprt_binding[3] cnt: 0
> rpc_wait_queue[xprt_binding].qlen: 0 maxpriority: 0
> wait_queue: xprt_sending[0] cnt: 0
> wait_queue: xprt_sending[1] cnt: 64887
> wait_queue: xprt_sending[2] cnt: 0
> wait_queue: xprt_sending[3] cnt: 0
> rpc_wait_queue[xprt_sending].qlen: 64887 maxpriority: 3
> wait_queue: xprt_pending[0] cnt: 524
> wait_queue: xprt_pending[1] cnt: 0
> wait_queue: xprt_pending[2] cnt: 0
> wait_queue: xprt_pending[3] cnt: 0
> rpc_wait_queue[xprt_pending].qlen: 524 maxpriority: 0
> wait_queue: xprt_backlog[0] cnt: 0
> wait_queue: xprt_backlog[1] cnt: 685801
> wait_queue: xprt_backlog[2] cnt: 0
> wait_queue: xprt_backlog[3] cnt: 0
> rpc_wait_queue[xprt_backlog].qlen: 30441 maxpriority: 3 [task cnt mismatch]
>
> There is no effect on operations when this overflow occurs. However
> it causes confusion when trying to diagnose the performance problem.
>
> Signed-off-by: Dai Ngo <[email protected]>
> ---
> include/linux/sunrpc/sched.h | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/include/linux/sunrpc/sched.h b/include/linux/sunrpc/sched.h
> index 8ada7dc802d3..8f9bee0e21c3 100644
> --- a/include/linux/sunrpc/sched.h
> +++ b/include/linux/sunrpc/sched.h
> @@ -186,7 +186,7 @@ struct rpc_wait_queue {
> unsigned char maxpriority; /* maximum priority (0 if queue is not a priority queue) */
> unsigned char priority; /* current priority */
> unsigned char nr; /* # tasks remaining for cookie */
> - unsigned short qlen; /* total # tasks waiting in queue */
> + unsigned int qlen; /* total # tasks waiting in queue */
> struct rpc_timer timer_list;
> #if IS_ENABLED(CONFIG_SUNRPC_DEBUG) || IS_ENABLED(CONFIG_TRACEPOINTS)
> const char * name;
Seems fine to me. In fact, on x86_64 there is a 2 byte hole after the
existing 2 byte qlen, so this probably won't even result in the
structure growing.
Reviewed-by: Jeff Layton <[email protected]>