RE: [PATCH for-rc] IB/isert: Fix hang in iscsit_wait_for_tag

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



> 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?

Shiraz




[Index of Archives]     [Linux SCSI]     [Kernel Newbies]     [Linux SCSI Target Infrastructure]     [Share Photos]     [IDE]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Linux ATA RAID]     [Linux IIO]     [Device Mapper]

  Powered by Linux