stuck iscsi/iser target with linux-4.15.0-rc1

stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

Hey, while working on some changes in the cxgb4 qp_drain functionality, I
encountered this stall.  To reproduce it, I attach 2 ram disks via iser over
cxgb4 and run an fio test.  While the test is running, I tear down the target
stack with 'targetcli clearconfig true'

While this could be something with my qp_drain logic, I don't see that in these
stuck threads.  Has anybody seen this?  

Thanks

Steve.

---

[ 1107.205467] INFO: task iscsi_trx:9901 blocked for more than 120 seconds.
[ 1107.221177]       Tainted: G        W        4.15.0-rc1-drain-flush-fix+ #8
[ 1107.237174] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 1107.254109] iscsi_trx       D    0  9901      2 0x80000084
[ 1107.268775] Call Trace:
[ 1107.280341]  ? __schedule+0x28d/0x870
[ 1107.293129]  schedule+0x32/0x80
[ 1107.305381]  schedule_timeout+0x1d4/0x2f0
[ 1107.318529]  ? ib_sg_to_pages+0x1a0/0x1a0 [ib_core]
[ 1107.332554]  wait_for_completion+0x123/0x190
[ 1107.345965]  ? wake_up_q+0x70/0x70
[ 1107.358526]  target_wait_for_sess_cmds+0x41/0x180 [target_core_mod]
[ 1107.373826]  isert_wait_conn+0x1bd/0x320 [ib_isert]
[ 1107.387559]  iscsit_close_connection+0x155/0x8e0 [iscsi_target_mod]
[ 1107.402604]  ? wait_for_completion_interruptible+0x16f/0x1c0
[ 1107.416966]  ? wake_up_q+0x70/0x70
[ 1107.428926]  iscsit_take_action_for_connection_exit+0x7e/0x100
[iscsi_target_mod]
[ 1107.445049]  iscsi_target_rx_thread+0xdc/0xf0 [iscsi_target_mod]
[ 1107.459636]  kthread+0xf5/0x130
[ 1107.471236]  ? iscsi_target_tx_thread+0x1f0/0x1f0 [iscsi_target_mod]
[ 1107.486060]  ? kthread_associate_blkcg+0x90/0x90
[ 1107.499068]  ret_from_fork+0x1f/0x30
[ 1107.510902] INFO: task targetcli:9913 blocked for more than 120 seconds.
[ 1107.525915]       Tainted: G        W        4.15.0-rc1-drain-flush-fix+ #8
[ 1107.541170] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 1107.557317] targetcli       D    0  9913   9750 0x00000080
[ 1107.571126] Call Trace:
[ 1107.581750]  ? __schedule+0x28d/0x870
[ 1107.593499]  schedule+0x32/0x80
[ 1107.604578]  schedule_timeout+0x1d4/0x2f0
[ 1107.616433]  ? signal_wake_up_state+0x15/0x30
[ 1107.628515]  wait_for_completion+0x123/0x190
[ 1107.640367]  ? wake_up_q+0x70/0x70
[ 1107.651248]  iscsit_cause_connection_reinstatement+0x95/0xe0
[iscsi_target_mod]
[ 1107.666102]  iscsit_free_session+0x100/0x160 [iscsi_target_mod]
[ 1107.679489]  iscsit_release_sessions_for_tpg+0x18b/0x200 [iscsi_target_mod]
[ 1107.693909]  iscsit_tpg_disable_portal_group+0xc1/0x1c0 [iscsi_target_mod]
[ 1107.708180]  lio_target_tpg_enable_store+0x65/0xe0 [iscsi_target_mod]
[ 1107.721984]  configfs_write_file+0xa3/0x100
[ 1107.733431]  __vfs_write+0x33/0x170
[ 1107.744056]  ? handle_mm_fault+0xc4/0x1d0
[ 1107.755084]  ? _cond_resched+0x15/0x30
[ 1107.765748]  vfs_write+0xad/0x1a0
[ 1107.775832]  SyS_write+0x52/0xc0
[ 1107.785683]  do_syscall_64+0x61/0x1a0
[ 1107.795865]  entry_SYSCALL64_slow_path+0x25/0x25
[ 1107.806931] RIP: 0033:0x7f967db18c60
[ 1107.816850] RSP: 002b:00007ffdce1705e8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[ 1107.830847] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007f967db18c60
[ 1107.844408] RDX: 0000000000000001 RSI: 00007f967ec76000 RDI: 0000000000000003
[ 1107.857898] RBP: 00007f967ec76000 R08: 0000000001e0abb0 R09: 00007f967ecfa740
[ 1107.871311] R10: 00007f967eae05f0 R11: 0000000000000246 R12: 0000000001e0aad0
[ 1107.884703] R13: 0000000000000001 R14: 00000000018440a0 R15: 00007f967eaaaf00

--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: stuck iscsi/iser target with linux-4.15.0-rc1

[Sagi Grimberg]

Hey Steve,

> Hey, while working on some changes in the cxgb4 qp_drain functionality, I
> encountered this stall.  To reproduce it, I attach 2 ram disks via iser over
> cxgb4 and run an fio test.  While the test is running, I tear down the target
> stack with 'targetcli clearconfig true'
> 
> While this could be something with my qp_drain logic, I don't see that in these
> stuck threads.  Has anybody seen this?

Not for a while, can you turn the debug prints in
target_wait_for_sess_cmds so we can understand which commands are
hanging?
--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> 
> Hey Steve,
> 
> > Hey, while working on some changes in the cxgb4 qp_drain functionality, I
> > encountered this stall.  To reproduce it, I attach 2 ram disks via iser over
> > cxgb4 and run an fio test.  While the test is running, I tear down the target
> > stack with 'targetcli clearconfig true'
> >
> > While this could be something with my qp_drain logic, I don't see that in these
> > stuck threads.  Has anybody seen this?
> 
> Not for a while, can you turn the debug prints in
> target_wait_for_sess_cmds so we can understand which commands are
> hanging?

Here ya go:

[239800.115739] target_wait_for_sess_cmds: Waiting for se_cmd: ffff88034082c998 t_state: 6, fabric state: 12


--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: stuck iscsi/iser target with linux-4.15.0-rc1

[Sagi Grimberg]

>> Not for a while, can you turn the debug prints in
>> target_wait_for_sess_cmds so we can understand which commands are
>> hanging?
> 
> Here ya go:
> 
> [239800.115739] target_wait_for_sess_cmds: Waiting for se_cmd: ffff88034082c998 t_state: 6, fabric state: 12

Hmm, this means that the command was delegated to isert to send
data+response... Which means we lose a reference put somewhere here.

I'm assuming that this happens before your changes to ib_drain_qp
correct? If this does not happen without your changes it might indicate
that drain_qp is missing an error (or successful?) completion which
would prevent a final reference drop (isert_completion_put).

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> > [239800.115739] target_wait_for_sess_cmds: Waiting for se_cmd:
> ffff88034082c998 t_state: 6, fabric state: 12
> 
> Hmm, this means that the command was delegated to isert to send
> data+response... Which means we lose a reference put somewhere here.
> 
> I'm assuming that this happens before your changes to ib_drain_qp
> correct? If this does not happen without your changes it might indicate
> that drain_qp is missing an error (or successful?) completion which
> would prevent a final reference drop (isert_completion_put).

Hey Sagi, I'm trying to reproduce this on CX4 cards with mlx5.  I have the two nodes setup via RoCEv2 and rping works over mlx5 fine, but when I try to discover the iSER targets, the initiator fails with:

[root@potato1 ~]# iscsiadm -m discovery -t sendtargets -p 172.16.99.239:3260 -I iser
iscsiadm: recv's end state machine bug?
iscsiadm: Could not perform SendTargets discovery: iSCSI PDU timed out
[root@potato1 ~]# uname -r
4.15.0-rc3+

And the target logs this:

[  873.240460] mlx5_0:dump_cqe:277:(pid 494): dump error cqe
[  873.246665] 00000000 00000000 00000000 00000000
[  873.251942] 00000000 00000000 00000000 00000000
[  873.257214] 00000000 00000000 00000000 00000000
[  873.262472] 00000000 00008a12 0a0000f6 00014bd2
[  873.267711] isert: isert_print_wc: send failure: invalid request error (9) vend_err 8a

Any ideas?  I'm using straight 4.15.0-rc3 + a workaround to avoid crashing my x86 systems at bootup from here:

https://www.mail-archive.com/netdev-u79uwXL29TY76Z2rM5mHXA@public.gmane.org/msg203210.html'

Steve.
Thanks,

Steve.



---
This email has been checked for viruses by AVG.
http://www.avg.com

--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> > > [239800.115739] target_wait_for_sess_cmds: Waiting for se_cmd:
> > ffff88034082c998 t_state: 6, fabric state: 12
> >
> > Hmm, this means that the command was delegated to isert to send
> > data+response... Which means we lose a reference put somewhere here.
> >
> > I'm assuming that this happens before your changes to ib_drain_qp
> > correct? If this does not happen without your changes it might indicate
> > that drain_qp is missing an error (or successful?) completion which
> > would prevent a final reference drop (isert_completion_put).
> 
> Hey Sagi, I'm trying to reproduce this on CX4 cards with mlx5.  I have the two
> nodes setup via RoCEv2 and rping works over mlx5 fine, but when I try to
> discover the iSER targets, the initiator fails with:
> 
> [root@potato1 ~]# iscsiadm -m discovery -t sendtargets -p 172.16.99.239:3260
> -I iser
> iscsiadm: recv's end state machine bug?
> iscsiadm: Could not perform SendTargets discovery: iSCSI PDU timed out
> [root@potato1 ~]# uname -r
> 4.15.0-rc3+
> 
> And the target logs this:
> 
> [  873.240460] mlx5_0:dump_cqe:277:(pid 494): dump error cqe
> [  873.246665] 00000000 00000000 00000000 00000000
> [  873.251942] 00000000 00000000 00000000 00000000
> [  873.257214] 00000000 00000000 00000000 00000000
> [  873.262472] 00000000 00008a12 0a0000f6 00014bd2
> [  873.267711] isert: isert_print_wc: send failure: invalid request error (9)
> vend_err 8a
> 
> Any ideas?  I'm using straight 4.15.0-rc3 + a workaround to avoid crashing my
> x86 systems at bootup from here:
> 
> https://www.mail-archive.com/netdev@vger.kernel.org/msg203210.html'
> 

I tried with 4.14.0 and got the same results.  I then backed up to 4.9.44 and I can discovery/login again.  I'll see if I can bisect this out, unless somebody knows about current problems with iser?




---
This email has been checked for viruses by AVG.
http://www.avg.com

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> 
> I tried with 4.14.0 and got the same results.  I then backed up to 4.9.44 and I can
> discovery/login again.  I'll see if I can bisect this out, unless somebody knows
> about current problems with iser?

Actually, 4.9.44 has the same issue.  It works with iscsi/tcp, not iser. I must be doing something wrong in my setup.  


---
This email has been checked for viruses by AVG.
http://www.avg.com

--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: stuck iscsi/iser target with linux-4.15.0-rc1

[Max Gurtovoy]

hi Steve,

On 12/14/2017 12:35 AM, Steve Wise wrote:
>>
>> I tried with 4.14.0 and got the same results.  I then backed up to 4.9.44 and I can
>> discovery/login again.  I'll see if I can bisect this out, unless somebody knows
>> about current problems with iser?
> 
> Actually, 4.9.44 has the same issue.  It works with iscsi/tcp, not iser. I must be doing something wrong in my setup.

can you run "targetcli ls" on your target side ?
also "iscsiadm -V" on the initiator side ?
can you try running with ib link layer ?

I'll try to find similar setup to repro in our labs.

> 
> 
> ---
> This email has been checked for viruses by AVG.
> https://emea01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwww.avg.com&data=02%7C01%7Cmaxg%40mellanox.com%7C30b666b3fb324c3e678608d54279df3e%7Ca652971c7d2e4d9ba6a4d149256f461b%7C0%7C0%7C636488013569543438&sdata=w2S1quZYnMQmzXuQJuRvdEJBvyCGQ9Fbm6MGOrRD6Pw%3D&reserved=0
> 
> --
> To unsubscribe from this list: send the line "unsubscribe target-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  https://emea01.safelinks.protection.outlook.com/?url=http%3A%2F%2Fvger.kernel.org%2Fmajordomo-info.html&data=02%7C01%7Cmaxg%40mellanox.com%7C30b666b3fb324c3e678608d54279df3e%7Ca652971c7d2e4d9ba6a4d149256f461b%7C0%7C0%7C636488013569543438&sdata=cf3SNf3pqSvPKz4xkQSzUS8r4I3AY7%2Bj5EYmI5khDP4%3D&reserved=0
> 

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> 
> hi Steve,
> 
> On 12/14/2017 12:35 AM, Steve Wise wrote:
> >>
> >> I tried with 4.14.0 and got the same results.  I then backed up to 4.9.44 and I
> can
> >> discovery/login again.  I'll see if I can bisect this out, unless somebody knows
> >> about current problems with iser?
> >
> > Actually, 4.9.44 has the same issue.  It works with iscsi/tcp, not iser. I must be
> doing something wrong in my setup.
> 
> can you run "targetcli ls" on your target side ?
> also "iscsiadm -V" on the initiator side ?
> can you try running with ib link layer ?
> 
> I'll try to find similar setup to repro in our labs.

Hi Max, I'm setting this up on other systems at the moment.  If I can reproduce any of this, I'll reply with more details.

Thanks!

Steve.



---
This email has been checked for viruses by AVG.
http://www.avg.com

--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> > [239800.115739] target_wait_for_sess_cmds: Waiting for se_cmd:
> ffff88034082c998 t_state: 6, fabric state: 12
> 
> Hmm, this means that the command was delegated to isert to send
> data+response... Which means we lose a reference put somewhere here.
> 
> I'm assuming that this happens before your changes to ib_drain_qp
> correct? If this does not happen without your changes it might indicate
> that drain_qp is missing an error (or successful?) completion which
> would prevent a final reference drop (isert_completion_put).

The issue doesn't happen on 4.15-rc4 with mlx4, but it does with cxgb4.  There have been some bad problems with cxgb4's drain logic, so I need to just root cause this, because backing up to see if it used to work is problematic and will hit other issues with drain.  The qp does get drained, and I confirmed it has no pending send or recv wrs.  The associated cq's last 2 completions are from the ib_drain_qp() logic, so I need to somehow determine what completion got lost/dropped/whatever. 

Do you have any thoughts on debugging this?  Turning on isert debug is bad because the IO load is very high.  I sort of need something that I can do after it gets stuck.  So I can change the wait_for_completion() to a wait_for_completion_timeout() and if it times out, go figure out what it is stuck on.  



---
This email has been checked for viruses by AVG.
http://www.avg.com

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> 
> Do you have any thoughts on debugging this?  Turning on isert debug is bad
> because the IO load is very high.  I sort of need something that I can do after it
> gets stuck.  So I can change the wait_for_completion() to a
> wait_for_completion_timeout() and if it times out, go figure out what it is stuck
> on.

This snipit from isert_put_cmd() looks interesting:

...
                        /*
                         * Check for special case during comp_err where
                         * WRITE_PENDING has been handed off from core,
                         * but requires an extra target_put_sess_cmd()
                         * before transport_generic_free_cmd() below.
                         */
                        if (comp_err &&
                            cmd->se_cmd.t_state == TRANSPORT_WRITE_PENDING) {
                                struct se_cmd *se_cmd = &cmd->se_cmd;

                                target_put_sess_cmd(se_cmd);
                        }
...


---
This email has been checked for viruses by AVG.
http://www.avg.com

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> 
> >
> > Do you have any thoughts on debugging this?  Turning on isert debug is bad
> > because the IO load is very high.  I sort of need something that I can do after it
> > gets stuck.  So I can change the wait_for_completion() to a
> > wait_for_completion_timeout() and if it times out, go figure out what it is
> stuck
> > on.
> 
> This snipit from isert_put_cmd() looks interesting:
> 
> ...
>                         /*
>                          * Check for special case during comp_err where
>                          * WRITE_PENDING has been handed off from core,
>                          * but requires an extra target_put_sess_cmd()
>                          * before transport_generic_free_cmd() below.
>                          */
>                         if (comp_err &&
>                             cmd->se_cmd.t_state == TRANSPORT_WRITE_PENDING) {
>                                 struct se_cmd *se_cmd = &cmd->se_cmd;
> 
>                                 target_put_sess_cmd(se_cmd);
>                         }
> ...

Hey Sagi, 

I found my bug: If a wr chain is posted to iw_cxgb4  and needs to be flushed, only the first wr in the chain was being flushed.  The rest never completed.  This completion leak was causing the failure to deref IO commands...

Steve.





---
This email has been checked for viruses by AVG.
http://www.avg.com

--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: stuck iscsi/iser target with linux-4.15.0-rc1

[Sagi Grimberg]

> Hey Sagi,
> 
> I found my bug: If a wr chain is posted to iw_cxgb4  and needs to be flushed, only the first wr in the chain was being flushed.  The rest never completed.  This completion leak was causing the failure to deref IO commands...

Good to know,

Do does any of the other discussions in the thread still apply? Anything
that I still need to look at?
--
To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: stuck iscsi/iser target with linux-4.15.0-rc1

[Steve Wise]

> 
> 
> > Hey Sagi,
> >
> > I found my bug: If a wr chain is posted to iw_cxgb4  and needs to be flushed,
> only the first wr in the chain was being flushed.  The rest never completed.  This
> completion leak was causing the failure to deref IO commands...
> 
> Good to know,
> 
> Do does any of the other discussions in the thread still apply? Anything
> that I still need to look at?

At this point, no. 

Thanks for hanging in there with me. :)

Steve.