Received-SPF: pass (google.com: domain of linux-kernel+bounces-95991-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:45d1:ec00::1 as permitted sender) client-ip=2604:1380:45d1:ec00::1;
Message-ID: <afab7f4d-d8cd-4582-b46c-d4fa7673f429@oracle.com>
Date: Thu, 7 Mar 2024 10:00:49 -0800
User-Agent: Mozilla Thunderbird
Subject: Re: [PATCH RFC] RDMA/cm: add timeout to cm_destroy_id wait
Content-Language: en-US
To: Leon Romanovsky <leon@kernel.org>
Cc: dledford@redhat.com, jgg@ziepe.ca, linux-rdma@vger.kernel.org,
        linux-kernel@vger.kernel.org, rama.nichanamatlu@oracle.com
References: <20240227200017.308719-1-manjunath.b.patil@oracle.com>
 <20240303095810.GA112581@unreal>
 <8265fa8e-3de1-444e-8f58-ec60c79d6a9c@oracle.com>
 <20240307094607.GB8392@unreal>
From: Manjunath Patil <manjunath.b.patil@oracle.com>
In-Reply-To: <20240307094607.GB8392@unreal>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: bulk
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: 
	=?utf-8?B?bU04ZGR1dkpTZFFiVkdpSkJnVWx1NlRTSkg0WGRaT1U5MGRhRFJNQUkyOE1J?=
 =?utf-8?B?QzNwYlh5cG0wd2ZZNWZudW92dUxuZGt1TXpZVnk1L2hhT1lEdHE2Sm5pNHVP?=
 =?utf-8?B?RUpYL3RvOFJOSjMwSElKTmFiRGVkTGF3WWNpRVlqK01xdDI2NS9TVFM0VThp?=
 =?utf-8?B?cjZtNHBuZE5ZcmZsTW01QTZPb3hER09WOHpFWUszbEpzbDR1cEJycEJaeEhT?=
 =?utf-8?B?OXRxajVDQ213d3VSaUNFUmVYZVM3S1F5U0pkcldlVzZuY1NMQngwRTZpeG05?=
 =?utf-8?B?cHN3SGJkTHZlbktkK1o4Rno5Z1I1dDc1c0g3eDhySXh5bi9ZTzNLdjZoVFo3?=
 =?utf-8?B?MThUMDBDWm5abnM0c1ZCcWVhcGJEMis2V3Y4c1Y0M2FkVGFzblFSRmdvdzBL?=
 =?utf-8?B?dU1QQlVVbHRHekhZbW1uek1udnFvTFg0TU9kcGZqbjFZb0crQ2VNcFJYbk04?=
 =?utf-8?B?UmdGSGVOREpPdFhGTzFPRzl5MVl4dWczQUlrNGFYSDhYY25NMkhaK0ZyUk9S?=
 =?utf-8?B?TUt1aytDcUpPZmJFc3RpM3FBclphMEEzSWhoT080dlMxV2NqTjVBcFhOQmRY?=
 =?utf-8?B?K042b0tjSENkTjNQTGZieGlqNTJhSFRaOGFWNG1ZZmJFeG5kM2VYU1E0Wnhi?=
 =?utf-8?B?NFIzcDJHcUdleVZaekg4RkN5Q0xlWGpmc0hURVBxYzdnYzUrTTFiOTkvYWMr?=
 =?utf-8?B?WjFJb2RoSlZWTWVFVXRGd1ZCQ3hBUmFKMVArRVpaa28rd3JMSEpaK2g2TEtK?=
 =?utf-8?B?RVlqMEVxenh2VHFYSDVRQUREYU0ra3hGUG9TUWpnUW9lbk5UZFNwME53N3F4?=
 =?utf-8?B?SnFHQmJ4Z1p3UlRSWVZ6U3N4QzJYSTczOWVpS09jVVV6SGRsc0Jmb0hmUjNE?=
 =?utf-8?B?SjkwMWx4aFJzNDM5VWk0TjBSZkU0Yjg1K2E3MWRjNzJtbGhOK0pvRFppY3l6?=
 =?utf-8?B?VU02QmtnWWduN1lHSWc2eXFoYUk1SUF0UGltSE9QWDlha2ZCb3NxajZORDFq?=
 =?utf-8?B?czhRU0RsdXEveVdpejhVSXJ4MXBoSnpBN2ZDRlp3d0pvMnB6LzZPTE5GVEZ6?=
 =?utf-8?B?M253Uk13cy9pNVNRWjQydFJjNkhvNDVCSDRTTjFGRlZ0RU8yK3oxTnZ5VGlt?=
 =?utf-8?B?OEdadHJWd21lOVNWL0VsTHcvYWorNXZiY2dlZzg5Vkp3VThvbkRhWDVrYVVL?=
 =?utf-8?B?cU5WK0czTXN6RG1YcUJkdXdEM1lJU3FRT1ZBYmNVdFB6QXQ4bkZkYnVuZjlG?=
 =?utf-8?B?dkR3blZZSE14ZjdPL3UwYk5nTlVKYlJMWHozOU5ZL1hSb1ExQ2s1aW5pRWZi?=
 =?utf-8?B?RXJNNnppWHB2NlhJWG8rRkRjSHZZR0lrL2ZCSDhQUDVjd2xrVjBZbWc5WjFk?=
 =?utf-8?B?UUUwZEZ4SW9oYjZXVWVpaTd5NmxHeWgzUlpVL3ptR0V3MkhBeTcyR21DL1Za?=
 =?utf-8?B?Wkw1cUJJeUZXMytWcllIUGlzK0lSVGlKRmh0K3RSd2hHK1V0akFlU3VxUVlE?=
 =?utf-8?B?TFBRMDlQL0Z0UFBJdWRvQWFJbzdKMitIU1gvL0ZqeDRVZERDcWdoMVQrNTVo?=
 =?utf-8?B?WFBNOEgweFFzV2laWHRhNXJpTSt2Q0YzU2FZTGhaV1RQTE4wRlg1dkZ1ZmJY?=
 =?utf-8?B?M0tKZmlXcVZaUXpFNWkxaW9qZCs5NmlTbUs4cmZBYlYrcjRvdWhJWHVUMXRw?=
 =?utf-8?B?bnMzY1hRNGtYS2tRQjlUWi9zTllYcFN0dDBod1JzeUFTSVQzRE5yY1lhdnk0?=
 =?utf-8?B?UkpWRnp2aTJkTzJ6UXpvczRRL1BEN3hwTkRud0ZHTFRoK3plK0FqNU85Y1pI?=
 =?utf-8?B?Mk9ob29aYlh5VEdMbGpZMEltV2IxZngrK2FBZEpEN1lRWEZ1a0hpZ0c4MVFC?=
 =?utf-8?B?VUFUdTdJTXloWXB5MjBMb0dTYXN3a2tBa2YrbUYwblZmQXRKNXd1UUV1eXFq?=
 =?utf-8?B?OTFQcVFUS0EwQkI2TXVEcWtvQWMwQ0k4K0JnL1FUZ2FEdjUvc1FqOTY4OS8r?=
 =?utf-8?B?YnNUTkEwZFpEdnBEL092bmdHUlVMNjBtWG5odkJqSU5kSndYbGpRSUNaYk1h?=
 =?utf-8?B?VDdDUkFTZDUvM1lKZGpMT3BwbkluQUErV0xDc29yZGRZeE9xOXlwNEd2THlI?=
 =?utf-8?B?ZGpJMW1PUGNUSkdvZW1zYk1UdUN2SXBxOGppSDVrbmU3amMrY252bW5BQVZv?=
 =?utf-8?B?WGc9PQ==?=
X-MS-Exchange-AntiSpam-ExternalHop-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-ExternalHop-MessageData-0: 
	CnABKhD4hrxZDN4lyhbkQYzyq1TE+Gj4S3O66lPZorgFHi/VogBUJdWjNLvsO//I7ycaNmaIXuygzvV8q/sbXDfUCVTUf5MeAH2hmspiXJ73rVJ6fz19GqTWvgtgnyPzo4PYPO6UuH/anlGKEjNHa1TbAFIJiXjHUgw8uwKdMYQDwMSEecd1tn26rwJDWENRDi2HIVBOUSnM05qKPdA31HFtj53QqfAlobF4DRaIisFoZr6p1m3RhcOOABbjO1h72TrZMV9dmi4zFO7dJXcJMII72ucJxxNzFTgH1LaOt/nsWqZ9SJeh4eXhUCrXpJjXKYyeyA4l8n7vYTXAo2Efr/EtKmn/sG5IfNG1dnnSOLerVODefiqCkeBv+NsTSGS9Zys3FBTDeznTrOlQPCCSYDi3PE1PKXmAB2xkzrcjO8mOJ8UTXYA7ZEaCTHx9bs//FOuznRhR4CI32Lh++OsbJNjTJRi61bwmj0+aM/0AGouc4OBIM7Sn/P2b9D7PfepZdue8owaDI8aGePoNuymCHGrgOmvHMhMM2waAyKH27pLDWc7/xnNC3Cplrjief85K5WkowgePxOFs6wUNGJXDR1czhHwNQNZdTLM0i3aSMfU=
X-OriginatorOrg: oracle.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 3ba24bc0-f62f-470f-0a6b-08dc3ed08771
X-MS-Exchange-CrossTenant-AuthSource: CY5PR10MB6216.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 07 Mar 2024 18:00:52.8129
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: ymaqP09IlOkQ3TfI6iSm2bsNk5Mqx8/BnbVkUCV8X0okH+C5P6GgJPBKffoHQvud/pkNBJLEI2U3wiGxyPsf2Mdi7GyQmx+nn93TuY8tMlg=
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BN0PR10MB4952
X-Proofpoint-Virus-Version: vendor=baseguard
 engine=ICAP:2.0.272,Aquarius:18.0.1011,Hydra:6.0.619,FMLib:17.11.176.26
 definitions=2024-03-07_14,2024-03-06_01,2023-05-22_02
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 mlxlogscore=999 bulkscore=0 mlxscore=0
 spamscore=0 phishscore=0 suspectscore=0 malwarescore=0 adultscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2311290000
 definitions=main-2403070124
X-Proofpoint-ORIG-GUID: 2sNgVSw1oPbehungf6Q7057XSk_W4074
X-Proofpoint-GUID: 2sNgVSw1oPbehungf6Q7057XSk_W4074


On 3/7/24 1:46 AM, Leon Romanovsky wrote:
> On Tue, Mar 05, 2024 at 02:59:11PM -0800, Manjunath Patil wrote:
>>
>>
>> On 3/3/24 1:58 AM, Leon Romanovsky wrote:
>>> On Tue, Feb 27, 2024 at 12:00:17PM -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.
>>>
>>> Why doesn't rdmatool resource cm_id dump help to see stalled cm_ids?
>> Wouldn't this require us to know cm_id before hand?
>>
>> I am unfamiliar with rdmatool. Can you explain how I use it to detect a stalled connection?
> 
> Please see it if it can help:
> https://urldefense.com/v3/__https://www.man7.org/linux/man-pages/man8/rdma-resource.8.html__;!!ACWV5N9M2RV99hQ!K0TW8CNb7aCJsJbLV7Uhy9K_rOdMuHsHoUki2GIaxxQt0hd31pUCi9FeGMx2hTNI0j48ju1D6KiIrDNJ254$
> rdma resource show cm_id ...
> 
Thank you for the reference. I will go through it.
>> I wouldn't know cm_id before hand to track it to see if that is stalled.
>>
>> My intention is to have a script monitor for stalled connections[Ex: one of my connections was stuck in destroying it's cm_id] and trigger things like firmware dumps, enable more logging in related modules, crash node if this takes longer than few minutes etc.
>>
>> The current logic is to, have this timeout trigger a function(which is traceable with ebpf/dtrace) in error path, if more than expected time is spent is destroying the cm_id.
> 
> I'm not against the idea to warn about stalled destroy_id, I'm against
> adding new knob to control this timeout.
> 
Thank you for sharing this. Adding sysctl isn't critical for me. I am happy to get rid of it.
I will send a v2 with control knob removed.

-Thanks,
Manjunath
> Thanks
> 
>>
>> -Thank you,
>> Manjunath
>>>
>>> Thanks
>>>
>>>>
>>>> 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
>>>>
>>>> Signed-off-by: Manjunath Patil <manjunath.b.patil@oracle.com>
>>>> ---
>>>>    drivers/infiniband/core/cm.c | 38 +++++++++++++++++++++++++++++++++++-
>>>>    1 file changed, 37 insertions(+), 1 deletion(-)
>>>>
>>>> diff --git a/drivers/infiniband/core/cm.c b/drivers/infiniband/core/cm.c
>>>> index ff58058aeadc..03f7b80efa77 100644
>>>> --- a/drivers/infiniband/core/cm.c
>>>> +++ b/drivers/infiniband/core/cm.c
>>>> @@ -34,6 +34,20 @@ MODULE_AUTHOR("Sean Hefty");
>>>>    MODULE_DESCRIPTION("InfiniBand CM");
>>>>    MODULE_LICENSE("Dual BSD/GPL");
>>>> +static unsigned long cm_destroy_id_wait_timeout_sec = 10;
>>>> +
>>>> +static struct ctl_table_header *cm_ctl_table_header;
>>>> +static struct ctl_table cm_ctl_table[] = {
>>>> +	{
>>>> +		.procname	= "destroy_id_wait_timeout_sec",
>>>> +		.data		= &cm_destroy_id_wait_timeout_sec,
>>>> +		.maxlen		= sizeof(cm_destroy_id_wait_timeout_sec),
>>>> +		.mode		= 0644,
>>>> +		.proc_handler	= proc_doulongvec_minmax,
>>>> +	},
>>>> +	{ }
>>>> +};
>>>> +
>>>>    static const char * const ibcm_rej_reason_strs[] = {
>>>>    	[IB_CM_REJ_NO_QP]			= "no QP",
>>>>    	[IB_CM_REJ_NO_EEC]			= "no EEC",
>>>> @@ -1025,10 +1039,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 +1159,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);
>>>> @@ -4505,6 +4536,10 @@ static int __init ib_cm_init(void)
>>>>    	ret = ib_register_client(&cm_client);
>>>>    	if (ret)
>>>>    		goto error3;
>>>> +	cm_ctl_table_header = register_net_sysctl(&init_net,
>>>> +						  "net/ib_cm", cm_ctl_table);
>>>> +	if (!cm_ctl_table_header)
>>>> +		pr_warn("ib_cm: couldn't register sysctl path, using default values\n");
>>>>    	return 0;
>>>>    error3:
>>>> @@ -4522,6 +4557,7 @@ static void __exit ib_cm_cleanup(void)
>>>>    		cancel_delayed_work(&timewait_info->work.work);
>>>>    	spin_unlock_irq(&cm.lock);
>>>> +	unregister_net_sysctl_table(cm_ctl_table_header);
>>>>    	ib_unregister_client(&cm_client);
>>>>    	destroy_workqueue(cm.wq);
>>>> -- 
>>>> 2.31.1
>>>>
>>>>