[PATCH] RDMA/cm: add timeout to cm_destroy_id wait

[PATCH] RDMA/cm: add timeout to cm_destroy_id wait

[Manjunath Patil]

Add timeout to cm_destroy_id, so that userspace can trigger any data
collection that would help in analyzing the cause of delay in destroying
the cm_id.

New noinline function helps dtrace/ebpf programs to hook on to it.
Existing functionality isn't changed except triggering a probe-able new
function at every timeout interval.

We have seen cases where CM messages stuck with MAD layer (either due to
software bug or faulty HCA), leading to cm_id getting stuck in the
following call stack. This patch helps in resolving such issues faster.

kernel: ... INFO: task XXXX:56778 blocked for more than 120 seconds.
...
	Call Trace:
	__schedule+0x2bc/0x895
	schedule+0x36/0x7c
	schedule_timeout+0x1f6/0x31f
 	? __slab_free+0x19c/0x2ba
	wait_for_completion+0x12b/0x18a
	? wake_up_q+0x80/0x73
	cm_destroy_id+0x345/0x610 [ib_cm]
	ib_destroy_cm_id+0x10/0x20 [ib_cm]
	rdma_destroy_id+0xa8/0x300 [rdma_cm]
	ucma_destroy_id+0x13e/0x190 [rdma_ucm]
	ucma_write+0xe0/0x160 [rdma_ucm]
	__vfs_write+0x3a/0x16d
	vfs_write+0xb2/0x1a1
	? syscall_trace_enter+0x1ce/0x2b8
	SyS_write+0x5c/0xd3
	do_syscall_64+0x79/0x1b9
	entry_SYSCALL_64_after_hwframe+0x16d/0x0

Orabug: 36280065

Signed-off-by: Manjunath Patil <manjunath.b.patil@oracle.com>
---
 drivers/infiniband/core/cm.c | 20 +++++++++++++++++++-
 1 file changed, 19 insertions(+), 1 deletion(-)

diff --git a/drivers/infiniband/core/cm.c b/drivers/infiniband/core/cm.c
index ff58058aeadc..00a16b08c7e2 100644
--- a/drivers/infiniband/core/cm.c
+++ b/drivers/infiniband/core/cm.c
@@ -34,6 +34,7 @@ MODULE_AUTHOR("Sean Hefty");
 MODULE_DESCRIPTION("InfiniBand CM");
 MODULE_LICENSE("Dual BSD/GPL");
 
+static unsigned long cm_destroy_id_wait_timeout_sec = 10;
 static const char * const ibcm_rej_reason_strs[] = {
 	[IB_CM_REJ_NO_QP]			= "no QP",
 	[IB_CM_REJ_NO_EEC]			= "no EEC",
@@ -1025,10 +1026,20 @@ static void cm_reset_to_idle(struct cm_id_private *cm_id_priv)
 	}
 }
 
+static noinline void cm_destroy_id_wait_timeout(struct ib_cm_id *cm_id)
+{
+	struct cm_id_private *cm_id_priv;
+
+	cm_id_priv = container_of(cm_id, struct cm_id_private, id);
+	pr_err("%s: cm_id=%p timed out. state=%d refcnt=%d\n", __func__,
+	       cm_id, cm_id->state, refcount_read(&cm_id_priv->refcount));
+}
+
 static void cm_destroy_id(struct ib_cm_id *cm_id, int err)
 {
 	struct cm_id_private *cm_id_priv;
 	struct cm_work *work;
+	int ret;
 
 	cm_id_priv = container_of(cm_id, struct cm_id_private, id);
 	spin_lock_irq(&cm_id_priv->lock);
@@ -1135,7 +1146,14 @@ static void cm_destroy_id(struct ib_cm_id *cm_id, int err)
 
 	xa_erase(&cm.local_id_table, cm_local_id(cm_id->local_id));
 	cm_deref_id(cm_id_priv);
-	wait_for_completion(&cm_id_priv->comp);
+	do {
+		ret = wait_for_completion_timeout(&cm_id_priv->comp,
+						  msecs_to_jiffies(
+				cm_destroy_id_wait_timeout_sec * 1000));
+		if (!ret) /* timeout happened */
+			cm_destroy_id_wait_timeout(cm_id);
+	} while (!ret);
+
 	while ((work = cm_dequeue_work(cm_id_priv)) != NULL)
 		cm_free_work(work);
 
-- 
2.31.1

Re: [PATCH] RDMA/cm: add timeout to cm_destroy_id wait

[Jason Gunthorpe]

On Thu, Mar 07, 2024 at 04:55:53PM -0800, Manjunath Patil wrote:
> Add timeout to cm_destroy_id, so that userspace can trigger any data
> collection that would help in analyzing the cause of delay in destroying
> the cm_id.
> 
> New noinline function helps dtrace/ebpf programs to hook on to it.
> Existing functionality isn't changed except triggering a probe-able new
> function at every timeout interval.
> 
> We have seen cases where CM messages stuck with MAD layer (either due to
> software bug or faulty HCA), leading to cm_id getting stuck in the
> following call stack. This patch helps in resolving such issues faster.
> 
> kernel: ... INFO: task XXXX:56778 blocked for more than 120 seconds.
> ...
> 	Call Trace:
> 	__schedule+0x2bc/0x895
> 	schedule+0x36/0x7c
> 	schedule_timeout+0x1f6/0x31f
>  	? __slab_free+0x19c/0x2ba
> 	wait_for_completion+0x12b/0x18a
> 	? wake_up_q+0x80/0x73
> 	cm_destroy_id+0x345/0x610 [ib_cm]
> 	ib_destroy_cm_id+0x10/0x20 [ib_cm]
> 	rdma_destroy_id+0xa8/0x300 [rdma_cm]
> 	ucma_destroy_id+0x13e/0x190 [rdma_ucm]
> 	ucma_write+0xe0/0x160 [rdma_ucm]
> 	__vfs_write+0x3a/0x16d
> 	vfs_write+0xb2/0x1a1
> 	? syscall_trace_enter+0x1ce/0x2b8
> 	SyS_write+0x5c/0xd3
> 	do_syscall_64+0x79/0x1b9
> 	entry_SYSCALL_64_after_hwframe+0x16d/0x0
> 
> Orabug: 36280065
> 
> Signed-off-by: Manjunath Patil <manjunath.b.patil@oracle.com>
> ---
>  drivers/infiniband/core/cm.c | 20 +++++++++++++++++++-
>  1 file changed, 19 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/infiniband/core/cm.c b/drivers/infiniband/core/cm.c
> index ff58058aeadc..00a16b08c7e2 100644
> --- a/drivers/infiniband/core/cm.c
> +++ b/drivers/infiniband/core/cm.c
> @@ -34,6 +34,7 @@ MODULE_AUTHOR("Sean Hefty");
>  MODULE_DESCRIPTION("InfiniBand CM");
>  MODULE_LICENSE("Dual BSD/GPL");
>  
> +static unsigned long cm_destroy_id_wait_timeout_sec = 10;

Don't need this to be a variable, just make it a #define

>  static const char * const ibcm_rej_reason_strs[] = {
>  	[IB_CM_REJ_NO_QP]			= "no QP",
>  	[IB_CM_REJ_NO_EEC]			= "no EEC",
> @@ -1025,10 +1026,20 @@ static void cm_reset_to_idle(struct cm_id_private *cm_id_priv)
>  	}
>  }
>  
> +static noinline void cm_destroy_id_wait_timeout(struct ib_cm_id *cm_id)
> +{
> +	struct cm_id_private *cm_id_priv;
> +
> +	cm_id_priv = container_of(cm_id, struct cm_id_private, id);
> +	pr_err("%s: cm_id=%p timed out. state=%d refcnt=%d\n", __func__,
> +	       cm_id, cm_id->state, refcount_read(&cm_id_priv->refcount));
> +}

WARN_ON? Is the backtrace valuable?

Jason

Re: [PATCH] RDMA/cm: add timeout to cm_destroy_id wait

[Manjunath Patil]

On 3/8/24 6:18 AM, Jason Gunthorpe wrote:
> On Thu, Mar 07, 2024 at 04:55:53PM -0800, Manjunath Patil wrote:
>> Add timeout to cm_destroy_id, so that userspace can trigger any data
>> collection that would help in analyzing the cause of delay in destroying
>> the cm_id.
>>
>> New noinline function helps dtrace/ebpf programs to hook on to it.
>> Existing functionality isn't changed except triggering a probe-able new
>> function at every timeout interval.
>>
>> We have seen cases where CM messages stuck with MAD layer (either due to
>> software bug or faulty HCA), leading to cm_id getting stuck in the
>> following call stack. This patch helps in resolving such issues faster.
>>
>> kernel: ... INFO: task XXXX:56778 blocked for more than 120 seconds.
>> ...
>> 	Call Trace:
>> 	__schedule+0x2bc/0x895
>> 	schedule+0x36/0x7c
>> 	schedule_timeout+0x1f6/0x31f
>>   	? __slab_free+0x19c/0x2ba
>> 	wait_for_completion+0x12b/0x18a
>> 	? wake_up_q+0x80/0x73
>> 	cm_destroy_id+0x345/0x610 [ib_cm]
>> 	ib_destroy_cm_id+0x10/0x20 [ib_cm]
>> 	rdma_destroy_id+0xa8/0x300 [rdma_cm]
>> 	ucma_destroy_id+0x13e/0x190 [rdma_ucm]
>> 	ucma_write+0xe0/0x160 [rdma_ucm]
>> 	__vfs_write+0x3a/0x16d
>> 	vfs_write+0xb2/0x1a1
>> 	? syscall_trace_enter+0x1ce/0x2b8
>> 	SyS_write+0x5c/0xd3
>> 	do_syscall_64+0x79/0x1b9
>> 	entry_SYSCALL_64_after_hwframe+0x16d/0x0
>>
>> Orabug: 36280065
>>
>> Signed-off-by: Manjunath Patil <manjunath.b.patil@oracle.com>
>> ---
>>   drivers/infiniband/core/cm.c | 20 +++++++++++++++++++-
>>   1 file changed, 19 insertions(+), 1 deletion(-)
>>
>> diff --git a/drivers/infiniband/core/cm.c b/drivers/infiniband/core/cm.c
>> index ff58058aeadc..00a16b08c7e2 100644
>> --- a/drivers/infiniband/core/cm.c
>> +++ b/drivers/infiniband/core/cm.c
>> @@ -34,6 +34,7 @@ MODULE_AUTHOR("Sean Hefty");
>>   MODULE_DESCRIPTION("InfiniBand CM");
>>   MODULE_LICENSE("Dual BSD/GPL");
>>   
>> +static unsigned long cm_destroy_id_wait_timeout_sec = 10;
> 
> Don't need this to be a variable, just make it a #define
sure. I will send v3 with this change.
> 
>>   static const char * const ibcm_rej_reason_strs[] = {
>>   	[IB_CM_REJ_NO_QP]			= "no QP",
>>   	[IB_CM_REJ_NO_EEC]			= "no EEC",
>> @@ -1025,10 +1026,20 @@ static void cm_reset_to_idle(struct cm_id_private *cm_id_priv)
>>   	}
>>   }
>>   
>> +static noinline void cm_destroy_id_wait_timeout(struct ib_cm_id *cm_id)
>> +{
>> +	struct cm_id_private *cm_id_priv;
>> +
>> +	cm_id_priv = container_of(cm_id, struct cm_id_private, id);
>> +	pr_err("%s: cm_id=%p timed out. state=%d refcnt=%d\n", __func__,
>> +	       cm_id, cm_id->state, refcount_read(&cm_id_priv->refcount));
>> +}
> 
> WARN_ON? Is the backtrace valuable?
No. I would prefer just pr_err to avoid noise if there are multiple cm_ids are stuck due to any lower layer issue.

Thank you for your feedback.

-Manjunath
> 
> Jason