On 3/7/23 02:09, Saleem, Shiraz wrote:
Subject: Re: [PATCH for-rc] IB/isert: Fix hang in iscsit_wait_for_tag
On 1/30/23 20:22, Devale, Sindhu wrote:
Subject: Re: [PATCH for-rc] IB/isert: Fix hang in iscsit_wait_for_tag
From: Mustafa Ismail <mustafa.ismail@xxxxxxxxx>
Running fio can occasionally cause a hang when sbitmap_queue_get()
fails to return a tag in iscsit_allocate_cmd() and
iscsit_wait_for_tag() is called and will never return from the
schedule(). This is because the polling thread of the CQ is
suspended, and will not poll for a SQ completion which would free up a tag.
Fix this by creating a separate CQ for the SQ so that send
completions are processed on a separate thread and are not blocked
when the RQ CQ is stalled.
Fixes: 10e9cbb6b531 ("scsi: target: Convert target drivers to use
sbitmap")
Is this the real offending commit? What prevented this from happening
before?
Maybe going to a global bitmap instead of per cpu ida makes it less likely to
occur.
Going to single CQ maybe the real root cause in this
commit:6f0fae3d7797("iser-target: Use single CQ for TX and RX")
Yes this is more likely.
Reviewed-by: Mike Marciniszyn <mike.marciniszyn@xxxxxxxxx>
Signed-off-by: Mustafa Ismail <mustafa.ismail@xxxxxxxxx>
Signed-off-by: Shiraz Saleem <shiraz.saleem@xxxxxxxxx>
---
drivers/infiniband/ulp/isert/ib_isert.c | 33
+++++++++++++++++++++++--
--------
drivers/infiniband/ulp/isert/ib_isert.h | 3 ++-
2 files changed, 25 insertions(+), 11 deletions(-)
diff --git a/drivers/infiniband/ulp/isert/ib_isert.c
b/drivers/infiniband/ulp/isert/ib_isert.c
index 7540488..f827b91 100644
--- a/drivers/infiniband/ulp/isert/ib_isert.c
+++ b/drivers/infiniband/ulp/isert/ib_isert.c
@@ -109,19 +109,27 @@ static int isert_sg_tablesize_set(const char
*val,
const struct kernel_param *kp
struct ib_qp_init_attr attr;
int ret, factor;
- isert_conn->cq = ib_cq_pool_get(ib_dev, cq_size, -1,
IB_POLL_WORKQUEUE);
- if (IS_ERR(isert_conn->cq)) {
- isert_err("Unable to allocate cq\n");
- ret = PTR_ERR(isert_conn->cq);
+ isert_conn->snd_cq = ib_cq_pool_get(ib_dev, cq_size, -1,
+ IB_POLL_WORKQUEUE);
+ if (IS_ERR(isert_conn->snd_cq)) {
+ isert_err("Unable to allocate send cq\n");
+ ret = PTR_ERR(isert_conn->snd_cq);
return ERR_PTR(ret);
}
+ isert_conn->rcv_cq = ib_cq_pool_get(ib_dev, cq_size, -1,
+ IB_POLL_WORKQUEUE);
+ if (IS_ERR(isert_conn->rcv_cq)) {
+ isert_err("Unable to allocate receive cq\n");
+ ret = PTR_ERR(isert_conn->rcv_cq);
+ goto create_cq_err;
+ }
Does this have any noticeable performance implications?
Initial testing seems to indicate this change causes significant performance
variability specifically only with 2K Writes.
We suspect that may be due an unfortunate vector placement where the
snd_cq and rcv_cq are on different numa nodes.
We can, in the patch, alter the second CQ creation to pass comp_vector to
insure they are hinted to the same affinity.
Even so, still there are now two competing threads for completion processing.
Also I wander if there are any other assumptions in the code for
having a single context processing completions...
We don't see any.
It'd be much easier if iscsi_allocate_cmd could accept a timeout to fail...
CCing target-devel and Mike.
Do you mean add a timeout to the wait or removing the call
to iscsit_wait_for_tag() iscsit_allocate_cmd()?
Looking at the code, passing it TASK_RUNNING will make it fail if there no
available tag (and hence drop the received command, let the initiator retry). But I
also think that isert may need a deeper default queue depth...
Hi Sagi -
Mustafa reports - "The problem is not easily reproduced, so I reduce the amount of map_tags allocated when I testing a potential fix. Passing TASK_RUNNING and I got the following call trace:
[ 220.131709] isert: isert_allocate_cmd: Unable to allocate iscsit_cmd + isert_cmd
[ 220.131712] isert: isert_allocate_cmd: Unable to allocate iscsit_cmd + isert_cmd
[ 280.862544] ABORT_TASK: Found referenced iSCSI task_tag: 70
[ 313.265156] iSCSI Login timeout on Network Portal 5.1.1.21:3260
[ 334.769268] INFO: task kworker/32:3:1285 blocked for more than 30 seconds.
[ 334.769272] Tainted: G OE 6.2.0-rc3 #6
[ 334.769274] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 334.769275] task:kworker/32:3 state:D stack:0 pid:1285 ppid:2 flags:0x00004000
[ 334.769279] Workqueue: events target_tmr_work [target_core_mod]
[ 334.769307] Call Trace:
[ 334.769308] <TASK>
[ 334.769310] __schedule+0x318/0xa30
[ 334.769316] ? _prb_read_valid+0x22e/0x2b0
[ 334.769319] ? __pfx_schedule_timeout+0x10/0x10
[ 334.769322] ? __wait_for_common+0xd3/0x1e0
[ 334.769323] schedule+0x57/0xd0
[ 334.769325] schedule_timeout+0x273/0x320
[ 334.769327] ? __irq_work_queue_local+0x39/0x80
[ 334.769330] ? irq_work_queue+0x3f/0x60
[ 334.769332] ? __pfx_schedule_timeout+0x10/0x10
[ 334.769333] __wait_for_common+0xf9/0x1e0
[ 334.769335] target_put_cmd_and_wait+0x59/0x80 [target_core_mod]
[ 334.769351] core_tmr_abort_task.cold.8+0x187/0x202 [target_core_mod]
[ 334.769369] target_tmr_work+0xa1/0x110 [target_core_mod]
[ 334.769384] process_one_work+0x1b0/0x390
[ 334.769387] worker_thread+0x40/0x380
[ 334.769389] ? __pfx_worker_thread+0x10/0x10
[ 334.769391] kthread+0xfa/0x120
[ 334.769393] ? __pfx_kthread+0x10/0x10
[ 334.769395] ret_from_fork+0x29/0x50
[ 334.769399] </TASK>
[ 334.769442] INFO: task iscsi_np:5337 blocked for more than 30 seconds.
[ 334.769444] Tainted: G OE 6.2.0-rc3 #6
[ 334.769444] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 334.769445] task:iscsi_np state:D stack:0 pid:5337 ppid:2 flags:0x00004004
[ 334.769447] Call Trace:
[ 334.769447] <TASK>
[ 334.769448] __schedule+0x318/0xa30
[ 334.769451] ? __pfx_schedule_timeout+0x10/0x10
[ 334.769453] ? __wait_for_common+0xd3/0x1e0
[ 334.769454] schedule+0x57/0xd0
[ 334.769456] schedule_timeout+0x273/0x320
[ 334.769459] ? iscsi_update_param_value+0x27/0x70 [iscsi_target_mod]
[ 334.769476] ? __kmalloc_node_track_caller+0x52/0x130
[ 334.769478] ? __pfx_schedule_timeout+0x10/0x10
[ 334.769480] __wait_for_common+0xf9/0x1e0
[ 334.769481] iscsi_check_for_session_reinstatement+0x1e8/0x280 [iscsi_target_mod]
[ 334.769496] iscsi_target_do_login+0x23b/0x570 [iscsi_target_mod]
[ 334.769508] iscsi_target_start_negotiation+0x55/0xc0 [iscsi_target_mod]
[ 334.769519] iscsi_target_login_thread+0x675/0xeb0 [iscsi_target_mod]
[ 334.769531] ? __pfx_iscsi_target_login_thread+0x10/0x10 [iscsi_target_mod]
[ 334.769541] kthread+0xfa/0x120
[ 334.769543] ? __pfx_kthread+0x10/0x10
[ 334.769544] ret_from_fork+0x29/0x50
[ 334.769547] </TASK>
[ 185.734571] isert: isert_allocate_cmd: Unable to allocate iscsit_cmd + isert_cmd
[ 246.032360] ABORT_TASK: Found referenced iSCSI task_tag: 75
[ 278.442726] iSCSI Login timeout on Network Portal 5.1.1.21:3260
By the way increasing tag_num in iscsi_target_locate_portal() will also avoid the issue"
Any thoughts on what could be causing this hang?
I know that Mike just did a set of fixes on the session teardown area...
Perhaps you should try with the patchset "target: TMF and recovery
fixes" applied?
