RQ overflow seen running isert traffic

Hi Sagi,
I've been trying to understand the isert functionality with respect to RDMA Receive Queue sizing and Queue full handling. Here is the problem is see with iw_cxgb4:

After running few minutes of iSER traffic with iw_cxgb4, I am seeing post receive failures due to receive queue full returning -ENOMEM. In case of iw_cxgb4 the RQ size is 130 with qp attribute max_recv_wr = 129, passed down by isert to iw_cxgb4.isert decides on max_recv_wr as 129 based on (ISERT_QP_MAX_RECV_DTOS = ISCSI_DEF_XMIT_CMDS_MAX = 128) + 1.

My debug suggests that at some point isert tries to post more than 129 receive WRs into the RQ and fails as the queue is full already. From the code most of the recv wr are posted only after a recieve completion, but few datain operations(isert_put_datain()) are done independent of receive completions. In fact the last WR failed to post in to RQ is from isert_put_datain() through target_complete_ok_work(). CQ stats at the time of failure shows the cq polled to empty.

How could I check for the possible conditions leading to this issue? I am happy to provide you any details further.
Thanks for your time.

Bharat.
--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi Sagi,

I've been trying to understand the isert functionality with respect to RDMA Receive Queue sizing and Queue full handling. Here is the problem is see with iw_cxgb4:

After running few minutes of iSER traffic with iw_cxgb4, I am seeing post receive failures due to receive queue full returning -ENOMEM. In case of iw_cxgb4 the RQ size is 130 with qp attribute max_recv_wr = 129, passed down by isert to iw_cxgb4.isert decides on max_recv_wr as 129 based on (ISERT_QP_MAX_RECV_DTOS = ISCSI_DEF_XMIT_CMDS_MAX = 128) + 1.

My debug suggests that at some point isert tries to post more than 129 receive WRs into the RQ and fails as the queue is full already. From the code most of the recv wr are posted only after a recieve completion, but few datain operations(isert_put_datain()) are done independent of receive completions.

In fact the last WR failed to post in to RQ is from isert_put_datain() through target_complete_ok_work(). CQ stats at the time of failure shows the cq polled to empty.

Quoted 2 lines

Hi Sagi,

Hey Baharat,

Sorry for the late response, its the holiday
season in Israel...

Quoted 4 lines

I've been trying to understand the isert functionality with respect to RDMA Receive Queue sizing and Queue full handling. Here is the problem is see with iw_cxgb4:

Quoted 5 lines

After running few minutes of iSER traffic with iw_cxgb4, I am seeing post receive failures due to receive queue full returning -ENOMEM. In case of iw_cxgb4 the RQ size is 130 with qp attribute max_recv_wr = 129, passed down by isert to iw_cxgb4.isert decides on max_recv_wr as 129 based on (ISERT_QP_MAX_RECV_DTOS = ISCSI_DEF_XMIT_CMDS_MAX = 128) + 1.

That's correct.

Quoted 7 lines

My debug suggests that at some point isert tries to post more than 129 receive WRs into the RQ and fails as the queue is full already. From the code most of the recv wr are posted only after a recieve completion, but few datain operations(isert_put_datain()) are done independent of receive completions.

Interesting. I suspect that this issue haven't come up is that the devices I used to test with allocate the send/recv queues in the next power of 2 (which would be 256) which was enough to hide this I guess...

We repost the recv buffer under the following conditions:
1. We are queueing data + response (datain) or just response (dataout) and we are done with the recv buffer.
2. We got a unsolicited dataout.

Can you please turn off unsolicited dataouts and see if this still happen? (InitialR2T=Yes)

Quoted 3 lines

In fact the last WR failed to post in to RQ is from isert_put_datain() through target_complete_ok_work(). CQ stats at the time of failure shows the cq polled to empty.

That is strange, each scsi command should trigger iscsit_queue_data_in just once. Can you provide evidence of a command that triggers it more than once?

Another possible reason is that we somehow get to put_data_in and put_response for the same command (which we should never do because we handle the response in put_data_in).

Thanks for reporting.
Sagi.

Quoted 8 lines

Quoted 2 lines

Hi Sagi,

Hey Baharat,

Sorry for the late response, its the holiday
season in Israel...

Quoted 7 lines

Quoted 7 lines

I've been trying to understand the isert functionality with respect to RDMA Receive Queue sizing and Queue full handling. Here is the problem is see with iw_cxgb4:

After running few minutes of iSER traffic with iw_cxgb4, I am seeing post receive failures due to receive queue full returning -ENOMEM. In case of iw_cxgb4 the RQ size is 130 with qp attribute max_recv_wr =

Quoted 4 lines

Quoted 2 lines

passed down by isert to iw_cxgb4.isert decides on max_recv_wr as 129 based on (ISERT_QP_MAX_RECV_DTOS = ISCSI_DEF_XMIT_CMDS_MAX = 128) + 1.

That's correct.

Hi Sagi,
Sorry for the late reply, I had to recheck my findings before I reply you back.

My interpretation of the queue full issue was not complete, got carried away by the recieve queue and missed the SQ failure due to full among the debug logs.

Here is what was happening:
It was the SQ full first and fails to get posted with ENOMEM, due to this the command is queued to queue full list this will schedule it to post at later instance and this repeated try for posting will cause the rq to get full. For everyfurther try sq post will any way fail and an extra rq wr is posted as a part of datain() leading it to be full too.

This happened a bit earlier in my case, since I corrected the the iser_put_datain() to return error to LIO.

Here is the failure log on a fresh 4.8 kernel:
isert: isert_rdma_rw_ctx_post: Cmd: ffff882ec8c96e60 failed to post RDMA res <===here is the post send failure due to ENOMEM.
ABORT_TASK: Found referenced iSCSI task_tag: 33
ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 33
isert: isert_post_recv: ib_post_recv() failed with ret: -22
isert: isert_post_response: ib_post_recv failed with -22
isert: isert_post_recv: ib_post_recv() failed with ret: -22
isert: isert_post_response: ib_post_recv failed with -22
isert: isert_post_recv: ib_post_recv() failed with ret: -22
isert: isert_post_response: ib_post_recv failed with -22
isert: isert_post_recv: ib_post_recv() failed with ret: -22
isert: isert_post_response: ib_post_recv failed with -22
isert: isert_post_recv: ib_post_recv() failed with ret: -22
isert: isert_post_response: ib_post_recv failed with -22 cxgb4 0000:84:00.4: AE qpid 1026 opcode 10 status 0x1 type 1 len 0x0 wrid.hi 0x0 wrid.lo 0x4c01
isert: isert_qp_event_callback: QP access error (3): conn ffff8817ddc46000
iSCSI Login timeout on Network Portal 10.40.40.198:3260

INFO: task iscsi_np:14744 blocked for more than 120 seconds.

Here are the QP and CQ stats before my assert for queue full:
qhp->attr.sq_num_entries 523 qhp->attr.rq_num_entries 129
qhp->wq.sq.qid 1026
qhp->wq.rq.qid 1027
qhp->wq.sq.in_use 523 <=== SQ to the brim qhp->wq.sq.size 524 <=== SQ size
qhp->wq.sq.cidx 391
qhp->wq.sq.pidx 390
qhp->wq.sq.wq_pidx 202
qhp->wq.sq.wq_pidx_inc 0
qhp->wq.sq.flush_cidx 391
qhp->wq.rq.in_use 128
qhp->wq.rq.size 130
qhp->wq.rq.cidx 112
qhp->wq.rq.pidx 110
qhp->wq.rq.wq_pidx 240
qhp->wq.rq.wq_pidx_inc 0
qhp->wq.flushed 0
chp->cq.cqid 1024
chp->cq.size 6335
chp->cq.cidx 4978
chp->cq.sw_cidx 4126
chp->cq.sw_pidx 4126
chp->cq.sw_in_use 0
chp->cq.cidx_inc 0

As an experiment I tried increasing the ISCSI_DEF_XMIT_CMDS_MAX to 256 instead of 128, which incase of iwarp creates SQ with size 1548, the issue is not seen.
I doubt if the SQ is not sized properly incase of iWARP Or factored incorrectly in the rdma api for iser IOP.

I am digging for root cause.

Thanks for your time,
Bharat.

Hey Sagi, I'm looking at isert_create_qp() and it appears to not be correctly sizing the SQ:
...

#define ISERT_QP_MAX_REQ_DTOS   (ISCSI_DEF_XMIT_CMDS_MAX +    \
                                ISERT_MAX_TX_MISC_PDUS  + \
                                ISERT_MAX_RX_MISC_PDUS)
...
        attr.cap.max_send_wr = ISERT_QP_MAX_REQ_DTOS + 1;
        attr.cap.max_recv_wr = ISERT_QP_MAX_RECV_DTOS + 1;

...

I think above snipit assumes a DTO consumes exactly one WR/WQE in the SQ. But the DTO can be broken into multiple WRs to handle REG_MRs, multiple WRITE or READ WRs due to limits on local sge depths target sge depths, etc. Yes? Or am I all wet? Or perhaps isert doesn't require the SQ to be the max possible because it flow controls the DTO submissions?

Hey Steve and Baharat,

Quoted 9 lines

Hey Sagi, I'm looking at isert_create_qp() and it appears to not be correctly sizing the SQ:
...

#define ISERT_QP_MAX_REQ_DTOS   (ISCSI_DEF_XMIT_CMDS_MAX +    \
                               ISERT_MAX_TX_MISC_PDUS  + \
                               ISERT_MAX_RX_MISC_PDUS)
...
       attr.cap.max_send_wr = ISERT_QP_MAX_REQ_DTOS + 1;
       attr.cap.max_recv_wr = ISERT_QP_MAX_RECV_DTOS + 1;

Quoted 7 lines

...

I think above snipit assumes a DTO consumes exactly one WR/WQE in the SQ. But the DTO can be broken into multiple WRs to handle REG_MRs, multiple WRITE or READ WRs due to limits on local sge depths target sge depths, etc. Yes? Or am I all wet? Or perhaps isert doesn't require the SQ to be the max possible because it flow controls the DTO submissions?

I think you are correct.

On my test devices, I didn't see that multiple WRs has had any effect becuase:
1. My test devices usually give next power of 2 (256)
2. workloads that involved multiple rdma operations never stressed the system enough to get the queues full.

Now, in iWARP for non-immediate writes we'll need more than a single wr per IO (I think the SQ size is expanded with the new rdma RW API which implicitly increases with attr.cap.max_rdma_ctxs).

But I do agree that we need to take into account that each IO needs at least 2 WRs (one for rdma and one for send).

So a temp bandage would be:
--

drivers/infiniband/ulp/isert/ib_isert.h +2 -2

index fc791efe3a10..81afb95aeea9 100644
@@ -54,8 +54,14 @@
 
 #define ISERT_MIN_POSTED_RX    (ISCSI_DEF_XMIT_CMDS_MAX >> 2)
 
-#define ISERT_QP_MAX_REQ_DTOS  (ISCSI_DEF_XMIT_CMDS_MAX +    \
-                               ISERT_MAX_TX_MISC_PDUS  + \
+/*
+ * Max QP send work requests consist of:

But we do need to track the SQ overflow and queue a retransmit work when we don't have enough available SQ slots..

Thoughts?

I tried out this change and it works fine with iwarp. I dont see SQ overflow. Apparently we have increased the sq too big to overflow. I am going to let it run with higher workloads for longer time, to see if it holds good.

Quoted 3 lines

I tried out this change and it works fine with iwarp. I dont see SQ overflow. Apparently we have increased the sq too big to overflow. I am

Quoted 1 line

to let it run with higher workloads for longer time, to see if it holds

Actually on second thought, this patch is an overkill. Effectively we now set:

MAX_CMD=266
and max_rdma_ctx=128 so together we take 394 which seems to too much.

If we go by the scheme of 1 rdma + 1 send for each IO we need:
- 128 sends
- 128 rdmas
- 10 miscs

so this gives 266.

Perhaps this is due to the fact that iWARP needs to register memory for rdma reads as well? (and also rdma writes > 128k for chelsio HW right?)

What is the workload you are running? with immediatedata enabled you should issue reg+rdma_read+send only for writes > 8k.

Does this happen when you run only reads for example?

I guess its time to get the sq accounting into shape...

1) we believe the iSER + RW API correctly sizes the SQ, yet we're seeing SQ overflows. So the SQ sizing needs more investigation.

Quoted 3 lines

1) we believe the iSER + RW API correctly sizes the SQ, yet we're seeing SQ overflows. So the SQ sizing needs more investigation.

NFS had this sort of problem - in that case it was because the code was assuming that a RQ completion implied SQ space - that is not legal, only direct completions from SQ WCs can guide available space in the SQ..

Quoted 2 lines

1) we believe the iSER + RW API correctly sizes the SQ, yet we're seeing SQ overflows. So the SQ sizing needs more investigation.

NFS had this sort of problem - in that case it was because the code was assuming that a RQ completion implied SQ space - that is not legal, only direct completions from SQ WCs can guide available space in the SQ..

Hey Jason,

Quoted 1 line

Quoted 1 line

1) we believe the iSER + RW API correctly sizes the SQ, yet we're

seeing SQ

Quoted 6 lines

Quoted 1 line

overflows.  So the SQ sizing needs more investigation.

NFS had this sort of problem - in that case it was because the code was assuming that a RQ completion implied SQ space - that is not legal, only direct completions from SQ WCs can guide available space in the SQ..

Its not the same problem. iser-target does not tie SQ and RQ spaces. The origin here is the difference between IB/RoCE and iWARP and the chelsio HW that makes it hard to predict the SQ correct size.

iWARP needs extra registration for rdma reads and the chelsio device seems to be limited in the number of pages per registration so this configuration will need a larger send queue.

Another problem is that we don't have a correct retry flow.

Hopefully we can address that in the RW API which is designed to hide these details from the ULP...

From this is there any possibility that we could use MR if the write WR

Quoted 15 lines

Hey Jason,

Quoted 1 line

Quoted 1 line

1) we believe the iSER + RW API correctly sizes the SQ, yet we're

seeing SQ

Quoted 6 lines

Quoted 1 line

overflows.  So the SQ sizing needs more investigation.

NFS had this sort of problem - in that case it was because the code was assuming that a RQ completion implied SQ space - that is not legal, only direct completions from SQ WCs can guide available space in the SQ..

Its not the same problem. iser-target does not tie SQ and RQ spaces. The origin here is the difference between IB/RoCE and iWARP and the chelsio HW that makes it hard to predict the SQ correct size.

Quoted 8 lines

iWARP needs extra registration for rdma reads and the chelsio device seems to be limited in the number of pages per registration so this configuration will need a larger send queue.

Another problem is that we don't have a correct retry flow.

Hopefully we can address that in the RW API which is designed to hide these details from the ULP...

Hi Sagi,
Here is what our further analysis of SQ dump at the time of overflow says:

RDMA read/write API is creating long chains (32 WRs) to handle large ISCSI READs. For Writing iscsi default block size of 512KB data, iw_cxgb4's max number of sge advertised is 4 page ~ 16KB for write, needs WR chain of 32 WRs (another possible factor is they all are unsignalled WRs and are completed only after next signalled WR) But apparantly rdma_rw_init_qp() assumes that any given IO will take only 1 WRITE WR to convey the data.

This evidently is incorrect and rdma_rw_init_qp() needs to factor and size the queue based on max_sge of device for write and read and the sg_tablesize for which rdma read/write is used for, like ISCSI_ISER_MAX_SG_TABLESIZE of initiator. If above analysis is correct, please suggest how could this be

Further, using MRs for rdma WRITE by using rdma_wr_force_mr = 1 module parameter of ib_core avoids SQ overflow by registering a single REG_MR and using that MR for a single WRITE WR. So a rdma-rw IO chain of say 32 WRITE WRs, becomes just 3 WRS: REG_MR + WRITE + INV_MR as max_fast_reg_page_list_len of iw_cxgb4 is 128 page.

(By default force_mr is not set and iw_cxgb4 could only use MR for rdma READs only as per rdma_rw_io_needs_mr() if force_mr isnt set)

Quoted 1 line

From this is there any possibility that we could use MR if the write WR

chain exceeds a certain number?

Thanks for your time!

Quoted 3 lines

Quoted 3 lines

I tried out this change and it works fine with iwarp. I dont see SQ overflow. Apparently we have increased the sq too big to overflow. I am

going

Quoted 1 line

Quoted 1 line

to let it run with higher workloads for longer time, to see if it holds

good.

Quoted 12 lines

Actually on second thought, this patch is an overkill. Effectively we now set:

MAX_CMD=266
and max_rdma_ctx=128 so together we take 394 which seems to too much.

If we go by the scheme of 1 rdma + 1 send for each IO we need:
- 128 sends
- 128 rdmas
- 10 miscs

Quoted 5 lines

so this gives 266.

Perhaps this is due to the fact that iWARP needs to register memory for rdma reads as well? (and also rdma writes > 128k for chelsio HW right?)

iWARP definitely needs to register memory for the target of reads, due to REMOTE_WRITE requirement for the protocol. The source of a write doesn't need to register memory, but the SGE depth can cause multiple WRITE WRs to be required to service the IO. And in theory there should be some threshold where it might be better performance-wise to do a memory register + 1 WRITE vs X WRITEs.

As you mentioned, the RW API should account for this, but perhaps it is still off some. Bharat, have a look into the RDMA-RW API and let us see if we can figure out if the additional SQ depth it adds is sufficient.

Quoted 6 lines

What is the workload you are running? with immediatedata enabled you should issue reg+rdma_read+send only for writes > 8k.

Does this happen when you run only reads for example?

I guess its time to get the sq accounting into shape...

So to sum up - 2 issues:

1) we believe the iSER + RW API correctly sizes the SQ, yet we're seeing SQ overflows. So the SQ sizing needs more investigation.

2) if the SQ is full, then the iSER/target code is supposed to resubmit. And apparently that isn't working.

Quoted 8 lines

So to sum up - 2 issues:

1) we believe the iSER + RW API correctly sizes the SQ, yet we're seeing SQ overflows. So the SQ sizing needs more investigation.

2) if the SQ is full, then the iSER/target code is supposed to resubmit. And apparently that isn't working.

For #2, target-core expects -ENOMEM or -EAGAIN return from fabric driver callbacks to signal internal queue-full retry logic. Otherwise, the extra se_cmd->cmd_kref response SCF_ACK_KREF is leaked until session shutdown and/or reinstatement occurs.

AFAICT, Potunri's earlier hung task with v4.8.y + ABORT_TASK is likely the earlier v4.1+ regression:

https://github.com/torvalds/linux/commit/527268df31e57cf2b6d417198717c6d6afd
b1e3e

That said, there is room for improvement in target-core queue-full error signaling, and iscsi-target/iser-target callback error propagation.

Sending out a series shortly to address these particular items. Please have a look.

Hi Steve, Potnuri, & Co,

Quoted 42 lines · Steve Wise

Quoted 3 lines

Quoted 3 lines

I tried out this change and it works fine with iwarp. I dont see SQ overflow. Apparently we have increased the sq too big to overflow. I am

going

Quoted 1 line

Quoted 1 line

to let it run with higher workloads for longer time, to see if it holds

good.

Quoted 12 lines

Actually on second thought, this patch is an overkill. Effectively we now set:

MAX_CMD=266
and max_rdma_ctx=128 so together we take 394 which seems to too much.

If we go by the scheme of 1 rdma + 1 send for each IO we need:
- 128 sends
- 128 rdmas
- 10 miscs

Quoted 5 lines

so this gives 266.

Perhaps this is due to the fact that iWARP needs to register memory for rdma reads as well? (and also rdma writes > 128k for chelsio HW right?)

iWARP definitely needs to register memory for the target of reads, due to REMOTE_WRITE requirement for the protocol. The source of a write doesn't need to register memory, but the SGE depth can cause multiple WRITE WRs to be required to service the IO. And in theory there should be some threshold where it might be better performance-wise to do a memory register + 1 WRITE vs X WRITEs.

As you mentioned, the RW API should account for this, but perhaps it is still off some. Bharat, have a look into the RDMA-RW API and let us see if we can figure out if the additional SQ depth it adds is sufficient.

Quoted 6 lines

What is the workload you are running? with immediatedata enabled you should issue reg+rdma_read+send only for writes > 8k.

Does this happen when you run only reads for example?

I guess its time to get the sq accounting into shape...

Quoted 8 lines

So to sum up - 2 issues:

1) we believe the iSER + RW API correctly sizes the SQ, yet we're seeing SQ overflows. So the SQ sizing needs more investigation.

2) if the SQ is full, then the iSER/target code is supposed to resubmit. And apparently that isn't working.

For #2, target-core expects -ENOMEM or -EAGAIN return from fabric driver callbacks to signal internal queue-full retry logic. Otherwise, the extra se_cmd->cmd_kref response SCF_ACK_KREF is leaked until session shutdown and/or reinstatement occurs.

AFAICT, Potunri's earlier hung task with v4.8.y + ABORT_TASK is likely the earlier v4.1+ regression:

https://github.com/torvalds/linux/commit/527268df31e57cf2b6d417198717c6d6afdb1e3e

That said, there is room for improvement in target-core queue-full error signaling, and iscsi-target/iser-target callback error propagation.

Sending out a series shortly to address these particular items. Please have a look.

On Monday, October 10/31/16, 2016 at 09:10:08 +0530, Nicholas A. Bellinger wrote:

Quoted 5 lines

Hi Steve, Potnuri, & Co,

Quoted 2 lines · Steve Wise

Quoted 2 lines

Quoted 2 lines

I tried out this change and it works fine with iwarp. I dont see

SQ

Quoted 1 line

Quoted 1 line

Quoted 1 line

Quoted 1 line

overflow. Apparently we have increased the sq too big to overflow.

I am

Quoted 2 lines

Quoted 2 lines

going

Quoted 1 line

Quoted 1 line

to let it run with higher workloads for longer time, to see if it

holds

Quoted 3 lines

Quoted 3 lines

good.

Quoted 2 lines

Actually on second thought, this patch is an overkill. Effectively

we

Quoted 4 lines

Quoted 4 lines

Quoted 4 lines

now set:

MAX_CMD=266
and max_rdma_ctx=128 so together we take 394 which seems to too

much.

Quoted 9 lines

Quoted 9 lines

Quoted 9 lines

If we go by the scheme of 1 rdma + 1 send for each IO we need:
- 128 sends
- 128 rdmas
- 10 miscs

so this gives 266.

Perhaps this is due to the fact that iWARP needs to register memory

for

Quoted 1 line

Quoted 1 line

Quoted 1 line

rdma reads as well? (and also rdma writes > 128k for chelsio HW

right?)

Quoted 3 lines

Quoted 3 lines

Quoted 1 line

iWARP definitely needs to register memory for the target of reads, due

to

Quoted 1 line

Quoted 1 line

REMOTE_WRITE requirement for the protocol.  The source of a write

doesn't need

Quoted 1 line

Quoted 1 line

to register memory, but the SGE depth can cause multiple WRITE WRs to

be

Quoted 1 line

Quoted 1 line

required to service the IO.  And in theory there should be some

threshold where

Quoted 1 line

Quoted 1 line

it might be better performance-wise to do a memory register + 1 WRITE

vs X

Quoted 3 lines

Quoted 3 lines

WRITEs.

As you mentioned, the RW API should account for this, but perhaps it

is still

Quoted 1 line

Quoted 1 line

off some.  Bharat, have a look into the RDMA-RW API and let us see if

we can

Quoted 5 lines

Quoted 5 lines

figure out if the additional SQ depth it adds is sufficient.

Quoted 3 lines

What is the workload you are running? with immediatedata enabled you should issue reg+rdma_read+send only for writes > 8k.

Quoted 7 lines

Quoted 7 lines

Quoted 3 lines

Does this happen when you run only reads for example?

I guess its time to get the sq accounting into shape...

So to sum up - 2 issues:

1) we believe the iSER + RW API correctly sizes the SQ, yet we're

seeing SQ

Quoted 3 lines

Quoted 3 lines

overflows.  So the SQ sizing needs more investigation.

2) if the SQ is full, then the iSER/target code is supposed to

resubmit.  And

Quoted 12 lines

Quoted 2 lines

apparently that isn't working.

For #2, target-core expects -ENOMEM or -EAGAIN return from fabric driver callbacks to signal internal queue-full retry logic.  Otherwise, the extra se_cmd->cmd_kref response SCF_ACK_KREF is leaked until session shutdown and/or reinstatement occurs.

AFAICT, Potunri's earlier hung task with v4.8.y + ABORT_TASK is likely the earlier v4.1+ regression:

[1]https://github.com/torvalds/linux/commit/527268df31e57cf2b6d417198717c6d6afdb1e3e

Quoted 7 lines

That said, there is room for improvement in target-core queue-full error signaling, and iscsi-target/iser-target callback error propagation.

Sending out a series shortly to address these particular items. Please have a look.

Thanks for the changes Nicholas.
Testing them now.
--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in the body of a message to [email protected]
More majordomo info at  [2]http://vger.kernel.org/majordomo-info.html

References

Visible links
1. https://github.com/torvalds/linux/commit/527268df31e57cf2b6d417198717c6d6afdb1e3e
2. http://vger.kernel.org/majordomo-info.html

Quoted 2 lines · Potnuri Bharat Teja

On Monday, October 10/31/16, 2016 at 09:10:08 +0530, Nicholas A. Bellinger wrote:

Hi Nicholas,
Tested the following 3 patches for SQ overflow.
https://www.spinics.net/lists/target-devel/msg13571.html

They along with an additional change added on top of those seems to hold good.( Aborts seen intermittently as shown at the end of mail)
I have been testing the changes using fio with IO sizes ranging from 1KB to 32MB and test is running fine (despite few Intermittent Aborts).

Here is what I see with the 3 patches alone applied:

-> In isert_put_datain() and isert_post_response() a corresponding recv WR is posted before posting a send and hence for every post failure a recv is already posted into a tightly packed RQ, causing it to overflow.

Below are the logs suggesting it:

[  189.944714] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0 failed to post RDMA res
[  189.944718] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0 failed to post RDMA res
[  189.944721] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0 failed to post RDMA res
[  189.944724] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0 failed to post RDMA res
[  189.944729] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0 failed to post RDMA res
[  189.944731] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944731] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944732] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944733] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944734] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944735] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944736] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944736] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944737] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944738] isert: isert_put_datain: ib_post_recv failed with -12

[  189.944739] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944740] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944740] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944741] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944746] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0 failed to post RDMA res
[  189.944747] isert: isert_post_recv: ib_post_recv() failed with ret: -12
[  189.944748] isert: isert_put_datain: ib_post_recv failed with -12
[  189.944749] isert: isert_post_recv: ib_post_recv() failed with ret: -12

[  251.543847] ABORT_TASK: Found referenced iSCSI task_tag: 68
[  251.543858] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 68
[  251.544071] ABORT_TASK: Found referenced iSCSI task_tag: 46
[  251.544076] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 46
[  251.544300] ABORT_TASK: Found referenced iSCSI task_tag: 51
[  251.544307] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 51
[  251.544528] ABORT_TASK: Found referenced iSCSI task_tag: 117
[  251.544533] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 117
[  282.778402] Unable to locate ITT: 0x00000062 on CID: 0
[  282.778404] Unable to locate RefTaskTag: 0x00000062 on CID: 0.
[  282.778407] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag: 0
[  282.778436] ABORT_TASK: Found referenced iSCSI task_tag: 37
[  282.778439] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 37
[  282.778519] ABORT_TASK: Found referenced iSCSI task_tag: 65
[  282.778522] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 65
[  282.778559] Unable to locate ITT: 0x00000019 on CID: 0
[  282.778560] Unable to locate RefTaskTag: 0x00000019 on CID: 0.
[  282.778563] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag: 0
[  293.004632] ABORT_TASK: Found referenced iSCSI task_tag: 22
[  293.004643] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 22
[  293.004808] TMR Opcode TARGET_WARM_RESET authorization failed for Initiator Node: iqn.1994-05.com.redhat:37fc2b6a5331
[  310.265993] iSCSI Login timeout on Network Portal 10.0.2.2:3260
[  493.567143] INFO: task iscsi_np:3998 blocked for more than 120 seconds.
[  493.567149]       Tainted: G           OE   4.9.0-For-DSGL-Debug+ #1
[  493.567151] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  493.567153] iscsi_np        D    0  3998      2 0x00000084
[  493.567159]  0000000000000000 ffff883028a88b40 ffff88302693f7c0 ffff88302de3e300
[  493.567163]  ffff88303e057a40 ffffc900008abc00 ffffffff815e415b ffffc900008abca0
[  493.567166]  ffffffff81af4180 ffff883028a88b40 7fffffffffffffff ffff882f7426db68
[  493.567170] Call Trace:
[  493.567180]  [<ffffffff815e415b>] ? __schedule+0x23b/0x6c0
[  493.567184]  [<ffffffff815e4616>] schedule+0x36/0x80
[  493.567187]  [<ffffffff815e71c3>] schedule_timeout+0x1f3/0x390
[  493.567194]  [<ffffffff812c1f2e>] ? number+0x2ce/0x300
[  493.567197]  [<ffffffff812c42be>] ? vsnprintf+0x32e/0x4b0
[  493.567199]  [<ffffffff815e56a4>] wait_for_completion+0xb4/0xf0
[  493.567201]  [<ffffffff8108a6b0>] ? wake_up_q+0x80/0x80
[  493.567216]  [<ffffffffa05284d1>] iscsit_stop_session+0x1b1/0x1c0 [iscsi_target_mod]
[  493.567220]  [<ffffffffa0519db2>] iscsi_check_for_session_reinstatement+0x1e2/0x270 [iscsi_target_mod]
[  493.567225]  [<ffffffffa051c8c0>] iscsi_target_check_for_existing_instances+0x30/0x40 [iscsi_target_mod]
[  493.567230]  [<ffffffffa051c9ee>] iscsi_target_do_login+0x11e/0x610 [iscsi_target_mod]
[  493.567235]  [<ffffffffa051dbbe>] iscsi_target_start_negotiation+0x4e/0xa0 [iscsi_target_mod]
[  493.567239]  [<ffffffffa051b933>] iscsi_target_login_thread+0xa73/0xfc0 [iscsi_target_mod]
[  493.567244]  [<ffffffffa051aec0>] ? iscsi_target_login_sess_out+0x250/0x250 [iscsi_target_mod]
[  493.567246]  [<ffffffff810660c4>] ? SyS_exit_group+0x14/0x20
[  493.567249]  [<ffffffff8107ee5a>] kthread+0xca/0xe0
[  493.567250]  [<ffffffff8107ed90>] ? kthread_park+0x60/0x60
[  493.567252]  [<ffffffff815e8752>] ret_from_fork+0x22/0x30
[  493.567254] INFO: task iscsi_trx:4149 blocked for more than 120 seconds.
[  493.567255]       Tainted: G           OE   4.9.0-For-DSGL-Debug+ #1
[  493.567256] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  493.567256] iscsi_trx       D    0  4149      2 0x00000084
[  493.567258]  0000000000000000 ffff882f5ef70340 ffff882f76253040 ffff88302de40340
[  493.567259]  ffff88303e097a40 ffffc90000f93c90 ffffffff815e415b ffffffff815e56c2
[  493.567261]  0000000000000001 ffff882f5ef70340 7fffffffffffffff ffff882d233cc9b0
[  493.567262] Call Trace:
[  493.567264]  [<ffffffff815e415b>] ? __schedule+0x23b/0x6c0
[  493.567265]  [<ffffffff815e56c2>] ? wait_for_completion+0xd2/0xf0
[  493.567267]  [<ffffffff815e4616>] schedule+0x36/0x80
[  493.567268]  [<ffffffff815e71c3>] schedule_timeout+0x1f3/0x390
[  493.567281]  [<ffffffffa118e910>] ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[  493.567285]  [<ffffffffa118e910>] ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[  493.567286]  [<ffffffff815e56a4>] wait_for_completion+0xb4/0xf0
[  493.567287]  [<ffffffff8108a6b0>] ? wake_up_q+0x80/0x80
[  493.567302]  [<ffffffffa04d5399>] target_wait_for_sess_cmds+0x49/0x1a0 [target_core_mod]

[  493.567306]  [<ffffffffa0471644>] isert_wait_conn+0x1a4/0x2d0 [ib_isert]
[  493.567311]  [<ffffffffa05289ab>] iscsit_close_connection+0x14b/0x820 [iscsi_target_mod]
[  493.567315]  [<ffffffffa05172ef>] iscsit_take_action_for_connection_exit+0x7f/0x100 [iscsi_target_mod]
[  493.567320]  [<ffffffffa0528265>] iscsi_target_rx_thread+0x95/0xa0 [iscsi_target_mod]
[  493.567324]  [<ffffffffa05281d0>] ? iscsi_target_tx_thread+0x1b0/0x1b0 [iscsi_target_mod]
[  493.567325]  [<ffffffff8107ee5a>] kthread+0xca/0xe0
[  493.567327]  [<ffffffff8107ed90>] ? kthread_park+0x60/0x60
[  493.567328]  [<ffffffff815e8752>] ret_from_fork+0x22/0x30

-> In order to address this I tried the following (experimental) change on top of your 3 patches:

drivers/infiniband/ulp/isert/ib_isert.c +21 -5

index 501a0ad124a7..0aead5faa2a2 100644
@@ -1817,16 +1817,16 @@ isert_post_response(struct isert_conn *isert_conn, struct isert_cmd *isert_cmd)
        struct ib_send_wr *wr_failed;
        int ret;
 
-       ret = isert_post_recv(isert_conn, isert_cmd->rx_desc);
+       ret = ib_post_send(isert_conn->qp, &isert_cmd->tx_desc.send_wr,
+                          &wr_failed);
        if (ret) {
-               isert_err("ib_post_recv failed with %d\n", ret);
+               isert_err("ib_post_send failed with %d\n", ret);
                return ret;
        }
 
-       ret = ib_post_send(isert_conn->qp, &isert_cmd->tx_desc.send_wr,
-                          &wr_failed);
+       ret = isert_post_recv(isert_conn, isert_cmd->rx_desc);
        if (ret) {
-               isert_err("ib_post_send failed with %d\n", ret);
+               isert_err("ib_post_recv failed with %d\n", ret);
                return ret;
        }
        return ret;

@@ -2166,6 +2166,13 @@ isert_put_datain(struct iscsi_conn *conn, struct iscsi_cmd *cmd)
        if (isert_prot_cmd(isert_conn, se_cmd)) {
                isert_cmd->tx_desc.tx_cqe.done = isert_rdma_write_done;
                cqe = &isert_cmd->tx_desc.tx_cqe;
+
+               rc = isert_rdma_rw_ctx_post(isert_cmd, isert_conn, cqe, chain_wr);
+               if (rc) {
+                       isert_dbg("Cmd: %p posted RDMA_WRITE for iSER Data READ rc: %d\n",
+                                  isert_cmd, rc);
+                       return rc;
+               }
        } else {
                /*
                 * Build isert_conn->tx_desc for iSCSI response PDU and attach

@@ -2178,18 +2185,21 @@ isert_put_datain(struct iscsi_conn *conn, struct iscsi_cmd *cmd)
                isert_init_send_wr(isert_conn, isert_cmd,
                                   &isert_cmd->tx_desc.send_wr);
 
+               chain_wr = &isert_cmd->tx_desc.send_wr;
+
+               rc = isert_rdma_rw_ctx_post(isert_cmd, isert_conn, cqe, chain_wr);
+               if (rc) {
+                       isert_err("Cmd: %p posted RDMA_WRITE for iSER Data READ rc: %d\n",
+                                  isert_cmd, rc);
+                       return rc;
+               }
+
                rc = isert_post_recv(isert_conn, isert_cmd->rx_desc);
                if (rc) {
                        isert_err("ib_post_recv failed with %d\n", rc);
                        return rc;
                }

-> With these changes it works fine, But I still see few Aborts intermittently as follows:

[10674.434643] isert: isert_rdma_rw_ctx_post: Cmd: ffff882cbb961138 failed to post RDMA res
[10674.434690] isert: isert_rdma_rw_ctx_post: Cmd: ffff882cbb9434c0 failed to post RDMA res
[10715.186372] ABORT_TASK: Found referenced iSCSI task_tag: 58
[10715.186417] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 58

-> Apart from the Aborts and post failure logs filling dmesg, luns are in state "running" and fio countinues to run.
[root@bharat ~]# iscsiadm -m session -P3 | grep "Attached scsi disk"

                        Attached scsi disk sdj          State: running
                        Attached scsi disk sdc          State: running
                        Attached scsi disk sdd          State: running
                        Attached scsi disk sde          State: running
                        Attached scsi disk sdf          State: running
                        Attached scsi disk sdg          State: running
                        Attached scsi disk sdh          State: running
                        Attached scsi disk sdi          State: running

Hi Bharat & Co,

Quoted 1 line · Potnuri Bharat Teja

On Tuesday, November 11/08/16, 2016 at 15:36:18 +0530, Potnuri Bharat

Quoted 1 line · Teja

Quoted 1 line

    On Monday, October 10/31/16, 2016 at 09:10:08 +0530, Nicholas A.

Bellinger

Quoted 4 lines

Quoted 1 line

    wrote:

Hi Nicholas,
Tested the following 3 patches for SQ overflow. [1]https://www.spinics.net/lists/target-devel/msg13571.html

Thanks for following up on this.

I was just thinking about sending these patches out again, as separate from iser-target bits in patch #3 (and your incremental below) they do address a couple of long-standing target-core issues wrt queue-full handling.

Quoted 1 line

They along with an additional change added on top of those seems to hold

good.( Aborts seen

Quoted 2 lines

intermittently as shown at the end of mail)
I have been testing the changes using fio with IO sizes ranging from 1KB

to 32MB and test is

Quoted 2 lines

running fine (despite few Intermittent Aborts).

At what I/O size do the post RDMA_WRITE failures for iw_cxgb4 and associated TMR ABORT_TASK begin..?

Quoted 4 lines

Here is what I see with the 3 patches alone applied:

-> In isert_put_datain() and isert_post_response() a corresponding recv

WR is posted before

Quoted 1 line

posting a send and hence for every post failure a recv is already posted

into a tightly packed

Quoted 1 line

RQ, causing it to overflow.

Just for me to understand, the intermittent TMR ABORT_TASKs are caused by the repeated failure to post RDMA_WRITE WRs for a large ISER Data-In payload, due to mis-sizing of needed WRs from RDMA R/W API vs. underlying hardware capabilities.

Moving the recv posts after the send post for RDMA_WRITEs helps to reduce the severity of the issue with iw_cxgb4, but doesn't completely eliminate the issue under load.

Quoted 5 lines

Below are the logs suggesting it:

[  189.944714] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0

failed to post RDMA res

Quoted 1 line

[  189.944718] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0

failed to post RDMA res

Quoted 1 line

[  189.944721] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0

failed to post RDMA res

Quoted 1 line

[  189.944724] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0

failed to post RDMA res

Quoted 1 line

[  189.944729] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0

failed to post RDMA res

Quoted 1 line

[  189.944731] isert: isert_post_recv: ib_post_recv() failed with ret:

   -12
   > [  189.944731] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944732] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944733] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944734] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944735] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944736] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944736] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944737] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944738] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944739] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944740] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944740] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944741] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944746] isert: isert_rdma_rw_ctx_post: Cmd: ffff882d233e83d0

   failed to post RDMA res
   > [  189.944747] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12
   > [  189.944748] isert: isert_put_datain: ib_post_recv failed with -12
   > [  189.944749] isert: isert_post_recv: ib_post_recv() failed with ret:
   -12

   Mmmm, why does the retry of isert_put_datain() stop here..?

Does this delay between the last isert_put_datain() retry and subsequent TMR ABORT_TASKs happen with your incremental patch applied too..?

Quoted 9 lines

[  251.543847] ABORT_TASK: Found referenced iSCSI task_tag: 68 [  251.543858] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 68 [  251.544071] ABORT_TASK: Found referenced iSCSI task_tag: 46 [  251.544076] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 46 [  251.544300] ABORT_TASK: Found referenced iSCSI task_tag: 51 [  251.544307] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 51 [  251.544528] ABORT_TASK: Found referenced iSCSI task_tag: 117 [  251.544533] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag:

   117
   > [  282.778402] Unable to locate ITT: 0x00000062 on CID: 0
   > [  282.778404] Unable to locate RefTaskTag: 0x00000062 on CID: 0.
   > [  282.778407] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag:
   0
   > [  282.778436] ABORT_TASK: Found referenced iSCSI task_tag: 37
   > [  282.778439] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 37
   > [  282.778519] ABORT_TASK: Found referenced iSCSI task_tag: 65
   > [  282.778522] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 65
   > [  282.778559] Unable to locate ITT: 0x00000019 on CID: 0
   > [  282.778560] Unable to locate RefTaskTag: 0x00000019 on CID: 0.
   > [  282.778563] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag:
   0
   > [  293.004632] ABORT_TASK: Found referenced iSCSI task_tag: 22
   > [  293.004643] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 22
   > [  293.004808] TMR Opcode TARGET_WARM_RESET authorization failed for
   Initiator Node: iqn.1994-05.com.redhat:37fc2b6a5331
   > [  310.265993] iSCSI Login timeout on Network Portal 10.0.2.2:3260
   > [  493.567143] INFO: task iscsi_np:3998 blocked for more than 120
   seconds.
   > [  493.567149]       Tainted: G           OE   4.9.0-For-DSGL-Debug+ #1
   > [  493.567151] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
   disables this message.
   > [  493.567153] iscsi_np        D    0  3998      2 0x00000084
   > [  493.567159]  0000000000000000 ffff883028a88b40 ffff88302693f7c0
   ffff88302de3e300
   > [  493.567163]  ffff88303e057a40 ffffc900008abc00 ffffffff815e415b
   ffffc900008abca0
   > [  493.567166]  ffffffff81af4180 ffff883028a88b40 7fffffffffffffff
   ffff882f7426db68
   > [  493.567170] Call Trace:
   > [  493.567180]  [<ffffffff815e415b>] ? __schedule+0x23b/0x6c0
   > [  493.567184]  [<ffffffff815e4616>] schedule+0x36/0x80
   > [  493.567187]  [<ffffffff815e71c3>] schedule_timeout+0x1f3/0x390
   > [  493.567194]  [<ffffffff812c1f2e>] ? number+0x2ce/0x300
   > [  493.567197]  [<ffffffff812c42be>] ? vsnprintf+0x32e/0x4b0
   > [  493.567199]  [<ffffffff815e56a4>] wait_for_completion+0xb4/0xf0
   > [  493.567201]  [<ffffffff8108a6b0>] ? wake_up_q+0x80/0x80
   > [  493.567216]  [<ffffffffa05284d1>] iscsit_stop_session+0x1b1/0x1c0
   [iscsi_target_mod]
   > [  493.567220]  [<ffffffffa0519db2>]
   iscsi_check_for_session_reinstatement+0x1e2/0x270 [iscsi_target_mod]
   > [  493.567225]  [<ffffffffa051c8c0>]
   iscsi_target_check_for_existing_instances+0x30/0x40 [iscsi_target_mod]
   > [  493.567230]  [<ffffffffa051c9ee>] iscsi_target_do_login+0x11e/0x610
   [iscsi_target_mod]
   > [  493.567235]  [<ffffffffa051dbbe>]
   iscsi_target_start_negotiation+0x4e/0xa0 [iscsi_target_mod]
   > [  493.567239]  [<ffffffffa051b933>]
   iscsi_target_login_thread+0xa73/0xfc0 [iscsi_target_mod]
   > [  493.567244]  [<ffffffffa051aec0>] ?
   iscsi_target_login_sess_out+0x250/0x250 [iscsi_target_mod]
   > [  493.567246]  [<ffffffff810660c4>] ? SyS_exit_group+0x14/0x20
   > [  493.567249]  [<ffffffff8107ee5a>] kthread+0xca/0xe0
   > [  493.567250]  [<ffffffff8107ed90>] ? kthread_park+0x60/0x60
   > [  493.567252]  [<ffffffff815e8752>] ret_from_fork+0x22/0x30
   > [  493.567254] INFO: task iscsi_trx:4149 blocked for more than 120
   seconds.
   > [  493.567255]       Tainted: G           OE   4.9.0-For-DSGL-Debug+ #1
   > [  493.567256] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
   disables this message.
   > [  493.567256] iscsi_trx       D    0  4149      2 0x00000084
   > [  493.567258]  0000000000000000 ffff882f5ef70340 ffff882f76253040
   ffff88302de40340
   > [  493.567259]  ffff88303e097a40 ffffc90000f93c90 ffffffff815e415b
   ffffffff815e56c2
   > [  493.567261]  0000000000000001 ffff882f5ef70340 7fffffffffffffff
   ffff882d233cc9b0
   > [  493.567262] Call Trace:
   > [  493.567264]  [<ffffffff815e415b>] ? __schedule+0x23b/0x6c0
   > [  493.567265]  [<ffffffff815e56c2>] ? wait_for_completion+0xd2/0xf0
   > [  493.567267]  [<ffffffff815e4616>] schedule+0x36/0x80
   > [  493.567268]  [<ffffffff815e71c3>] schedule_timeout+0x1f3/0x390
   > [  493.567281]  [<ffffffffa118e910>] ? ib_sg_to_pages+0x1a0/0x1a0
   [ib_core]
   > [  493.567285]  [<ffffffffa118e910>] ? ib_sg_to_pages+0x1a0/0x1a0
   [ib_core]
   > [  493.567286]  [<ffffffff815e56a4>] wait_for_completion+0xb4/0xf0
   > [  493.567287]  [<ffffffff8108a6b0>] ? wake_up_q+0x80/0x80
   > [  493.567302]  [<ffffffffa04d5399>]
   target_wait_for_sess_cmds+0x49/0x1a0 [target_core_mod]
   > [  493.567306]  [<ffffffffa0471644>] isert_wait_conn+0x1a4/0x2d0
   [ib_isert]
   > [  493.567311]  [<ffffffffa05289ab>] iscsit_close_connection+0x14b/0x820
   [iscsi_target_mod]
   > [  493.567315]  [<ffffffffa05172ef>]
   iscsit_take_action_for_connection_exit+0x7f/0x100 [iscsi_target_mod]
   > [  493.567320]  [<ffffffffa0528265>] iscsi_target_rx_thread+0x95/0xa0
   [iscsi_target_mod]
   > [  493.567324]  [<ffffffffa05281d0>] ?
   iscsi_target_tx_thread+0x1b0/0x1b0 [iscsi_target_mod]
   > [  493.567325]  [<ffffffff8107ee5a>] kthread+0xca/0xe0

   > [  493.567327]  [<ffffffff8107ed90>] ? kthread_park+0x60/0x60
   > [  493.567328]  [<ffffffff815e8752>] ret_from_fork+0x22/0x30
   >

   OK, AFAICT these hung tasks basically mean iser-target never gave
   target-core back the outstanding se_cmd it was attempting to retry, even
   up to the point in which session reinstatement was eventually triggered
   by iser-initiator.

So the reason why your patch to swap post_recv -> post_send to post_send -> post_recv makes a difference is because it allows enough trickle of RDMA_WRITEs to make it through, where iser-initiator doesn't attempt to escalate recovery and doesn't attempt session reinstatement.

Have you been able to confirm with your incremental patch below that once TMR ABORT_TASKs start to occur due to isert_rdma_rw_ctx_post failures, that any subsequent session reinstatement events for unrelated reasons (or explicit logout..?) doesn't run into the same issue..?

Quoted 2 lines

-> In order to address this I tried the following (experimental) change

on top of your 3 patches:

Review

Quoted 2 lines

(quoted diff) +0 -0

b/drivers/infiniband/ulp/isert/ib_isert.c

drivers/infiniband/ulp/isert/ib_isert.c isert_post_response(struct isert_conn

Quoted 4 lines

index 501a0ad124a7..0aead5faa2a2 100644

drivers/infiniband/ulp/isert/ib_isert.c +0 -0

@@ -1817,16 +1817,16 @@ isert_post_response(struct isert_conn

*isert_conn, struct isert_cmd *isert_cmd)

drivers/infiniband/ulp/isert/ib_isert.c isert_put_datain(struct iscsi_conn *conn, struct

Quoted 22 lines

drivers/infiniband/ulp/isert/ib_isert.c +5 -5

          struct ib_send_wr *wr_failed;
          int ret;
 
-       ret = isert_post_recv(isert_conn, isert_cmd->rx_desc);
+       ret = ib_post_send(isert_conn->qp, &isert_cmd->tx_desc.send_wr,
+                          &wr_failed);
          if (ret) {
-               isert_err("ib_post_recv failed with %d\n", ret);
+               isert_err("ib_post_send failed with %d\n", ret);
                  return ret;
          }
 
-       ret = ib_post_send(isert_conn->qp, &isert_cmd->tx_desc.send_wr,
-                          &wr_failed);
+       ret = isert_post_recv(isert_conn, isert_cmd->rx_desc);
          if (ret) {
-               isert_err("ib_post_send failed with %d\n", ret);
+               isert_err("ib_post_recv failed with %d\n", ret);
                  return ret;
          }
          return ret;

@@ -2166,6 +2166,13 @@ isert_put_datain(struct iscsi_conn *conn, struct

iscsi_cmd *cmd)

drivers/infiniband/ulp/isert/ib_isert.c isert_put_datain(struct iscsi_conn *conn, struct iscsi_cmd *cmd)

Quoted 5 lines

drivers/infiniband/ulp/isert/ib_isert.c +2 -0

          if (isert_prot_cmd(isert_conn, se_cmd)) {
                  isert_cmd->tx_desc.tx_cqe.done = isert_rdma_write_done;
                  cqe = &isert_cmd->tx_desc.tx_cqe;
+
+               rc = isert_rdma_rw_ctx_post(isert_cmd, isert_conn, cqe,

   chain_wr);
   > +               if (rc) {
   > +                       isert_dbg("Cmd: %p posted RDMA_WRITE for iSER
   Data READ rc: %d\n",
   > +                                  isert_cmd, rc);
   > +                       return rc;
   > +               }
   >         } else {
   >                 /*
   >                  * Build isert_conn->tx_desc for iSCSI response PDU and
   attach
   > @@ -2178,18 +2185,21 @@ isert_put_datain(struct iscsi_conn *conn, struct
   iscsi_cmd *cmd)
   >                 isert_init_send_wr(isert_conn, isert_cmd,
   >                                    &isert_cmd->tx_desc.send_wr);
   >
   > +               chain_wr = &isert_cmd->tx_desc.send_wr;
   > +
   > +               rc = isert_rdma_rw_ctx_post(isert_cmd, isert_conn, cqe,
   chain_wr);
   > +               if (rc) {
   > +                       isert_err("Cmd: %p posted RDMA_WRITE for iSER
   Data READ rc: %d\n",
   > +                                  isert_cmd, rc);
   > +                       return rc;
   > +               }
   > +
   >                 rc = isert_post_recv(isert_conn, isert_cmd->rx_desc);
   >                 if (rc) {
   >                         isert_err("ib_post_recv failed with %d\n", rc);
   >                         return rc;
   >                 }
   > -
   > -               chain_wr = &isert_cmd->tx_desc.send_wr;
   >         }
   > -       rc = isert_rdma_rw_ctx_post(isert_cmd, isert_conn, cqe,
   chain_wr);
   > -       isert_dbg("Cmd: %p posted RDMA_WRITE for iSER Data READ rc:

   %d\n",
   > -                  isert_cmd, rc);
   > -
   >         return rc;
   >  }
   >

   Unsure of the implications for other RNICs + iser-target here..

I'll have to defer to Sagi judgment on this one.  ;)

drivers/infiniband/ulp/isert/ib_isert.c isert_put_datain(struct iscsi_conn *conn, struct · line 2169

Quoted 1 line

drivers/infiniband/ulp/isert/ib_isert.c +0 -1

-> With these changes it works fine, But I still see few Aborts

intermittently as follows:

Quoted 2 lines

[10674.434643] isert: isert_rdma_rw_ctx_post: Cmd: ffff882cbb961138

failed to post RDMA res

Quoted 1 line

[10674.434690] isert: isert_rdma_rw_ctx_post: Cmd: ffff882cbb9434c0

failed to post RDMA res

Quoted 3 lines

[10715.186372] ABORT_TASK: Found referenced iSCSI task_tag: 58
[10715.186417] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 58

OK, so there is still a delay between the isert_rdma_rw_ctx_post failures, and receiving TMR ABORT_TASKs.

Is target-core -> iser-target aggressively retrying the posting of RDMA_WRITEs via isert_put_datain() during this entire time..?

Quoted 1 line

-> Apart from the Aborts and post failure logs filling dmesg, luns are

in state "running" and

Quoted 11 lines

fio countinues to run.
[root@bharat ~]# iscsiadm -m session -P3 | grep "Attached scsi disk" Attached scsi disk sdj          State: running Attached scsi disk sdc          State: running Attached scsi disk sdd          State: running Attached scsi disk sde          State: running Attached scsi disk sdf          State: running Attached scsi disk sdg          State: running Attached scsi disk sdh          State: running Attached scsi disk sdi          State: running

Ok, so it looks like you've got the second order issues under control for target-core + iser-target, once the first order issue of RDMA R/W API vs. iw_cxgb4 WR resource mis-sizing continuously triggers failed calls to isert_put_datain() -> isert_rdma_rw_ctx_post() rdma_rw_ctx_post().

That said, I'm going to go ahead and queue patch #1 and #2 from the original series to target-pending/for-next as they do address issues separate from iser-target scenario here, and await on Sagi's feedback for patch #3 and your incremental above.

Thanks again.

References

Visible links
1. https://www.spinics.net/lists/target-devel/msg13571.html

Hi Nicholas,
I see them from 2MB onwards.

Quoted 5 lines

Quoted 4 lines

Here is what I see with the 3 patches alone applied:

-> In isert_put_datain() and isert_post_response() a corresponding recv

WR is posted before

Quoted 8 lines

Quoted 1 line

posting a send and hence for every post failure a recv is already posted

into a tightly packed

Quoted 1 line

RQ, causing it to overflow.

Just for me to understand, the intermittent TMR ABORT_TASKs are caused by the repeated failure to post RDMA_WRITE WRs for a large ISER Data-In payload, due to mis-sizing of needed WRs from RDMA R/W API vs. underlying hardware capabilities.

Yes.

Quoted 4 lines

Moving the recv posts after the send post for RDMA_WRITEs helps to reduce the severity of the issue with iw_cxgb4, but doesn't completely eliminate the issue under load.

Moving recv posts only comes in to effect along with your changes.

Quoted 4 lines

So the reason why your patch to swap post_recv -> post_send to post_send -> post_recv makes a difference is because it allows enough trickle of RDMA_WRITEs to make it through, where iser-initiator doesn't attempt to escalate recovery and doesn't attempt session reinstatement.

I dont exactly know if above thing comes into play but the actual reason I did swap posting RQ and SQ is, unlike SQ, RQ is posted with WRs to the brim during the intialisation itself. From thereon we post a RQ WR for every RQ completion That makes it almost full at any point of time.

Now in our scenario, SQ is miscalulated and too small for few adapters and so filled gradually as the IO starts. Once SQ is full, according to your patches isert queues it and tries to repost the command again. Here in iser functions like isert_post_response(), isert_put_datain() post send is done after post recv. For the first post send failure in say isert_put_datain(), the corresponding post recv is already posted, then on queuing the command and trying reposting an extra recv is again posted which fills up the RQ also.

By swapping post recv and send as in my incermental patch, we dont post that
extra recv, and post recv only on successful post send.
Therfore I think this incremental patch is necessary.

Hi Baharat and Nic,

Apologies for the late reply,

Quoted 6 lines

Hi Nicholas,
I see them from 2MB onwards.

Quoted 4 lines

    > Here is what I see with the 3 patches alone applied:
    >
    > -> In isert_put_datain() and isert_post_response() a corresponding

recv

Quoted 2 lines

Quoted 2 lines

    WR is posted before
    > posting a send and hence for every post failure a recv is already

posted

Quoted 4 lines

Quoted 4 lines

    into a tightly packed
    > RQ, causing it to overflow.

    Just for me to understand, the intermittent TMR ABORT_TASKs are

caused

Quoted 1 line

Quoted 1 line

    by the repeated failure to post RDMA_WRITE WRs for a large ISER

Data-In

Quoted 6 lines

Quoted 2 lines

    payload, due to mis-sizing of needed WRs from RDMA R/W API vs. underlying hardware capabilities.

Yes.

Quoted 3 lines

    Moving the recv posts after the send post for RDMA_WRITEs helps to reduce the severity of the issue with iw_cxgb4, but doesn't

completely

Quoted 2 lines

Quoted 1 line

    eliminate the issue under load.

Moving recv posts only comes in to effect along with your changes.

...

Quoted 1 line

Quoted 1 line

    So the reason why your patch to swap post_recv -> post_send to

post_send

Quoted 1 line

Quoted 1 line

    -> post_recv makes a difference is because it allows enough trickle

of

Quoted 1 line

Quoted 1 line

    RDMA_WRITEs to make it through, where iser-initiator doesn't attempt

to

Quoted 2 lines

Quoted 1 line

    escalate recovery and doesn't attempt session reinstatement.

I dont exactly know if above thing comes into play but the actual reason

I did

Quoted 1 line

swap posting RQ and SQ is, unlike SQ, RQ is posted with WRs to the brim

during

Quoted 1 line

the intialisation itself. From thereon we post a RQ WR for every RQ

completion

Quoted 3 lines

That makes it almost full at any point of time.

Now in our scenario, SQ is miscalulated and too small for few adapters

and so

Quoted 1 line

filled gradually as the IO starts. Once SQ is full, according to your

patches

Quoted 1 line

isert queues it and tries to repost the command again. Here in iser

functions

Quoted 1 line

like isert_post_response(), isert_put_datain() post send is done after

post recv.

Quoted 1 line

For the first post send failure in say isert_put_datain(), the

corresponding

Quoted 1 line

post recv is already posted, then on queuing the command and trying

reposting

Quoted 3 lines

an extra recv is again posted which fills up the RQ also.

  By swapping post recv and send as in my incermental patch, we dont post

that

Quoted 2 lines

extra recv, and post recv only on successful post send. Therfore I think this incremental patch is necessary.

Reversing the order to recv and send posting will cause problems in stress IO workloads (especially for iWARP). The problem of sending a reply before reposting the recv buffer is that the initiator can send immediately a new request and we don't have a recv buffer waiting for it, which will cause RNR-NAK. This *will* cause performance drops and jitters for sure.

   How about we just track the rx_desc to know if we already posted it as
   a start (untested as I don't have access to RDMA HW this week):
   --
   diff --git a/drivers/infiniband/ulp/isert/ib_isert.c
   b/drivers/infiniband/ulp/isert/ib_isert.c
   index 9b33c0c97468..fcbed35e95a8 100644
   --- a/drivers/infiniband/ulp/isert/ib_isert.c
   +++ b/drivers/infiniband/ulp/isert/ib_isert.c
   @@ -817,6 +817,7 @@ isert_post_recvm(struct isert_conn *isert_conn, u32
   count)
                    rx_wr->sg_list = &rx_desc->rx_sg;
                    rx_wr->num_sge = 1;
                    rx_wr->next = rx_wr + 1;
   +               rx_desc->in_use = false;
            }
            rx_wr--;
            rx_wr->next = NULL; /* mark end of work requests list */
   @@ -835,6 +836,15 @@ isert_post_recv(struct isert_conn *isert_conn,
   struct iser_rx_desc *rx_desc)
            struct ib_recv_wr *rx_wr_failed, rx_wr;
            int ret;

   +       if (!rx_desc->in_use) {
   +               /*
   +                * if the descriptor is not in-use we already reposted it
   +                * for recv, so just silently return
   +                */
   +               return 0;
   +       }
   +
   +       rx_desc->in_use = false;
            rx_wr.wr_cqe = &rx_desc->rx_cqe;
            rx_wr.sg_list = &rx_desc->rx_sg;
            rx_wr.num_sge = 1;
   @@ -1397,6 +1407,8 @@ isert_recv_done(struct ib_cq *cq, struct ib_wc *wc)
                    return;
            }

   +       rx_desc->in_use = true;
   +
            ib_dma_sync_single_for_cpu(ib_dev, rx_desc->dma_addr,
                            ISER_RX_PAYLOAD_SIZE, DMA_FROM_DEVICE);

   diff --git a/drivers/infiniband/ulp/isert/ib_isert.h
   b/drivers/infiniband/ulp/isert/ib_isert.h
   index c02ada57d7f5..87d994de8c91 100644
   --- a/drivers/infiniband/ulp/isert/ib_isert.h
   +++ b/drivers/infiniband/ulp/isert/ib_isert.h
   @@ -60,7 +60,7 @@

     #define ISER_RX_PAD_SIZE       (ISCSI_DEF_MAX_RECV_SEG_LEN + 4096 - \
                    (ISER_RX_PAYLOAD_SIZE + sizeof(u64) + sizeof(struct
   ib_sge) + \
   -                sizeof(struct ib_cqe)))
   +                sizeof(struct ib_cqe) + sizeof(bool)))

     #define ISCSI_ISER_SG_TABLESIZE                256

   @@ -85,6 +85,7 @@ struct iser_rx_desc {
            u64             dma_addr;
            struct ib_sge   rx_sg;
            struct ib_cqe   rx_cqe;
   +       bool            in_use;
            char            pad[ISER_RX_PAD_SIZE];
     } __packed;
   --

We have a lot of room for cleanups in isert... I'll need to make some time to get it going...

I'll be waiting to hear from you if it makes your issue go away.

Cheers,
Sagi.

Test runs fine and it solved the issue.
Thanks for the patch!

Quoted 2 lines

Test runs fine and it solved the issue.
Thanks for the patch!

Cool, can I add your "Tested-by" tag on a formal patch then?

--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in the body of a message to [email protected] More majordomo info at  [1]http://vger.kernel.org/majordomo-info.html

References

Visible links
1. http://vger.kernel.org/majordomo-info.html