From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI, SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 85C77C4361B for ; Wed, 16 Dec 2020 16:43:27 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 4C480233EB for ; Wed, 16 Dec 2020 16:43:27 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726364AbgLPQnK (ORCPT ); Wed, 16 Dec 2020 11:43:10 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:60902 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1725939AbgLPQnJ (ORCPT ); Wed, 16 Dec 2020 11:43:09 -0500 Received: from mail-ej1-x636.google.com (mail-ej1-x636.google.com [IPv6:2a00:1450:4864:20::636]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 6743CC061794 for ; Wed, 16 Dec 2020 08:42:29 -0800 (PST) Received: by mail-ej1-x636.google.com with SMTP id x16so33677653ejj.7 for ; Wed, 16 Dec 2020 08:42:29 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=cloud.ionos.com; s=google; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc:content-transfer-encoding; bh=+5h6kSWDeYqJvOetnrGGhPnTuRYQnnjgBuQrUdwAxJU=; b=KvX7Zui1BiYATc90ISSe949091SM6NHLWsfKtU/OIRxxLQYQblTB3VvVOn2rHbFe+n KUheXYbCXxjJwsCUf3Du5sn0aXjgL1qce2RIJkVPmtn2XtU6QDs+SCG7MtvcbJ3qHKOw f7eokQAtQToqtJ1Q4ZsSKhhhbJ6cnPVRXAEoFWlAQjOuZ005mMtl9ySXY3EXCaiJ/Iko NRg2aO/BYbYlvZqI1F1aV/fmifO9/IDr0aooZcbDK8HcArfTV7svvriCgYYh7RJocU3U J9aSAUZHMGDvxEht3rwNUStB+8twEWD9G0jo2M+0lP0L2mxuWTi0QNSicXNiZ5qKGE2s tN7A== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc:content-transfer-encoding; bh=+5h6kSWDeYqJvOetnrGGhPnTuRYQnnjgBuQrUdwAxJU=; b=HER0uKyBPZpCfbCfmLVqah1yBz5yosVPZVMQtOikUPgBy2RRuNl0J5vtjhcFDNsBZb 7BPkP0MmQsPcppl5EZHPLpwCXMYr1rvDQ09equsloWVBXZebxkbjgc7z1HMurjAUEFFy ZEAsMwwq11nPh6yUk++IAlCbOQWsyVa6Zg1P87surNVolcs4f2dEYVAfD6uDfyvgeo8m en5lIS6MiLNP0KvwtxcNd5I/NPc7yZTFqCELgeBTeecmBqLYb06heHqb4vh0GGnEKZc2 LNXLfkty97uce1FlrrQw0tHPIB1HoY1DJWJbk4gN/VncOa5R+boQyZMrZo2PCl8lO3pL DzEQ== X-Gm-Message-State: AOAM530JIL7crTvpIm6aRxHfSQnCCWTK5UB9hO2x3nExTN/HT9Nm8vu1 VfYjr6PCcvCa4XFLwGDMjEhuY6TzEV7zdoQo3ax1dg== X-Google-Smtp-Source: ABdhPJx/rpoCy8cb52SjwykEe5v280LaDX9NcjMkmohXL2sd+6HmE86n4PnTtF8HUgLDa99Z2mlQqL+VbNBra+BIGbU= X-Received: by 2002:a17:906:94ca:: with SMTP id d10mr30193377ejy.62.1608136948004; Wed, 16 Dec 2020 08:42:28 -0800 (PST) MIME-Version: 1.0 References: <20201209164542.61387-1-jinpu.wang@cloud.ionos.com> <20201209164542.61387-3-jinpu.wang@cloud.ionos.com> <20201211072600.GA192848@unreal> <20201211134543.GB5487@ziepe.ca> <20201211162900.GC5487@ziepe.ca> In-Reply-To: <20201211162900.GC5487@ziepe.ca> From: Jinpu Wang Date: Wed, 16 Dec 2020 17:42:17 +0100 Message-ID: Subject: Re: [PATCH for-next 02/18] RMDA/rtrs-srv: Occasionally flush ongoing session closing To: Jason Gunthorpe Cc: Jack Wang , Bart Van Assche , Danil Kipnis , Doug Ledford , Guoqing Jiang , Leon Romanovsky , linux-rdma@vger.kernel.org Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Precedence: bulk List-ID: X-Mailing-List: linux-rdma@vger.kernel.org On Fri, Dec 11, 2020 at 5:29 PM Jason Gunthorpe wrote: > > On Fri, Dec 11, 2020 at 05:17:36PM +0100, Jack Wang wrote: > > En, the lockdep was complaining about the new conn_id, I will > > post the full log if needed next week. let=E2=80=99s skip this patc= h for > > now, will double check! > > That is even more worrysome as the new conn_id already has a different > lock class. > > Jason This is the dmesg of the LOCKDEP warning, it's on kernel 5.4.77, but the latest 5.10 behaves the same. [ 500.071552] =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D [ 500.071648] WARNING: possible circular locking dependency detected [ 500.071869] 5.4.77-storage+ #35 Tainted: G O [ 500.071959] ------------------------------------------------------ [ 500.072054] kworker/1:1/28 is trying to acquire lock: [ 500.072200] ffff99653a624390 (&id_priv->handler_mutex){+.+.}, at: rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.072837] but task is already holding lock: [ 500.072938] ffff9d18800f7e80 ((work_completion)(&sess->close_work)){+.+.}, at: process_one_work+0x223/0x600 [ 500.075642] which lock already depends on the new lock. [ 500.075759] the existing dependency chain (in reverse order) is: [ 500.075880] -> #3 ((work_completion)(&sess->close_work)){+.+.}: [ 500.076062] process_one_work+0x278/0x600 [ 500.076154] worker_thread+0x2d/0x3d0 [ 500.076225] kthread+0x111/0x130 [ 500.076290] ret_from_fork+0x24/0x30 [ 500.076370] -> #2 ((wq_completion)rtrs_server_wq){+.+.}: [ 500.076482] flush_workqueue+0xab/0x4b0 [ 500.076565] rtrs_srv_rdma_cm_handler+0x71d/0x1500 [rtrs_server] [ 500.076674] cma_ib_req_handler+0x8c4/0x14f0 [rdma_cm] [ 500.076770] cm_process_work+0x22/0x140 [ib_cm] [ 500.076857] cm_req_handler+0x900/0xde0 [ib_cm] [ 500.076944] cm_work_handler+0x136/0x1af2 [ib_cm] [ 500.077025] process_one_work+0x29f/0x600 [ 500.077097] worker_thread+0x2d/0x3d0 [ 500.077164] kthread+0x111/0x130 [ 500.077224] ret_from_fork+0x24/0x30 [ 500.077294] -> #1 (&id_priv->handler_mutex/1){+.+.}: [ 500.077409] __mutex_lock+0x7e/0x950 [ 500.077488] cma_ib_req_handler+0x787/0x14f0 [rdma_cm] [ 500.077582] cm_process_work+0x22/0x140 [ib_cm] [ 500.077669] cm_req_handler+0x900/0xde0 [ib_cm] [ 500.077755] cm_work_handler+0x136/0x1af2 [ib_cm] [ 500.077835] process_one_work+0x29f/0x600 [ 500.077907] worker_thread+0x2d/0x3d0 [ 500.077973] kthread+0x111/0x130 [ 500.078034] ret_from_fork+0x24/0x30 [ 500.078095] -> #0 (&id_priv->handler_mutex){+.+.}: [ 500.078196] __lock_acquire+0x1166/0x1440 [ 500.078267] lock_acquire+0x90/0x170 [ 500.078335] __mutex_lock+0x7e/0x950 [ 500.078410] rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.078498] rtrs_srv_close_work+0xf2/0x2d0 [rtrs_server] [ 500.078586] process_one_work+0x29f/0x600 [ 500.078662] worker_thread+0x2d/0x3d0 [ 500.078732] kthread+0x111/0x130 [ 500.078793] ret_from_fork+0x24/0x30 [ 500.078859] other info that might help us debug this: [ 500.078984] Chain exists of: &id_priv->handler_mutex --> (wq_completion)rtrs_server_wq --> (work_completion)(&sess->close_work) [ 500.079207] Possible unsafe locking scenario: [ 500.079293] CPU0 CPU1 [ 500.079358] ---- ---- [ 500.079358] lock((work_completion)(&sess->close_work)); [ 500.079358] lock((wq_completion)rtrs_server_wq); [ 500.079358] lock((work_completion)(&sess->close_work)); [ 500.079358] lock(&id_priv->handler_mutex); [ 500.079358] *** DEADLOCK *** [ 500.079358] 2 locks held by kworker/1:1/28: [ 500.079358] #0: ffff99652d281f28 ((wq_completion)rtrs_server_wq){+.+.}, at: process_one_work+0x223/0x600 [ 500.079358] #1: ffff9d18800f7e80 ((work_completion)(&sess->close_work)){+.+.}, at: process_one_work+0x223/0x600 [ 500.079358] stack backtrace: [ 500.079358] CPU: 1 PID: 28 Comm: kworker/1:1 Tainted: G O 5.4.77-storage+ #35 [ 500.079358] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu1 04/01/2014 [ 500.079358] Workqueue: rtrs_server_wq rtrs_srv_close_work [rtrs_server] [ 500.079358] Call Trace: [ 500.079358] dump_stack+0x71/0x9b [ 500.079358] check_noncircular+0x17d/0x1a0 [ 500.079358] ? __lock_acquire+0x1166/0x1440 [ 500.079358] __lock_acquire+0x1166/0x1440 [ 500.079358] lock_acquire+0x90/0x170 [ 500.079358] ? rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.079358] ? rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.079358] __mutex_lock+0x7e/0x950 [ 500.079358] ? rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.079358] ? find_held_lock+0x2d/0x90 [ 500.079358] ? mark_held_locks+0x49/0x70 [ 500.079358] ? rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.079358] rdma_destroy_id+0x55/0x230 [rdma_cm] [ 500.079358] rtrs_srv_close_work+0xf2/0x2d0 [rtrs_server] [ 500.079358] process_one_work+0x29f/0x600 [ 500.079358] worker_thread+0x2d/0x3d0 [ 500.079358] ? process_one_work+0x600/0x600 [ 500.079358] kthread+0x111/0x130 [ 500.079358] ? kthread_park+0x90/0x90 [ 500.079358] ret_from_fork+0x24/0x30 According to my understanding in cma_ib_req_handler, the conn_id is newly created in https://elixir.bootlin.com/linux/latest/source/drivers/infiniband/core/cma.= c#L2222. And the rdma_cm_id associated with conn_id is passed to rtrs_srv_rdma_cm_handler->rtrs_rdma_connect. In rtrs_rdma_connect, we do flush_workqueue will only flush close_work for any other cm_id, but not the newly created one conn_id, it has not associated with anything yet. The same applies to nvme-rdma. so it's a false alarm by lockdep. Regards!