Re: iscsi_trx going into D state
- Original Message - > From: "Robert LeBlanc" > To: "Laurence Oberman" > Cc: "Doug Ledford" , "Nicholas A. Bellinger" > , "Zhu Lingshan" > , "linux-rdma" , > linux-scsi@vger.kernel.org, "Sagi Grimberg" > , "Christoph Hellwig" > Sent: Friday, January 13, 2017 6:38:33 PM > Subject: Re: iscsi_trx going into D state > > Laurance, > > I'm really starting to think that the stars aligned with the phase of > the moon or something when I reproduced this in my lab before because > I've been unable to reproduce it on Infiniband the last two days. The > problem with this issue is that it is so hard to trigger, but causes a > lot of problems when it does happen. I really hate wasting people's > time when I can't reproduce it myself reliably. Please don't waste too > much time if you can't get it reproduced on Infiniband, I'll have to > wait until someone with the ConnectX-4-LX cards can replicate it. > > Hmmm you do have ConnectX-4 cards which may have the same bug it > Ethernet mode. I don't see the RoCE bug on my ConnectX-3 cards, but > your ConnectX-4 cards may work. Try putting the cards into Ethernet > mode, set the speed and advertised speed to something lower than the > max speed and verify that the link speed is that (ethtool). On the > ConnectX-4-LX cards, I just had to set both interfaces down and then > back up at the same time, on the ConnectX-3 I had to pull the cable > (shutting down the client might have worked). Then set up target and > client with iSER, format and run the test and it should trigger > automatically. > > Looking at release notes on the ConnectX-4-LX cards, the latest > firmware may fix the bug that so easily exposes the problem with that > card. My cards are SuperMicro branded cards and don't have the new > firmware available yet. > > Good luck. > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Fri, Jan 13, 2017 at 8:10 AM, Laurence Oberman > wrote: > > > > > > - Original Message - > >> From: "Robert LeBlanc" > >> To: "Laurence Oberman" > >> Cc: "Doug Ledford" , "Nicholas A. Bellinger" > >> , "Zhu Lingshan" > >> , "linux-rdma" , > >> linux-scsi@vger.kernel.org, "Sagi Grimberg" > >> , "Christoph Hellwig" > >> Sent: Thursday, January 12, 2017 4:26:05 PM > >> Subject: Re: iscsi_trx going into D state > >> > >> Sorry sent prematurely... > >> > >> On Thu, Jan 12, 2017 at 2:22 PM, Robert LeBlanc > >> wrote: > >> > I'm having trouble replicating the D state issue on Infiniband (I was > >> > able to trigger it reliably a couple weeks back, I don't know if OFED > >> > to verify the same results happen there as well. > >> > >> I'm having trouble replicating the D state issue on Infiniband (I was > >> able to trigger it reliably a couple weeks back, I don't know if OFED > >> being installed is altering things but it only installed for 3.10. The > >> ConnectX-4-LX exposes the issue easily if you have those cards.) to > >> verify the same results happen there as well. > >> > >> > >> Robert LeBlanc > >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > >> -- > >> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in > >> the body of a message to majord...@vger.kernel.org > >> More majordomo info at http://vger.kernel.org/majordomo-info.html > >> > > > > I am only back in the office next Wednesday. > > I have this all setup using ConnectX-4 with IB/ISER but have no way of > > remotely creating the disconnect as I currently have it back-to-back. > > Have run multiple tests with IB and ISER hard resting the client to break > > the IB connection but have not been able to reproduce as yet. > > So it will have to wait until I can pull cables next week as that seemed to > > be the way you have been reproducing this. > > > > This is in a code area I also don't have a lot of knowledge of the flow but > > have started trying to understand it better. > > > > Thanks > > Laurence > > > -- > To unsubscribe from this list: send the line "unsubscribe linux-scsi" in > the body of a message to majord...@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Hello Robert I will try this sometime tomorrow by running in ethernet mode. Its been days of resets with no reproduction so I agree, very hard ro trproduce with Infiniband. Thanks Laurence -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Laurance, I'm really starting to think that the stars aligned with the phase of the moon or something when I reproduced this in my lab before because I've been unable to reproduce it on Infiniband the last two days. The problem with this issue is that it is so hard to trigger, but causes a lot of problems when it does happen. I really hate wasting people's time when I can't reproduce it myself reliably. Please don't waste too much time if you can't get it reproduced on Infiniband, I'll have to wait until someone with the ConnectX-4-LX cards can replicate it. Hmmm you do have ConnectX-4 cards which may have the same bug it Ethernet mode. I don't see the RoCE bug on my ConnectX-3 cards, but your ConnectX-4 cards may work. Try putting the cards into Ethernet mode, set the speed and advertised speed to something lower than the max speed and verify that the link speed is that (ethtool). On the ConnectX-4-LX cards, I just had to set both interfaces down and then back up at the same time, on the ConnectX-3 I had to pull the cable (shutting down the client might have worked). Then set up target and client with iSER, format and run the test and it should trigger automatically. Looking at release notes on the ConnectX-4-LX cards, the latest firmware may fix the bug that so easily exposes the problem with that card. My cards are SuperMicro branded cards and don't have the new firmware available yet. Good luck. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Jan 13, 2017 at 8:10 AM, Laurence Oberman wrote: > > > - Original Message - >> From: "Robert LeBlanc" >> To: "Laurence Oberman" >> Cc: "Doug Ledford" , "Nicholas A. Bellinger" >> , "Zhu Lingshan" >> , "linux-rdma" , >> linux-scsi@vger.kernel.org, "Sagi Grimberg" >> , "Christoph Hellwig" >> Sent: Thursday, January 12, 2017 4:26:05 PM >> Subject: Re: iscsi_trx going into D state >> >> Sorry sent prematurely... >> >> On Thu, Jan 12, 2017 at 2:22 PM, Robert LeBlanc wrote: >> > I'm having trouble replicating the D state issue on Infiniband (I was >> > able to trigger it reliably a couple weeks back, I don't know if OFED >> > to verify the same results happen there as well. >> >> I'm having trouble replicating the D state issue on Infiniband (I was >> able to trigger it reliably a couple weeks back, I don't know if OFED >> being installed is altering things but it only installed for 3.10. The >> ConnectX-4-LX exposes the issue easily if you have those cards.) to >> verify the same results happen there as well. >> >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> -- >> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in >> the body of a message to majord...@vger.kernel.org >> More majordomo info at http://vger.kernel.org/majordomo-info.html >> > > I am only back in the office next Wednesday. > I have this all setup using ConnectX-4 with IB/ISER but have no way of > remotely creating the disconnect as I currently have it back-to-back. > Have run multiple tests with IB and ISER hard resting the client to break the > IB connection but have not been able to reproduce as yet. > So it will have to wait until I can pull cables next week as that seemed to > be the way you have been reproducing this. > > This is in a code area I also don't have a lot of knowledge of the flow but > have started trying to understand it better. > > Thanks > Laurence > -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
- Original Message - > From: "Robert LeBlanc" > To: "Laurence Oberman" > Cc: "Doug Ledford" , "Nicholas A. Bellinger" > , "Zhu Lingshan" > , "linux-rdma" , > linux-scsi@vger.kernel.org, "Sagi Grimberg" > , "Christoph Hellwig" > Sent: Thursday, January 12, 2017 4:26:05 PM > Subject: Re: iscsi_trx going into D state > > Sorry sent prematurely... > > On Thu, Jan 12, 2017 at 2:22 PM, Robert LeBlanc wrote: > > I'm having trouble replicating the D state issue on Infiniband (I was > > able to trigger it reliably a couple weeks back, I don't know if OFED > > to verify the same results happen there as well. > > I'm having trouble replicating the D state issue on Infiniband (I was > able to trigger it reliably a couple weeks back, I don't know if OFED > being installed is altering things but it only installed for 3.10. The > ConnectX-4-LX exposes the issue easily if you have those cards.) to > verify the same results happen there as well. > > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > -- > To unsubscribe from this list: send the line "unsubscribe linux-scsi" in > the body of a message to majord...@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > I am only back in the office next Wednesday. I have this all setup using ConnectX-4 with IB/ISER but have no way of remotely creating the disconnect as I currently have it back-to-back. Have run multiple tests with IB and ISER hard resting the client to break the IB connection but have not been able to reproduce as yet. So it will have to wait until I can pull cables next week as that seemed to be the way you have been reproducing this. This is in a code area I also don't have a lot of knowledge of the flow but have started trying to understand it better. Thanks Laurence -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Sorry sent prematurely... On Thu, Jan 12, 2017 at 2:22 PM, Robert LeBlanc wrote: > I'm having trouble replicating the D state issue on Infiniband (I was > able to trigger it reliably a couple weeks back, I don't know if OFED > to verify the same results happen there as well. I'm having trouble replicating the D state issue on Infiniband (I was able to trigger it reliably a couple weeks back, I don't know if OFED being installed is altering things but it only installed for 3.10. The ConnectX-4-LX exposes the issue easily if you have those cards.) to verify the same results happen there as well. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
I have a crappy patch (sledgehammer approach) that seems to prevent
the D state issue and the connection recovers, but things are possibly
not being cleaned up properly in iSCSI and so it may have issues after
a few recoveries (one test completed with a lot of resets but no iSCSI
errors). Hopefully this will help those smarter than I to understand
what is going on and know how to create a proper fix.
I'm having trouble replicating the D state issue on Infiniband (I was
able to trigger it reliably a couple weeks back, I don't know if OFED
to verify the same results happen there as well.
Patch
diff --git a/drivers/infiniband/core/verbs.c b/drivers/infiniband/core/verbs.c
index 8368764..ed36748 100644
--- a/drivers/infiniband/core/verbs.c
+++ b/drivers/infiniband/core/verbs.c
@@ -2089,3 +2089,19 @@ void ib_drain_qp(struct ib_qp *qp)
ib_drain_rq(qp);
}
EXPORT_SYMBOL(ib_drain_qp);
+
+void ib_reset_sq(struct ib_qp *qp)
+{
+ struct ib_qp_attr attr = { .qp_state = IB_QPS_RESET};
+ int ret;
+
+ ret = ib_modify_qp(qp, &attr, IB_QP_STATE);
+}
+EXPORT_SYMBOL(ib_reset_sq);
+
+void ib_reset_qp(struct ib_qp *qp)
+{
+ printk("ib_reset_qp calling ib_reset_sq.\n");
+ ib_reset_sq(qp);
+}
+EXPORT_SYMBOL(ib_reset_qp);
diff --git a/drivers/infiniband/ulp/isert/ib_isert.c
b/drivers/infiniband/ulp/isert/ib_isert.c
index 6dd43f6..619dbc7 100644
--- a/drivers/infiniband/ulp/isert/ib_isert.c
+++ b/drivers/infiniband/ulp/isert/ib_isert.c
@@ -2595,10 +2595,9 @@ static void isert_wait_conn(struct iscsi_conn *conn)
isert_conn_terminate(isert_conn);
mutex_unlock(&isert_conn->mutex);
- ib_drain_qp(isert_conn->qp);
+ ib_reset_qp(isert_conn->qp);
isert_put_unsol_pending_cmds(conn);
- isert_wait4cmds(conn);
- isert_wait4logout(isert_conn);
+ cancel_work_sync(&isert_conn->release_work);
queue_work(isert_release_wq, &isert_conn->release_work);
}
@@ -2607,7 +2606,7 @@ static void isert_free_conn(struct iscsi_conn *conn)
{
struct isert_conn *isert_conn = conn->context;
- ib_drain_qp(isert_conn->qp);
+ ib_close_qp(isert_conn->qp);
isert_put_conn(isert_conn);
}
diff --git a/include/rdma/ib_verbs.h b/include/rdma/ib_verbs.h
index 5ad43a4..3310c37 100644
--- a/include/rdma/ib_verbs.h
+++ b/include/rdma/ib_verbs.h
@@ -3357,4 +3357,6 @@ int ib_sg_to_pages(struct ib_mr *mr, struct
scatterlist *sgl, int sg_nents,
void ib_drain_rq(struct ib_qp *qp);
void ib_drain_sq(struct ib_qp *qp);
void ib_drain_qp(struct ib_qp *qp);
+void ib_reset_sq(struct ib_qp *qp);
+void ib_reset_qp(struct ib_qp *qp);
#endif /* IB_VERBS_H */
iSCSI Errors (may have many of these)
[ 292.444044] [ cut here ]
[ 292.444045] WARNING: CPU: 26 PID: 12705 at lib/list_debug.c:59
__list_del_entry+0xa1/0xd0
[ 292.444046] list_del corruption. prev->next should be
8865628c27c0, but was dead0100
[ 292.444057] Modules linked in: ib_isert rdma_cm iw_cm ib_cm
target_core_user target_core_pscsi target_core_file target_core_iblock
mlx5_ib ib_core dm_mod 8021q garp mrp iptable_filter sb_edac edac_core
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ext4
ipmi_devintf irqbypass crct10dif_pclmul crc32_pclmul
ghash_clmulni_intel aesni_intel lrw jbd2 gf128mul mbcache mei_me
glue_helper iTCO_wdt ablk_helper cryptd iTCO_vendor_support mei joydev
sg ioatdma shpchp pcspkr i2c_i801 lpc_ich mfd_core i2c_smbus acpi_pad
wmi ipmi_si ipmi_msghandler acpi_power_meter ip_tables xfs libcrc32c
raid1 sd_mod ast drm_kms_helper syscopyarea sysfillrect sysimgblt
fb_sys_fops ttm mlx5_core igb ahci ptp drm libahci pps_core mlx4_core
libata dca i2c_algo_bit be2iscsi bnx2i cnic uio qla4xxx
iscsi_boot_sysfs
[ 292.444058] CPU: 26 PID: 12705 Comm: kworker/26:2 Tainted: G W 4.9.0+ #14
[ 292.444058] Hardware name: Supermicro SYS-6028TP-HTFR/X10DRT-PIBF,
BIOS 1.1 08/03/2015
[ 292.444059] Workqueue: target_completion target_complete_ok_work
[ 292.444060] c90035533ca0 8134d45f c90035533cf0
[ 292.444061] c90035533ce0 81083371 003b0202
8865628c27c0
[ 292.444062] 887f25f48064 0001
0680
[ 292.444062] Call Trace:
[ 292.444063] [] dump_stack+0x63/0x84
[ 292.444065] [] __warn+0xd1/0xf0
[ 292.444066] [] warn_slowpath_fmt+0x5f/0x80
[ 292.444067] [] __list_del_entry+0xa1/0xd0
[ 292.444067] [] list_del+0xd/0x30
[ 292.444069] [] target_remove_from_state_list+0x64/0x70
[ 292.444070] [] transport_cmd_check_stop+0xf9/0x110
[ 292.444071] [] target_complete_ok_work+0x169/0x360
[ 292.444072] [] process_one_work+0x152/0x400
[ 292.444072] [] worker_thread+0x125/0x4b0
[ 292.444073] [] ? rescuer_thread+0x380/0x380
[ 292.444075] [] kthread+0xd9/0xf0
[ 292.444076] [] ? kthread_park+0x60/0x60
[ 292.444077] [] ret_from_fork+0x25/0x30
[ 292.444078] ---[ end trace 721cfe26853c53b7 ]---
Robert LeBlanc
PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654
Re: iscsi_trx going into D state
Laurence,
Since the summary may be helpful to others, I'm just going to send it
to the list.
I've been able to reproduce the D state problem on both Infiniband and
RoCE, but it is much easier to reproduce on RoCE due to another bug
and doesn't require being at the server to yank the cable (remote
power control of a switch may work as well). The bug seems to be
triggered by an abrupt and unexpected break in communications
Common config between both Infiniband and RoCE:
* Linux kernel 4.9 (using only inbox drivers, no OFED)
* Target and initiator both configured on the same subnet
* 100 GB ram disk exported by iser [1]
* Iser volume imported on client and the whole block device formatted ext4.
* FIO run on iser volume on the client [2]
* Anything not mentioned in this document should be default (it is a
pretty simple config)
Infiniband specific config:
* Any IB cards should work (my config has ConnectX-3, but has also
been seen on Connect-IB in our environment)
* Back to back (my config) or connected to a switch
* OpenSM running on the target (my config), or on a separate host (not
sure how cutting power to the switch may impact triggering the bug, I
believe it will still trigger ok)
* While running the fio job, pull the cable on the initiator side.
After about 120 seconds the fio job will fail and the iscsi processes
should be in D state on the target.
RoCE specific config:
* Only tested with ConnectX-4-LX cards (I don't know if others will
trigger the problem, pulling the cable like in the Infiniband section,
may also trigger the bug if it doesn't trigger automatically)
* Hosts must be connected by a switch or a Linux bridge that doesn't
have RoCE offload. I was able to trigger the bugs with a back to back
connection if the target clamps the speed to 10 Gb [3].
* Running the fio job should be enough to trigger the RoCE card to
unexpectedly drop the RDMA connection and that should then cause the
target iscsci processes to go into D state.
For either the Infiniband or RoCE setup, the bug can be triggered with
only two hosts connected back to back. If something is still not
clear, please let me know.
[1] /etc/saveconfig.json
```json
{
"fabric_modules": [],
"storage_objects": [
{
"attributes": {
"block_size": 512,
"emulate_3pc": 1,
"emulate_caw": 1,
"emulate_dpo": 0,
"emulate_fua_read": 0,
"emulate_fua_write": 1,
"emulate_model_alias": 1,
"emulate_rest_reord": 0,
"emulate_tas": 1,
"emulate_tpu": 0,
"emulate_tpws": 0,
"emulate_ua_intlck_ctrl": 0,
"emulate_write_cache": 0,
"enforce_pr_isids": 1,
"force_pr_aptpl": 0,
"is_nonrot": 1,
"max_unmap_block_desc_count": 0,
"max_unmap_lba_count": 0,
"max_write_same_len": 0,
"optimal_sectors": 4294967288,
"pi_prot_format": 0,
"pi_prot_type": 0,
"queue_depth": 128,
"unmap_granularity": 0,
"unmap_granularity_alignment": 0
},
"name": "test1",
"plugin": "ramdisk",
"size": 107374182400,
"wwn": "7486ed41-585e-400f-8799-ac605485b221"
}
],
"targets": [
{
"fabric": "iscsi",
"tpgs": [
{
"attributes": {
"authentication": 0,
"cache_dynamic_acls": 1,
"default_cmdsn_depth": 64,
"default_erl": 0,
"demo_mode_discovery": 1,
"demo_mode_write_protect": 0,
"generate_node_acls": 1,
"login_timeout": 15,
"netif_timeout": 2,
"prod_mode_write_protect": 0,
"t10_pi": 0
},
"enable": true,
"luns": [
{
"index": 0,
"storage_object": "/backstores/ramdisk/test1"
}
],
"node_acls": [],
"parameters": {
"AuthMethod": "CHAP,None",
"DataDigest": "CRC32C,None",
"DataPDUInOrder": "Yes",
"DataSequenceInOrder": "Yes",
"DefaultTime2Retain": "20",
"DefaultTime2Wait": "2",
"ErrorRecoveryLevel": "0",
"FirstBurstLength": "65536",
"HeaderDigest": "CRC32C,None",
"IFMarkInt": "Reject",
"IFMarker": "No",
"ImmediateData": "Yes",
"InitialR2T": "Yes",
"MaxBurstLength": "262144",
"MaxConnections": "1",
"MaxOutstandingR2T": "1",
"MaxRecvDataSegmentLength": "8192",
"MaxXmitDataSegmentLength": "262144",
"OFMarkInt": "Reject",
"OFMarker": "No",
"TargetAlias": "LIO Target"
},
"portals": [
{
"ip_address": "0.0.0.0",
"iser": true,
"port": 3260
}
],
"tag": 1
}
],
"wwn": "iqn.2016-12.com.betterservers"
}
]
}
```
[2] ec
Re: iscsi_trx going into D state
- Original Message - > From: "Robert LeBlanc" > To: "Doug Ledford" > Cc: "Nicholas A. Bellinger" , "Zhu Lingshan" > , "linux-rdma" > , linux-scsi@vger.kernel.org, "Sagi Grimberg" > , "Christoph Hellwig" > > Sent: Tuesday, January 3, 2017 7:11:40 PM > Subject: Re: iscsi_trx going into D state > > With the last patch it is getting hung up on wait_for_completion in > target_wait_for_sess_cmds. I don't know what t_state or fabric state > mean. To me it looks like a queue is not being emptied, but it would > help if someone confirmed this and has some pointers on how to > properly flush them when the communication is interrupted. > > [ 222.989134] Starting iscsit_close_connection. > [ 222.993555] Calling flush_workqueue. > [ 222.997703] Returned from flush_workqueue. > [ 223.005802] isert_wait_conn calling ib_close_qp/ib_drain_qp. > [ 223.011892] isert_wait_conn finished ib_close_qp/ib_drain_qp. > [ 223.018063] isert_wait_conn calling isert_put_unsol_pending_cmds. > [ 223.024574] isert_wait_conn returned from > isert_put_unsol_pending_cmds. > [ 223.031582] isert_wait_conn calling isert_wait4cmds. > [ 223.036942] isert_wait4cmds calling > target_sess_cmd_list_set_waiting. > [ 223.043789] isert_wait4cmds returned from > target_sess_cmd_list_set_waiting. > [ 223.051135] isert_wait4cmds calling target_wait_for_sess_cmds. > [ 223.057362] Waiting for se_cmd: 887ebf88bd00 t_state: 6, fabric > state: 29 > [ 223.064893] target_wait_for_sess_cmds calling > spin_unlock_irqrestore. > [ 223.071748] target_wait_for_sess_cmds calling wait_for_completion. > [ 224.997636] Calling wait_for_common. > [ 225.001936] Starting __wait_for_common. > [ 225.006226] Calling do_wait_for_common. > > Thanks > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Tue, Jan 3, 2017 at 1:07 PM, Robert LeBlanc wrote: > > With this patch I'm not seeing the __ib_drain_sq backtraces, but I'm > > still seeing the previous backtraces. > > > > diff --git a/drivers/infiniband/ulp/isert/ib_isert.c > > b/drivers/infiniband/ulp/isert/ib_isert.c > > index 6dd43f6..1e53502 100644 > > --- a/drivers/infiniband/ulp/isert/ib_isert.c > > +++ b/drivers/infiniband/ulp/isert/ib_isert.c > > @@ -2595,7 +2595,7 @@ static void isert_wait_conn(struct iscsi_conn *conn) > >isert_conn_terminate(isert_conn); > >mutex_unlock(&isert_conn->mutex); > > > > - ib_drain_qp(isert_conn->qp); > > + ib_close_qp(isert_conn->qp); > >isert_put_unsol_pending_cmds(conn); > >isert_wait4cmds(conn); > >isert_wait4logout(isert_conn); > > > > I was thinking that if the connection was brought down uncleanly then > > there may be messages(??) it the send queue that would never be > > consumed by the application, so it would never drain and would have to > > be forcibly emptied. Maybe there is something stuck in the command > > queue as well? > > > > [(support-1.0) root@prv-0-13-roberttest ~]# ps aux | grep " D " > > root 15426 0.0 0.0 0 0 ?D12:48 0:00 [iscsi_np] > > root 15429 0.0 0.0 0 0 ?D12:48 0:00 > > [iscsi_ttx] > > root 16077 0.0 0.0 112656 2216 pts/0S+ 12:55 0:00 grep > > --color=auto D > > [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/15426/stack > > [] iscsit_stop_session+0x1b1/0x1c0 > > [] iscsi_check_for_session_reinstatement+0x1e2/0x270 > > [] iscsi_target_check_for_existing_instances+0x30/0x40 > > [] iscsi_target_do_login+0x138/0x630 > > [] iscsi_target_start_negotiation+0x4e/0xa0 > > [] __iscsi_target_login_thread+0x83e/0xf20 > > [] iscsi_target_login_thread+0x24/0x30 > > [] kthread+0xd9/0xf0 > > [] ret_from_fork+0x25/0x30 > > [] 0x > > [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/15429/stack > > [] target_wait_for_sess_cmds+0x49/0x190 > > [] isert_wait_conn+0x1a4/0x2d0 [ib_isert] > > [] iscsit_close_connection+0x157/0x860 > > [] iscsit_take_action_for_connection_exit+0x7b/0xf0 > > [] iscsi_target_tx_thread+0x150/0x1d0 > > [] kthread+0xd9/0xf0 > > [] ret_from_fork+0x25/0x30 > > [] 0x > > > > Robert LeBlanc > > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > > > > On Fri, Dec 30, 2016 at 4:07 PM, Robert LeBlanc > > wrote: > >> I decided to try something completely different... Runni
Re: iscsi_trx going into D state
With the last patch it is getting hung up on wait_for_completion in target_wait_for_sess_cmds. I don't know what t_state or fabric state mean. To me it looks like a queue is not being emptied, but it would help if someone confirmed this and has some pointers on how to properly flush them when the communication is interrupted. [ 222.989134] Starting iscsit_close_connection. [ 222.993555] Calling flush_workqueue. [ 222.997703] Returned from flush_workqueue. [ 223.005802] isert_wait_conn calling ib_close_qp/ib_drain_qp. [ 223.011892] isert_wait_conn finished ib_close_qp/ib_drain_qp. [ 223.018063] isert_wait_conn calling isert_put_unsol_pending_cmds. [ 223.024574] isert_wait_conn returned from isert_put_unsol_pending_cmds. [ 223.031582] isert_wait_conn calling isert_wait4cmds. [ 223.036942] isert_wait4cmds calling target_sess_cmd_list_set_waiting. [ 223.043789] isert_wait4cmds returned from target_sess_cmd_list_set_waiting. [ 223.051135] isert_wait4cmds calling target_wait_for_sess_cmds. [ 223.057362] Waiting for se_cmd: 887ebf88bd00 t_state: 6, fabric state: 29 [ 223.064893] target_wait_for_sess_cmds calling spin_unlock_irqrestore. [ 223.071748] target_wait_for_sess_cmds calling wait_for_completion. [ 224.997636] Calling wait_for_common. [ 225.001936] Starting __wait_for_common. [ 225.006226] Calling do_wait_for_common. Thanks Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Tue, Jan 3, 2017 at 1:07 PM, Robert LeBlanc wrote: > With this patch I'm not seeing the __ib_drain_sq backtraces, but I'm > still seeing the previous backtraces. > > diff --git a/drivers/infiniband/ulp/isert/ib_isert.c > b/drivers/infiniband/ulp/isert/ib_isert.c > index 6dd43f6..1e53502 100644 > --- a/drivers/infiniband/ulp/isert/ib_isert.c > +++ b/drivers/infiniband/ulp/isert/ib_isert.c > @@ -2595,7 +2595,7 @@ static void isert_wait_conn(struct iscsi_conn *conn) >isert_conn_terminate(isert_conn); >mutex_unlock(&isert_conn->mutex); > > - ib_drain_qp(isert_conn->qp); > + ib_close_qp(isert_conn->qp); >isert_put_unsol_pending_cmds(conn); >isert_wait4cmds(conn); >isert_wait4logout(isert_conn); > > I was thinking that if the connection was brought down uncleanly then > there may be messages(??) it the send queue that would never be > consumed by the application, so it would never drain and would have to > be forcibly emptied. Maybe there is something stuck in the command > queue as well? > > [(support-1.0) root@prv-0-13-roberttest ~]# ps aux | grep " D " > root 15426 0.0 0.0 0 0 ?D12:48 0:00 [iscsi_np] > root 15429 0.0 0.0 0 0 ?D12:48 0:00 [iscsi_ttx] > root 16077 0.0 0.0 112656 2216 pts/0S+ 12:55 0:00 grep > --color=auto D > [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/15426/stack > [] iscsit_stop_session+0x1b1/0x1c0 > [] iscsi_check_for_session_reinstatement+0x1e2/0x270 > [] iscsi_target_check_for_existing_instances+0x30/0x40 > [] iscsi_target_do_login+0x138/0x630 > [] iscsi_target_start_negotiation+0x4e/0xa0 > [] __iscsi_target_login_thread+0x83e/0xf20 > [] iscsi_target_login_thread+0x24/0x30 > [] kthread+0xd9/0xf0 > [] ret_from_fork+0x25/0x30 > [] 0x > [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/15429/stack > [] target_wait_for_sess_cmds+0x49/0x190 > [] isert_wait_conn+0x1a4/0x2d0 [ib_isert] > [] iscsit_close_connection+0x157/0x860 > [] iscsit_take_action_for_connection_exit+0x7b/0xf0 > [] iscsi_target_tx_thread+0x150/0x1d0 > [] kthread+0xd9/0xf0 > [] ret_from_fork+0x25/0x30 > [] 0x > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Fri, Dec 30, 2016 at 4:07 PM, Robert LeBlanc wrote: >> I decided to try something completely different... Running the stock >> CentOS 3.10 kernel and OFED 3.4 on both hosts, I'm not seeing the hung >> processes and the tests complete successfully. The same seems to be >> true for the target on 4.9 and the initiator on 3.10. >> >> However, with the target on 3.10 and the initiator on 4.9, I get this >> on the target: >> >> [(support-1.0) root@prv-0-13-roberttest ~]# ps aux | grep " D " >> root 14791 0.0 0.0 0 0 ?D15:08 0:00 [iscsi_np] >> root 14795 0.0 0.0 0 0 ?D15:08 0:00 [iscsi_trx] >> root 14852 0.0 0.0 112648 976 pts/0S+ 15:11 0:00 grep >> --color=auto D >> [(support-1.0) root@prv-0-13-roberttest ~]# uname -a >> Linux prv-0-13-roberttest.betterservers.com 3.10.0-327.36.3.el7.x86_64 >> #1 SMP Mon Oct 24 16:09:20 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux >> [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/14791/stack >> [] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod] >> [] iscsi_check_for_session_reinstatement+0x1ea/0x280 >> [iscsi_target_mod] >> [] >> iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_tar
Re: iscsi_trx going into D state
With this patch I'm not seeing the __ib_drain_sq backtraces, but I'm still seeing the previous backtraces. diff --git a/drivers/infiniband/ulp/isert/ib_isert.c b/drivers/infiniband/ulp/isert/ib_isert.c index 6dd43f6..1e53502 100644 --- a/drivers/infiniband/ulp/isert/ib_isert.c +++ b/drivers/infiniband/ulp/isert/ib_isert.c @@ -2595,7 +2595,7 @@ static void isert_wait_conn(struct iscsi_conn *conn) isert_conn_terminate(isert_conn); mutex_unlock(&isert_conn->mutex); - ib_drain_qp(isert_conn->qp); + ib_close_qp(isert_conn->qp); isert_put_unsol_pending_cmds(conn); isert_wait4cmds(conn); isert_wait4logout(isert_conn); I was thinking that if the connection was brought down uncleanly then there may be messages(??) it the send queue that would never be consumed by the application, so it would never drain and would have to be forcibly emptied. Maybe there is something stuck in the command queue as well? [(support-1.0) root@prv-0-13-roberttest ~]# ps aux | grep " D " root 15426 0.0 0.0 0 0 ?D12:48 0:00 [iscsi_np] root 15429 0.0 0.0 0 0 ?D12:48 0:00 [iscsi_ttx] root 16077 0.0 0.0 112656 2216 pts/0S+ 12:55 0:00 grep --color=auto D [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/15426/stack [] iscsit_stop_session+0x1b1/0x1c0 [] iscsi_check_for_session_reinstatement+0x1e2/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x138/0x630 [] iscsi_target_start_negotiation+0x4e/0xa0 [] __iscsi_target_login_thread+0x83e/0xf20 [] iscsi_target_login_thread+0x24/0x30 [] kthread+0xd9/0xf0 [] ret_from_fork+0x25/0x30 [] 0x [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/15429/stack [] target_wait_for_sess_cmds+0x49/0x190 [] isert_wait_conn+0x1a4/0x2d0 [ib_isert] [] iscsit_close_connection+0x157/0x860 [] iscsit_take_action_for_connection_exit+0x7b/0xf0 [] iscsi_target_tx_thread+0x150/0x1d0 [] kthread+0xd9/0xf0 [] ret_from_fork+0x25/0x30 [] 0x Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Dec 30, 2016 at 4:07 PM, Robert LeBlanc wrote: > I decided to try something completely different... Running the stock > CentOS 3.10 kernel and OFED 3.4 on both hosts, I'm not seeing the hung > processes and the tests complete successfully. The same seems to be > true for the target on 4.9 and the initiator on 3.10. > > However, with the target on 3.10 and the initiator on 4.9, I get this > on the target: > > [(support-1.0) root@prv-0-13-roberttest ~]# ps aux | grep " D " > root 14791 0.0 0.0 0 0 ?D15:08 0:00 [iscsi_np] > root 14795 0.0 0.0 0 0 ?D15:08 0:00 [iscsi_trx] > root 14852 0.0 0.0 112648 976 pts/0S+ 15:11 0:00 grep > --color=auto D > [(support-1.0) root@prv-0-13-roberttest ~]# uname -a > Linux prv-0-13-roberttest.betterservers.com 3.10.0-327.36.3.el7.x86_64 > #1 SMP Mon Oct 24 16:09:20 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux > [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/14791/stack > [] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod] > [] iscsi_check_for_session_reinstatement+0x1ea/0x280 > [iscsi_target_mod] > [] > iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_target_mod] > [] iscsi_target_do_login+0x141/0x670 [iscsi_target_mod] > [] iscsi_target_start_negotiation+0x1c/0xb0 > [iscsi_target_mod] > [] iscsi_target_login_thread+0xadf/0x1050 [iscsi_target_mod] > [] kthread+0xcf/0xe0 > [] ret_from_fork+0x58/0x90 > [] 0x > [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/14795/stack > [] isert_wait4flush+0x79/0xc0 [ib_isert] > [] isert_wait_conn+0x5b/0x2d0 [ib_isert] > [] iscsit_close_connection+0x15d/0x820 [iscsi_target_mod] > [] iscsit_take_action_for_connection_exit+0x83/0x110 > [iscsi_target_mod] > [] iscsi_target_rx_thread+0x1e7/0xf80 [iscsi_target_mod] > [] kthread+0xcf/0xe0 > [] ret_from_fork+0x58/0x90 > [] 0x > > [ 345.970157] iSCSI Login timeout on Network Portal 0.0.0.0:3260 > [ 483.850714] INFO: task iscsi_np:14791 blocked for more than 120 seconds. > [ 483.857467] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 483.865326] iscsi_npD 0 14791 2 > 0x0004 > [ 483.872460] 886e3b117be0 0046 887ede579700 > 886e3b117fd8 > [ 483.879983] 886e3b117fd8 886e3b117fd8 887ede579700 > 883ef7898160 > [ 483.887500] 883ef7898168 7fff 887ede579700 > > [ 483.895025] Call Trace: > [ 483.897505] [] schedule+0x29/0x70 > [ 483.902496] [] schedule_timeout+0x209/0x2d0 > [ 483.908355] [] ? simple_strtoull+0x3b/0x70 > [ 483.914128] [] wait_for_completion+0x116/0x170 > [ 483.920253] [] ? wake_up_state+0x20/0x20 > [ 483.925847] [] iscsit_stop_session+0x1c8/0x1e0 > [iscsi_target_mod] > [ 483.933612] []
Re: iscsi_trx going into D state
I decided to try something completely different... Running the stock CentOS 3.10 kernel and OFED 3.4 on both hosts, I'm not seeing the hung processes and the tests complete successfully. The same seems to be true for the target on 4.9 and the initiator on 3.10. However, with the target on 3.10 and the initiator on 4.9, I get this on the target: [(support-1.0) root@prv-0-13-roberttest ~]# ps aux | grep " D " root 14791 0.0 0.0 0 0 ?D15:08 0:00 [iscsi_np] root 14795 0.0 0.0 0 0 ?D15:08 0:00 [iscsi_trx] root 14852 0.0 0.0 112648 976 pts/0S+ 15:11 0:00 grep --color=auto D [(support-1.0) root@prv-0-13-roberttest ~]# uname -a Linux prv-0-13-roberttest.betterservers.com 3.10.0-327.36.3.el7.x86_64 #1 SMP Mon Oct 24 16:09:20 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/14791/stack [] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod] [] iscsi_check_for_session_reinstatement+0x1ea/0x280 [iscsi_target_mod] [] iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_target_mod] [] iscsi_target_do_login+0x141/0x670 [iscsi_target_mod] [] iscsi_target_start_negotiation+0x1c/0xb0 [iscsi_target_mod] [] iscsi_target_login_thread+0xadf/0x1050 [iscsi_target_mod] [] kthread+0xcf/0xe0 [] ret_from_fork+0x58/0x90 [] 0x [(support-1.0) root@prv-0-13-roberttest ~]# cat /proc/14795/stack [] isert_wait4flush+0x79/0xc0 [ib_isert] [] isert_wait_conn+0x5b/0x2d0 [ib_isert] [] iscsit_close_connection+0x15d/0x820 [iscsi_target_mod] [] iscsit_take_action_for_connection_exit+0x83/0x110 [iscsi_target_mod] [] iscsi_target_rx_thread+0x1e7/0xf80 [iscsi_target_mod] [] kthread+0xcf/0xe0 [] ret_from_fork+0x58/0x90 [] 0x [ 345.970157] iSCSI Login timeout on Network Portal 0.0.0.0:3260 [ 483.850714] INFO: task iscsi_np:14791 blocked for more than 120 seconds. [ 483.857467] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 483.865326] iscsi_npD 0 14791 2 0x0004 [ 483.872460] 886e3b117be0 0046 887ede579700 886e3b117fd8 [ 483.879983] 886e3b117fd8 886e3b117fd8 887ede579700 883ef7898160 [ 483.887500] 883ef7898168 7fff 887ede579700 [ 483.895025] Call Trace: [ 483.897505] [] schedule+0x29/0x70 [ 483.902496] [] schedule_timeout+0x209/0x2d0 [ 483.908355] [] ? simple_strtoull+0x3b/0x70 [ 483.914128] [] wait_for_completion+0x116/0x170 [ 483.920253] [] ? wake_up_state+0x20/0x20 [ 483.925847] [] iscsit_stop_session+0x1c8/0x1e0 [iscsi_target_mod] [ 483.933612] [] iscsi_check_for_session_reinstatement+0x1ea/0x280 [iscsi_target_mod] [ 483.942944] [] iscsi_target_check_for_existing_instances+0x35/0x40 [iscsi_target_mod] [ 483.953304] [] iscsi_target_do_login+0x141/0x670 [iscsi_target_mod] [ 483.961988] [] iscsi_target_start_negotiation+0x1c/0xb0 [iscsi_target_mod] [ 483.971278] [] iscsi_target_login_thread+0xadf/0x1050 [iscsi_target_mod] [ 483.980346] [] ? __schedule+0x1f1/0x900 [ 483.986525] [] ? iscsi_target_login_sess_out+0x250/0x250 [iscsi_target_mod] [ 483.995816] [] kthread+0xcf/0xe0 [ 484.001403] [] ? kthread_create_on_node+0x140/0x140 [ 484.008608] [] ret_from_fork+0x58/0x90 [ 484.014672] [] ? kthread_create_on_node+0x140/0x140 [ 484.021896] INFO: task iscsi_trx:14795 blocked for more than 120 seconds. [ 484.029349] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 484.037849] iscsi_trx D 887ee64f8000 0 14795 2 0x0004 [ 484.045598] 886e391bfbe0 0046 887ed715c500 886e391bffd8 [ 484.053753] 886e391bffd8 886e391bffd8 887ed715c500 887ee64f91d0 [ 484.061891] 887ee64f91d8 7fff 887ed715c500 887ee64f8000 [ 484.070049] Call Trace: [ 484.073174] [] schedule+0x29/0x70 [ 484.078797] [] schedule_timeout+0x209/0x2d0 [ 484.085290] [] ? cm_alloc_msg+0x115/0x180 [ib_cm] [ 484.092252] [] wait_for_completion+0x116/0x170 [ 484.098960] [] ? wake_up_state+0x20/0x20 [ 484.105132] [] isert_wait4flush+0x79/0xc0 [ib_isert] [ 484.112369] [] isert_wait_conn+0x5b/0x2d0 [ib_isert] [ 484.119566] [] iscsit_close_connection+0x15d/0x820 [iscsi_target_mod] [ 484.128239] [] ? wait_for_completion_interruptible+0x167/0x1d0 [ 484.136341] [] ? iscsi_target_tx_thread+0x200/0x200 [iscsi_target_mod] [ 484.145135] [] iscsit_take_action_for_connection_exit+0x83/0x110 [iscsi_target_mod] [ 484.155067] [] iscsi_target_rx_thread+0x1e7/0xf80 [iscsi_target_mod] [ 484.163700] [] ? __switch_to+0xf8/0x4b0 [ 484.169774] [] ? iscsi_target_tx_thread+0x200/0x200 [iscsi_target_mod] [ 484.178530] [] kthread+0xcf/0xe0 [ 484.183991] [] ? kthread_create_on_node+0x140/0x140 [ 484.191106] [] ret_from_fork+0x58/0x90 [ 484.197096] [] ? kthread_create_on_node+0x140/0x140 I think there are two bugs here. Something in 4.9 iser (ini
Re: iscsi_trx going into D state
OK, I've drilled down a little more and timeout = action(timeout); in do_wait_for_common() in kernel/sched/completion.c is not returning. I'll have to see if I can make more progress tomorrow. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Thu, Dec 29, 2016 at 2:23 PM, Robert LeBlanc wrote: > I know most people are ignoring this thread by now, but I hope someone > is still reading and can offer some ideas. > > It looks like ib_drain_qp_done() is not being called the first time > that __ib_drain_sq() is called from iscsit_close_connection(). I tried > to debug wait_for_completion() and friends, but they are called by too > many things and I don't know how to filter out what I'm looking for. > My next idea is to copy the completion functions here so that I can > add debug to only that path. I feel like I'm inching closer to the > problem, stumbling around in the dark. > > [Thu Dec 29 14:02:03 2016] Starting iscsit_close_connection. > [Thu Dec 29 14:02:03 2016] isert_wait_conn calling ib_drain_qp. > [Thu Dec 29 14:02:03 2016] ib_drain_qp calling ib_drain_sq. > [Thu Dec 29 14:02:03 2016] ib_drain_sq calling __ib_drain_sq. > [Thu Dec 29 14:02:03 2016] Setting up drain callback. > [Thu Dec 29 14:02:03 2016] Starting init_completion. > [Thu Dec 29 14:02:03 2016] Calling ib_modify_qp. > [Thu Dec 29 14:02:03 2016] Calling ib_post_send. > [Thu Dec 29 14:02:03 2016] Calling wait_for_completion. > [Thu Dec 29 14:02:03 2016] &sdrain.done->done = 0. > > Gets "stuck" here... > > [Thu Dec 29 14:02:20 2016] iSCSI Login timeout on Network Portal 0.0.0.0:3260 > [Thu Dec 29 14:02:37 2016] ib_drain_qp calling ib_drain_sq. > [Thu Dec 29 14:02:37 2016] ib_drain_sq calling __ib_drain_sq. > [Thu Dec 29 14:02:37 2016] Setting up drain callback. > [Thu Dec 29 14:02:37 2016] Starting init_completion. > [Thu Dec 29 14:02:37 2016] Calling ib_modify_qp. > [Thu Dec 29 14:02:37 2016] Calling ib_post_send. > [Thu Dec 29 14:02:37 2016] Calling wait_for_completion. > [Thu Dec 29 14:02:37 2016] ib_drain_qp_done going to call complete. > [Thu Dec 29 14:02:38 2016] &sdrain.done->done = 1. > [Thu Dec 29 14:02:38 2016] Returned from wait_for_completion. > [Thu Dec 29 14:02:38 2016] ib_drain_qp_done going to call complete. > > Next time ib_drain_qp is called, ib_drain_qp_done gets called... > > [Thu Dec 29 14:02:55 2016] ib_drain_qp calling ib_drain_sq. > [Thu Dec 29 14:02:55 2016] ib_drain_sq calling __ib_drain_sq. > [Thu Dec 29 14:02:55 2016] Setting up drain callback. > [Thu Dec 29 14:02:55 2016] Starting init_completion. > [Thu Dec 29 14:02:55 2016] Calling ib_modify_qp. > [Thu Dec 29 14:02:55 2016] Calling ib_post_send. > [Thu Dec 29 14:02:55 2016] Calling wait_for_completion. > [Thu Dec 29 14:02:55 2016] ib_drain_qp_done going to call complete. > [Thu Dec 29 14:02:55 2016] &sdrain.done->done = 1. > [Thu Dec 29 14:02:55 2016] Returned from wait_for_completion. > [Thu Dec 29 14:02:55 2016] ib_drain_qp_done going to call complete. > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Wed, Dec 28, 2016 at 1:58 PM, Robert LeBlanc wrote: >> Good news! I found a 10 Gb switch laying around and put it in place of >> the Linux router. I'm getting the same failure with the switch, so it >> is not something funky with the Linux router and easier to replicate. >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> >> >> On Wed, Dec 28, 2016 at 1:39 PM, Robert LeBlanc wrote: >>> OK, here is some more info. This is a diagram of my current set up. >>> >>> ++ >>> | Linux Router | >>> | ConnectX-3 | >>> | port 1 port 2 | >>> ++ >>> / \ >>> +---+ /\ +---+ >>> |Host 1 | / A A \ |Host 2 | >>> | ConnectX-4-LX | /\ | ConnectX-4-LX | >>> |Port 1 |- -| Port 1| >>> |Port 2 || Port 2| >>> +---+B +---+ >>> >>> The Linux router has the ConnectX-3 (not PRO) card in Ethernet mode >>> and is using a breakout cable (port 1 only) to connect to the >>> ConnectX-4-LX cards at 10 Gb as path 'A'. The second port of the >>> ConnectX-4-LX cards are connected directly at 25 Gb as path 'B'. >>> >>> Running Iser and RoCE on path 'B' seems to run just fine. >>> >>> Running Iser and RoCE on path 'A' has issues when the Linux router is >>> operating as a bridge or a router. Some small operations like mkfs >>> seem to work just fine, but fio causes iser to want to log out and we >>> get D state. I can run ib_send_bw 'all' tests through path 'A' and >>> don't see a problem. It does seem to be load related, though. I have >>> been trying to run >>> >>> echo "3" > /proc/sys/vm/drop_caches; fio --rw=read --b
Re: iscsi_trx going into D state
I know most people are ignoring this thread by now, but I hope someone is still reading and can offer some ideas. It looks like ib_drain_qp_done() is not being called the first time that __ib_drain_sq() is called from iscsit_close_connection(). I tried to debug wait_for_completion() and friends, but they are called by too many things and I don't know how to filter out what I'm looking for. My next idea is to copy the completion functions here so that I can add debug to only that path. I feel like I'm inching closer to the problem, stumbling around in the dark. [Thu Dec 29 14:02:03 2016] Starting iscsit_close_connection. [Thu Dec 29 14:02:03 2016] isert_wait_conn calling ib_drain_qp. [Thu Dec 29 14:02:03 2016] ib_drain_qp calling ib_drain_sq. [Thu Dec 29 14:02:03 2016] ib_drain_sq calling __ib_drain_sq. [Thu Dec 29 14:02:03 2016] Setting up drain callback. [Thu Dec 29 14:02:03 2016] Starting init_completion. [Thu Dec 29 14:02:03 2016] Calling ib_modify_qp. [Thu Dec 29 14:02:03 2016] Calling ib_post_send. [Thu Dec 29 14:02:03 2016] Calling wait_for_completion. [Thu Dec 29 14:02:03 2016] &sdrain.done->done = 0. Gets "stuck" here... [Thu Dec 29 14:02:20 2016] iSCSI Login timeout on Network Portal 0.0.0.0:3260 [Thu Dec 29 14:02:37 2016] ib_drain_qp calling ib_drain_sq. [Thu Dec 29 14:02:37 2016] ib_drain_sq calling __ib_drain_sq. [Thu Dec 29 14:02:37 2016] Setting up drain callback. [Thu Dec 29 14:02:37 2016] Starting init_completion. [Thu Dec 29 14:02:37 2016] Calling ib_modify_qp. [Thu Dec 29 14:02:37 2016] Calling ib_post_send. [Thu Dec 29 14:02:37 2016] Calling wait_for_completion. [Thu Dec 29 14:02:37 2016] ib_drain_qp_done going to call complete. [Thu Dec 29 14:02:38 2016] &sdrain.done->done = 1. [Thu Dec 29 14:02:38 2016] Returned from wait_for_completion. [Thu Dec 29 14:02:38 2016] ib_drain_qp_done going to call complete. Next time ib_drain_qp is called, ib_drain_qp_done gets called... [Thu Dec 29 14:02:55 2016] ib_drain_qp calling ib_drain_sq. [Thu Dec 29 14:02:55 2016] ib_drain_sq calling __ib_drain_sq. [Thu Dec 29 14:02:55 2016] Setting up drain callback. [Thu Dec 29 14:02:55 2016] Starting init_completion. [Thu Dec 29 14:02:55 2016] Calling ib_modify_qp. [Thu Dec 29 14:02:55 2016] Calling ib_post_send. [Thu Dec 29 14:02:55 2016] Calling wait_for_completion. [Thu Dec 29 14:02:55 2016] ib_drain_qp_done going to call complete. [Thu Dec 29 14:02:55 2016] &sdrain.done->done = 1. [Thu Dec 29 14:02:55 2016] Returned from wait_for_completion. [Thu Dec 29 14:02:55 2016] ib_drain_qp_done going to call complete. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Wed, Dec 28, 2016 at 1:58 PM, Robert LeBlanc wrote: > Good news! I found a 10 Gb switch laying around and put it in place of > the Linux router. I'm getting the same failure with the switch, so it > is not something funky with the Linux router and easier to replicate. > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Wed, Dec 28, 2016 at 1:39 PM, Robert LeBlanc wrote: >> OK, here is some more info. This is a diagram of my current set up. >> >> ++ >> | Linux Router | >> | ConnectX-3 | >> | port 1 port 2 | >> ++ >> / \ >> +---+ /\ +---+ >> |Host 1 | / A A \ |Host 2 | >> | ConnectX-4-LX | /\ | ConnectX-4-LX | >> |Port 1 |- -| Port 1| >> |Port 2 || Port 2| >> +---+B +---+ >> >> The Linux router has the ConnectX-3 (not PRO) card in Ethernet mode >> and is using a breakout cable (port 1 only) to connect to the >> ConnectX-4-LX cards at 10 Gb as path 'A'. The second port of the >> ConnectX-4-LX cards are connected directly at 25 Gb as path 'B'. >> >> Running Iser and RoCE on path 'B' seems to run just fine. >> >> Running Iser and RoCE on path 'A' has issues when the Linux router is >> operating as a bridge or a router. Some small operations like mkfs >> seem to work just fine, but fio causes iser to want to log out and we >> get D state. I can run ib_send_bw 'all' tests through path 'A' and >> don't see a problem. It does seem to be load related, though. I have >> been trying to run >> >> echo "3" > /proc/sys/vm/drop_caches; fio --rw=read --bs=4K --size=1G >> --numjobs=40 --name=worker.matt --group_reporting >> >> If I reduce the number of jobs to 10 or less, it seems to work >> although I may see some of the debug messages I added in, it doesn't >> seem to completely hang and cause the logout lockup. >> >> Steps to reproduce: >> 1. 4.9 kernel >> 2. Bridge ports 1 & 2 on the Linux router >> 3. Configure port 1 on Host 1 & 2 on the same subnet >> 4. Create large ramdisk in targetcli and export from Host 1 >> 5. Login from Host 2
Re: iscsi_trx going into D state
Good news! I found a 10 Gb switch laying around and put it in place of
the Linux router. I'm getting the same failure with the switch, so it
is not something funky with the Linux router and easier to replicate.
Robert LeBlanc
PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Wed, Dec 28, 2016 at 1:39 PM, Robert LeBlanc wrote:
> OK, here is some more info. This is a diagram of my current set up.
>
> ++
> | Linux Router |
> | ConnectX-3 |
> | port 1 port 2 |
> ++
> / \
> +---+ /\ +---+
> |Host 1 | / A A \ |Host 2 |
> | ConnectX-4-LX | /\ | ConnectX-4-LX |
> |Port 1 |- -| Port 1|
> |Port 2 || Port 2|
> +---+B +---+
>
> The Linux router has the ConnectX-3 (not PRO) card in Ethernet mode
> and is using a breakout cable (port 1 only) to connect to the
> ConnectX-4-LX cards at 10 Gb as path 'A'. The second port of the
> ConnectX-4-LX cards are connected directly at 25 Gb as path 'B'.
>
> Running Iser and RoCE on path 'B' seems to run just fine.
>
> Running Iser and RoCE on path 'A' has issues when the Linux router is
> operating as a bridge or a router. Some small operations like mkfs
> seem to work just fine, but fio causes iser to want to log out and we
> get D state. I can run ib_send_bw 'all' tests through path 'A' and
> don't see a problem. It does seem to be load related, though. I have
> been trying to run
>
> echo "3" > /proc/sys/vm/drop_caches; fio --rw=read --bs=4K --size=1G
> --numjobs=40 --name=worker.matt --group_reporting
>
> If I reduce the number of jobs to 10 or less, it seems to work
> although I may see some of the debug messages I added in, it doesn't
> seem to completely hang and cause the logout lockup.
>
> Steps to reproduce:
> 1. 4.9 kernel
> 2. Bridge ports 1 & 2 on the Linux router
> 3. Configure port 1 on Host 1 & 2 on the same subnet
> 4. Create large ramdisk in targetcli and export from Host 1
> 5. Login from Host 2
> 6. Create EXT4 file system on imported disk
> 7. Mount and cd into mount
> 8. Run fio: echo "3" > /proc/sys/vm/drop_caches; fio --rw=read --bs=4K
> --size=1G --numjobs=40 --name=worker.matt --group_reporting
> 9. After some time, the fio process will report the file system is
> read only and the iscsi processes will be in D state on Host 1
>
> It does seem the problem is in iser and not specific to the generic RDMA
> stack.
>
> I'll keep digging and reporting back.
>
> Robert LeBlanc
> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
>
>
> On Tue, Dec 27, 2016 at 1:58 PM, Robert LeBlanc wrote:
>> I realized that I did not set the default RoCE mode to v2 and the
>> client is on a different subnet, probably why I'm seeing the -110
>> error. Iser should not go into D state because of this and should
>> handle this gracefully, but may provide an easy way to replicate the
>> issue.
>>
>> Robert LeBlanc
>> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
>>
>>
>> On Tue, Dec 27, 2016 at 1:22 PM, Robert LeBlanc wrote:
>>> I looked at this code and it is quiet above my ability. I created this
>>> patch, but I don't know how to interrogate the queue to see how many
>>> items there are. If you can give me some more direction on what to
>>> try, I can keep fumbling around with this until someone smarter than
>>> me can figure it out. This is now a blocker for me so I'm going to
>>> beat my head on this until it is fixed.
>>>
>>> Thanks for being patient with me.
>>>
>>> diff --git a/drivers/infiniband/core/verbs.c
>>> b/drivers/infiniband/core/verbs.c
>>> index 8368764..9e5bd4b 100644
>>> --- a/drivers/infiniband/core/verbs.c
>>> +++ b/drivers/infiniband/core/verbs.c
>>> @@ -1954,22 +1954,27 @@ static void __ib_drain_sq(struct ib_qp *qp)
>>> return;
>>> }
>>>
>>> + printk("Setting up drain callback.");
>>> swr.wr_cqe = &sdrain.cqe;
>>> sdrain.cqe.done = ib_drain_qp_done;
>>> + printk("Starting init_completion.");
>>> init_completion(&sdrain.done);
>>>
>>> + printk("Calling ib_modify_qp.");
>>> ret = ib_modify_qp(qp, &attr, IB_QP_STATE);
>>> if (ret) {
>>> WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
>>> return;
>>> }
>>>
>>> + printk("Calling ib_post_send.");
>>> ret = ib_post_send(qp, &swr, &bad_swr);
>>> if (ret) {
>>> WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
>>> return;
>>> }
>>>
>>> + printk("Starting wait_for_completion.");
>>> wait_for_completion(&sdrain.done);
>>> }
>>>
>>> I get the same processes in D state (and same backtrace) a
Re: iscsi_trx going into D state
OK, here is some more info. This is a diagram of my current set up.
++
| Linux Router |
| ConnectX-3 |
| port 1 port 2 |
++
/ \
+---+ /\ +---+
|Host 1 | / A A \ |Host 2 |
| ConnectX-4-LX | /\ | ConnectX-4-LX |
|Port 1 |- -| Port 1|
|Port 2 || Port 2|
+---+B +---+
The Linux router has the ConnectX-3 (not PRO) card in Ethernet mode
and is using a breakout cable (port 1 only) to connect to the
ConnectX-4-LX cards at 10 Gb as path 'A'. The second port of the
ConnectX-4-LX cards are connected directly at 25 Gb as path 'B'.
Running Iser and RoCE on path 'B' seems to run just fine.
Running Iser and RoCE on path 'A' has issues when the Linux router is
operating as a bridge or a router. Some small operations like mkfs
seem to work just fine, but fio causes iser to want to log out and we
get D state. I can run ib_send_bw 'all' tests through path 'A' and
don't see a problem. It does seem to be load related, though. I have
been trying to run
echo "3" > /proc/sys/vm/drop_caches; fio --rw=read --bs=4K --size=1G
--numjobs=40 --name=worker.matt --group_reporting
If I reduce the number of jobs to 10 or less, it seems to work
although I may see some of the debug messages I added in, it doesn't
seem to completely hang and cause the logout lockup.
Steps to reproduce:
1. 4.9 kernel
2. Bridge ports 1 & 2 on the Linux router
3. Configure port 1 on Host 1 & 2 on the same subnet
4. Create large ramdisk in targetcli and export from Host 1
5. Login from Host 2
6. Create EXT4 file system on imported disk
7. Mount and cd into mount
8. Run fio: echo "3" > /proc/sys/vm/drop_caches; fio --rw=read --bs=4K
--size=1G --numjobs=40 --name=worker.matt --group_reporting
9. After some time, the fio process will report the file system is
read only and the iscsi processes will be in D state on Host 1
It does seem the problem is in iser and not specific to the generic RDMA stack.
I'll keep digging and reporting back.
Robert LeBlanc
PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Tue, Dec 27, 2016 at 1:58 PM, Robert LeBlanc wrote:
> I realized that I did not set the default RoCE mode to v2 and the
> client is on a different subnet, probably why I'm seeing the -110
> error. Iser should not go into D state because of this and should
> handle this gracefully, but may provide an easy way to replicate the
> issue.
>
> Robert LeBlanc
> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
>
>
> On Tue, Dec 27, 2016 at 1:22 PM, Robert LeBlanc wrote:
>> I looked at this code and it is quiet above my ability. I created this
>> patch, but I don't know how to interrogate the queue to see how many
>> items there are. If you can give me some more direction on what to
>> try, I can keep fumbling around with this until someone smarter than
>> me can figure it out. This is now a blocker for me so I'm going to
>> beat my head on this until it is fixed.
>>
>> Thanks for being patient with me.
>>
>> diff --git a/drivers/infiniband/core/verbs.c
>> b/drivers/infiniband/core/verbs.c
>> index 8368764..9e5bd4b 100644
>> --- a/drivers/infiniband/core/verbs.c
>> +++ b/drivers/infiniband/core/verbs.c
>> @@ -1954,22 +1954,27 @@ static void __ib_drain_sq(struct ib_qp *qp)
>> return;
>> }
>>
>> + printk("Setting up drain callback.");
>> swr.wr_cqe = &sdrain.cqe;
>> sdrain.cqe.done = ib_drain_qp_done;
>> + printk("Starting init_completion.");
>> init_completion(&sdrain.done);
>>
>> + printk("Calling ib_modify_qp.");
>> ret = ib_modify_qp(qp, &attr, IB_QP_STATE);
>> if (ret) {
>> WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
>> return;
>> }
>>
>> + printk("Calling ib_post_send.");
>> ret = ib_post_send(qp, &swr, &bad_swr);
>> if (ret) {
>> WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
>> return;
>> }
>>
>> + printk("Starting wait_for_completion.");
>> wait_for_completion(&sdrain.done);
>> }
>>
>> I get the same processes in D state (and same backtrace) and this is
>> what shows up in dmesg:
>>
>> [ 920.317401] isert: isert_rdma_accept: rdma_accept() failed with: -110
>> [ 920.325554] [ cut here ]
>> [ 920.330188] WARNING: CPU: 11 PID: 705 at
>> drivers/infiniband/core/verbs.c:303 ib_dealloc_pd+0x58/0xa0 [ib_core]
>> [ 920.340210] Modules linked in: target_core_user target_core_pscsi
>> target_core_file target_core_iblock 8021q garp mrp rpcrdma sunrpc
>> ib_isert ib_iser ib_srpt ib_srp scsi_transport_srp ib_ipoib
>> iptable_filter rdma_ucm i
>> b_
Re: iscsi_trx going into D state
I realized that I did not set the default RoCE mode to v2 and the
client is on a different subnet, probably why I'm seeing the -110
error. Iser should not go into D state because of this and should
handle this gracefully, but may provide an easy way to replicate the
issue.
Robert LeBlanc
PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Tue, Dec 27, 2016 at 1:22 PM, Robert LeBlanc wrote:
> I looked at this code and it is quiet above my ability. I created this
> patch, but I don't know how to interrogate the queue to see how many
> items there are. If you can give me some more direction on what to
> try, I can keep fumbling around with this until someone smarter than
> me can figure it out. This is now a blocker for me so I'm going to
> beat my head on this until it is fixed.
>
> Thanks for being patient with me.
>
> diff --git a/drivers/infiniband/core/verbs.c b/drivers/infiniband/core/verbs.c
> index 8368764..9e5bd4b 100644
> --- a/drivers/infiniband/core/verbs.c
> +++ b/drivers/infiniband/core/verbs.c
> @@ -1954,22 +1954,27 @@ static void __ib_drain_sq(struct ib_qp *qp)
> return;
> }
>
> + printk("Setting up drain callback.");
> swr.wr_cqe = &sdrain.cqe;
> sdrain.cqe.done = ib_drain_qp_done;
> + printk("Starting init_completion.");
> init_completion(&sdrain.done);
>
> + printk("Calling ib_modify_qp.");
> ret = ib_modify_qp(qp, &attr, IB_QP_STATE);
> if (ret) {
> WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
> return;
> }
>
> + printk("Calling ib_post_send.");
> ret = ib_post_send(qp, &swr, &bad_swr);
> if (ret) {
> WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
> return;
> }
>
> + printk("Starting wait_for_completion.");
> wait_for_completion(&sdrain.done);
> }
>
> I get the same processes in D state (and same backtrace) and this is
> what shows up in dmesg:
>
> [ 920.317401] isert: isert_rdma_accept: rdma_accept() failed with: -110
> [ 920.325554] [ cut here ]
> [ 920.330188] WARNING: CPU: 11 PID: 705 at
> drivers/infiniband/core/verbs.c:303 ib_dealloc_pd+0x58/0xa0 [ib_core]
> [ 920.340210] Modules linked in: target_core_user target_core_pscsi
> target_core_file target_core_iblock 8021q garp mrp rpcrdma sunrpc
> ib_isert ib_iser ib_srpt ib_srp scsi_transport_srp ib_ipoib
> iptable_filter rdma_ucm i
> b_ucm ib_uverbs ib_umad rdma_cm ib_cm iw_cm sb_edac edac_core
> x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ext4
> ipmi_devintf irqbypass crct10dif_pclmul crc32_pclmul
> ghash_clmulni_intel aesni_intel jbd2 lr
> w gf128mul glue_helper mbcache iTCO_wdt ablk_helper mei_me
> iTCO_vendor_support cryptd joydev sg mei i2c_i801 lpc_ich pcspkr
> mfd_core ioatdma shpchp i2c_smbus ipmi_si wmi ipmi_msghandler
> acpi_power_meter acpi_pad ip_table
> s xfs libcrc32c raid1 mlx4_en mlx4_ib mlx5_ib sd_mod ib_core ast
> drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm
> mlx5_core igb mlx4_core
> [ 920.412347] ahci ptp drm libahci pps_core libata dca i2c_algo_bit
> be2iscsi bnx2i cnic uio qla4xxx iscsi_boot_sysfs
> [ 920.421744] CPU: 11 PID: 705 Comm: kworker/11:2 Not tainted 4.9.0+ #3
> [ 920.428199] Hardware name: Supermicro SYS-6028TP-HTFR/X10DRT-PIBF,
> BIOS 1.1 08/03/2015
> [ 920.436126] Workqueue: ib_cm cm_work_handler [ib_cm]
> [ 920.441113] c90032a03a40 8134d45f
>
> [ 920.448583] c90032a03a80 81083371 012fa04a1c4a
> 883f5e886e80
> [ 920.456073] 887f1eaa4400 887f1eaa5800 c90032a03b08
> ff92
> [ 920.463535] Call Trace:
> [ 920.465993] [] dump_stack+0x63/0x84
> [ 920.471144] [] __warn+0xd1/0xf0
> [ 920.475941] [] warn_slowpath_null+0x1d/0x20
> [ 920.481790] [] ib_dealloc_pd+0x58/0xa0 [ib_core]
> [ 920.488072] [] isert_device_put+0x50/0xc0 [ib_isert]
> [ 920.494693] [] isert_connect_request+0x68e/0xd40
> [ib_isert]
> [ 920.501924] [] isert_cma_handler+0xe3/0x3b0 [ib_isert]
> [ 920.508725] [] ? cma_new_conn_id+0x276/0x4b0 [rdma_cm]
> [ 920.515521] [] cma_listen_handler+0x20/0x30 [rdma_cm]
> [ 920.57] [] cma_req_handler+0x1f5/0x4c0 [rdma_cm]
> [ 920.528851] [] cm_process_work+0x25/0xf0 [ib_cm]
> [ 920.535125] [] cm_req_handler+0x8d4/0xc70 [ib_cm]
> [ 920.541485] [] cm_work_handler+0x1ce/0x1648 [ib_cm]
> [ 920.548021] [] process_one_work+0x152/0x400
> [ 920.553861] [] worker_thread+0x125/0x4b0
> [ 920.559443] [] ? rescuer_thread+0x380/0x380
> [ 920.565284] [] kthread+0xd9/0xf0
> [ 920.570178] [] ? kthread_park+0x60/0x60
> [ 920.576389] [] ret_from_fork+0x25/0x30
> [ 920.582473] ---[ end trace 1f5a1831f9d2d964 ]---
> [ 920.587907] [ cut here ]
> [ 920.593213] WARNING: CPU: 11 PID: 705 at
> drivers/infiniband/core/cq.c:189 ib_free_cq+0x97/0xc0
Re: iscsi_trx going into D state
I looked at this code and it is quiet above my ability. I created this
patch, but I don't know how to interrogate the queue to see how many
items there are. If you can give me some more direction on what to
try, I can keep fumbling around with this until someone smarter than
me can figure it out. This is now a blocker for me so I'm going to
beat my head on this until it is fixed.
Thanks for being patient with me.
diff --git a/drivers/infiniband/core/verbs.c b/drivers/infiniband/core/verbs.c
index 8368764..9e5bd4b 100644
--- a/drivers/infiniband/core/verbs.c
+++ b/drivers/infiniband/core/verbs.c
@@ -1954,22 +1954,27 @@ static void __ib_drain_sq(struct ib_qp *qp)
return;
}
+ printk("Setting up drain callback.");
swr.wr_cqe = &sdrain.cqe;
sdrain.cqe.done = ib_drain_qp_done;
+ printk("Starting init_completion.");
init_completion(&sdrain.done);
+ printk("Calling ib_modify_qp.");
ret = ib_modify_qp(qp, &attr, IB_QP_STATE);
if (ret) {
WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
return;
}
+ printk("Calling ib_post_send.");
ret = ib_post_send(qp, &swr, &bad_swr);
if (ret) {
WARN_ONCE(ret, "failed to drain send queue: %d\n", ret);
return;
}
+ printk("Starting wait_for_completion.");
wait_for_completion(&sdrain.done);
}
I get the same processes in D state (and same backtrace) and this is
what shows up in dmesg:
[ 920.317401] isert: isert_rdma_accept: rdma_accept() failed with: -110
[ 920.325554] [ cut here ]
[ 920.330188] WARNING: CPU: 11 PID: 705 at
drivers/infiniband/core/verbs.c:303 ib_dealloc_pd+0x58/0xa0 [ib_core]
[ 920.340210] Modules linked in: target_core_user target_core_pscsi
target_core_file target_core_iblock 8021q garp mrp rpcrdma sunrpc
ib_isert ib_iser ib_srpt ib_srp scsi_transport_srp ib_ipoib
iptable_filter rdma_ucm i
b_ucm ib_uverbs ib_umad rdma_cm ib_cm iw_cm sb_edac edac_core
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ext4
ipmi_devintf irqbypass crct10dif_pclmul crc32_pclmul
ghash_clmulni_intel aesni_intel jbd2 lr
w gf128mul glue_helper mbcache iTCO_wdt ablk_helper mei_me
iTCO_vendor_support cryptd joydev sg mei i2c_i801 lpc_ich pcspkr
mfd_core ioatdma shpchp i2c_smbus ipmi_si wmi ipmi_msghandler
acpi_power_meter acpi_pad ip_table
s xfs libcrc32c raid1 mlx4_en mlx4_ib mlx5_ib sd_mod ib_core ast
drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm
mlx5_core igb mlx4_core
[ 920.412347] ahci ptp drm libahci pps_core libata dca i2c_algo_bit
be2iscsi bnx2i cnic uio qla4xxx iscsi_boot_sysfs
[ 920.421744] CPU: 11 PID: 705 Comm: kworker/11:2 Not tainted 4.9.0+ #3
[ 920.428199] Hardware name: Supermicro SYS-6028TP-HTFR/X10DRT-PIBF,
BIOS 1.1 08/03/2015
[ 920.436126] Workqueue: ib_cm cm_work_handler [ib_cm]
[ 920.441113] c90032a03a40 8134d45f
[ 920.448583] c90032a03a80 81083371 012fa04a1c4a
883f5e886e80
[ 920.456073] 887f1eaa4400 887f1eaa5800 c90032a03b08
ff92
[ 920.463535] Call Trace:
[ 920.465993] [] dump_stack+0x63/0x84
[ 920.471144] [] __warn+0xd1/0xf0
[ 920.475941] [] warn_slowpath_null+0x1d/0x20
[ 920.481790] [] ib_dealloc_pd+0x58/0xa0 [ib_core]
[ 920.488072] [] isert_device_put+0x50/0xc0 [ib_isert]
[ 920.494693] [] isert_connect_request+0x68e/0xd40
[ib_isert]
[ 920.501924] [] isert_cma_handler+0xe3/0x3b0 [ib_isert]
[ 920.508725] [] ? cma_new_conn_id+0x276/0x4b0 [rdma_cm]
[ 920.515521] [] cma_listen_handler+0x20/0x30 [rdma_cm]
[ 920.57] [] cma_req_handler+0x1f5/0x4c0 [rdma_cm]
[ 920.528851] [] cm_process_work+0x25/0xf0 [ib_cm]
[ 920.535125] [] cm_req_handler+0x8d4/0xc70 [ib_cm]
[ 920.541485] [] cm_work_handler+0x1ce/0x1648 [ib_cm]
[ 920.548021] [] process_one_work+0x152/0x400
[ 920.553861] [] worker_thread+0x125/0x4b0
[ 920.559443] [] ? rescuer_thread+0x380/0x380
[ 920.565284] [] kthread+0xd9/0xf0
[ 920.570178] [] ? kthread_park+0x60/0x60
[ 920.576389] [] ret_from_fork+0x25/0x30
[ 920.582473] ---[ end trace 1f5a1831f9d2d964 ]---
[ 920.587907] [ cut here ]
[ 920.593213] WARNING: CPU: 11 PID: 705 at
drivers/infiniband/core/cq.c:189 ib_free_cq+0x97/0xc0 [ib_core]
[ 920.603383] Modules linked in: target_core_user target_core_pscsi
target_core_file target_core_iblock 8021q garp mrp rpcrdma sunrpc
ib_isert ib_iser ib_srpt ib_srp scsi_transport_srp ib_ipoib
iptable_filter rdma_ucm i
b_ucm ib_uverbs ib_umad rdma_cm ib_cm iw_cm sb_edac edac_core
x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ext4
ipmi_devintf irqbypass crct10dif_pclmul crc32_pclmul
ghash_clmulni_intel aesni_intel jbd2 lr
w gf128mul glue_helper mbcache iTCO_wdt ablk_helper mei_me
iTCO_vendor_support cryptd joydev sg mei i2c_i801 lpc_ich pcspkr
mfd_core ioatdma shpchp i2c_smbus ipmi_si wmi i
Re: iscsi_trx going into D state
On 12/21/2016 6:39 PM, Robert LeBlanc wrote: > I hit a new backtrace today, hopefully it adds something. > > # cat /proc/19659/stack > [] iscsit_stop_session+0x1b1/0x1c0 > [] iscsi_check_for_session_reinstatement+0x1e2/0x270 > [] iscsi_target_check_for_existing_instances+0x30/0x40 > [] iscsi_target_do_login+0x138/0x630 > [] iscsi_target_start_negotiation+0x4e/0xa0 > [] __iscsi_target_login_thread+0x83e/0xf20 > [] iscsi_target_login_thread+0x24/0x30 > [] kthread+0xd9/0xf0 > [] ret_from_fork+0x25/0x30 > [] 0x > > # cat /proc/21342/stack > [] __ib_drain_sq+0x190/0x1c0 [ib_core] > [] ib_drain_sq+0x25/0x30 [ib_core] > [] ib_drain_qp+0x12/0x30 [ib_core] > [] isert_wait_conn+0x5f/0x2d0 [ib_isert] > [] iscsit_close_connection+0x157/0x860 > [] iscsit_take_action_for_connection_exit+0x7b/0xf0 > [] iscsi_target_rx_thread+0x95/0xa0 > [] kthread+0xd9/0xf0 > [] ret_from_fork+0x25/0x30 > [] 0x > > # ps aux | grep iscsi | grep D > root 19659 0.0 0.0 0 0 ?D16:12 0:00 [iscsi_np] > root 21342 0.0 0.0 0 0 ?D16:29 0:00 [iscsi_trx] > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 That looks suspiciously like the __ib_drain_sq is stuck forever waiting on a completion that never comes. > > On Thu, Dec 15, 2016 at 1:38 PM, Robert LeBlanc wrote: >> Nicholas, >> >> I've found that the kernels I used were not able to be inspected using >> crash and I could not build the debug info for them. So I built a new >> 4.9 kernel and verified that I could inspect the crash. It is located >> at [1]. >> >> [1] http://mirrors.betterservers.com/trace/crash2.tar.xz >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> >> >> On Mon, Dec 12, 2016 at 4:57 PM, Robert LeBlanc wrote: >>> Nicholas, >>> >>> After lots of set backs and having to give up trying to get kernel >>> dumps on our "production" systems, I've been able to work out the >>> issues we had with kdump and replicate the issue on my dev boxes. I >>> have dumps from 4.4.30 and 4.9-rc8 (makedumpfile would not dump, so it >>> is a straight copy of /proc/vmcore from the crash kernel). In each >>> crash directory, I put a details.txt file that has the process IDs >>> that were having problems and a brief description of the set-up at the >>> time. This was mostly replicated by starting fio and pulling the >>> Infiniband cable until fio gave up. This hardware also has Mellanox >>> ConnectX4-LX cards and I also replicated the issue over RoCE using 4.9 >>> since it has the drivers in-box. Please let me know if you need more >>> info, I can test much faster now. The cores/kernels/modules are >>> located at [1]. >>> >>> [1] http://mirrors.betterservers.com/trace/crash.tar.xz >>> >>> Thanks, >>> Robert >>> >>> Robert LeBlanc >>> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >>> >>> >>> On Fri, Nov 4, 2016 at 3:57 PM, Robert LeBlanc wrote: We hit this yesterday, this time it was on the tx thread (the other ones before seem to be on the rx thread). We weren't able to get a kernel dump on this. We'll try to get one next time. # ps axuw | grep "D.*iscs[i]" root 12383 0.0 0.0 0 0 ?DNov03 0:04 [iscsi_np] root 23016 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] root 23018 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] # cat /proc/12383/stack [] iscsit_stop_session+0x19f/0x1d0 [] iscsi_check_for_session_reinstatement+0x1e6/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x140/0x640 [] iscsi_target_start_negotiation+0x1c/0xb0 [] iscsi_target_login_thread+0xa9b/0xfc0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x # cat /proc/23016/stack [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x870 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_tx_thread+0x1aa/0x1d0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x # cat /proc/23018/stack [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x870 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_tx_thread+0x1aa/0x1d0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x From dmesg: [ 394.476332] INFO: rcu_sched self-detected stall on CPU [ 394.476334] 20-...: (23976 ticks this GP) idle=edd/141/0 softirq=292/292 fqs=18788 [ 394.476336] (t=24003 jiffies g=3146 c=3145 q=0) [ 394.476337] Task dump for CPU 20: [ 394.476338] kworker/u68:2 R running ta
Re: iscsi_trx going into D state
I hit a new backtrace today, hopefully it adds something. # cat /proc/19659/stack [] iscsit_stop_session+0x1b1/0x1c0 [] iscsi_check_for_session_reinstatement+0x1e2/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x138/0x630 [] iscsi_target_start_negotiation+0x4e/0xa0 [] __iscsi_target_login_thread+0x83e/0xf20 [] iscsi_target_login_thread+0x24/0x30 [] kthread+0xd9/0xf0 [] ret_from_fork+0x25/0x30 [] 0x # cat /proc/21342/stack [] __ib_drain_sq+0x190/0x1c0 [ib_core] [] ib_drain_sq+0x25/0x30 [ib_core] [] ib_drain_qp+0x12/0x30 [ib_core] [] isert_wait_conn+0x5f/0x2d0 [ib_isert] [] iscsit_close_connection+0x157/0x860 [] iscsit_take_action_for_connection_exit+0x7b/0xf0 [] iscsi_target_rx_thread+0x95/0xa0 [] kthread+0xd9/0xf0 [] ret_from_fork+0x25/0x30 [] 0x # ps aux | grep iscsi | grep D root 19659 0.0 0.0 0 0 ?D16:12 0:00 [iscsi_np] root 21342 0.0 0.0 0 0 ?D16:29 0:00 [iscsi_trx] Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Thu, Dec 15, 2016 at 1:38 PM, Robert LeBlanc wrote: > Nicholas, > > I've found that the kernels I used were not able to be inspected using > crash and I could not build the debug info for them. So I built a new > 4.9 kernel and verified that I could inspect the crash. It is located > at [1]. > > [1] http://mirrors.betterservers.com/trace/crash2.tar.xz > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Mon, Dec 12, 2016 at 4:57 PM, Robert LeBlanc wrote: >> Nicholas, >> >> After lots of set backs and having to give up trying to get kernel >> dumps on our "production" systems, I've been able to work out the >> issues we had with kdump and replicate the issue on my dev boxes. I >> have dumps from 4.4.30 and 4.9-rc8 (makedumpfile would not dump, so it >> is a straight copy of /proc/vmcore from the crash kernel). In each >> crash directory, I put a details.txt file that has the process IDs >> that were having problems and a brief description of the set-up at the >> time. This was mostly replicated by starting fio and pulling the >> Infiniband cable until fio gave up. This hardware also has Mellanox >> ConnectX4-LX cards and I also replicated the issue over RoCE using 4.9 >> since it has the drivers in-box. Please let me know if you need more >> info, I can test much faster now. The cores/kernels/modules are >> located at [1]. >> >> [1] http://mirrors.betterservers.com/trace/crash.tar.xz >> >> Thanks, >> Robert >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> >> >> On Fri, Nov 4, 2016 at 3:57 PM, Robert LeBlanc wrote: >>> We hit this yesterday, this time it was on the tx thread (the other >>> ones before seem to be on the rx thread). We weren't able to get a >>> kernel dump on this. We'll try to get one next time. >>> >>> # ps axuw | grep "D.*iscs[i]" >>> root 12383 0.0 0.0 0 0 ?DNov03 0:04 [iscsi_np] >>> root 23016 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] >>> root 23018 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] >>> # cat /proc/12383/stack >>> [] iscsit_stop_session+0x19f/0x1d0 >>> [] iscsi_check_for_session_reinstatement+0x1e6/0x270 >>> [] iscsi_target_check_for_existing_instances+0x30/0x40 >>> [] iscsi_target_do_login+0x140/0x640 >>> [] iscsi_target_start_negotiation+0x1c/0xb0 >>> [] iscsi_target_login_thread+0xa9b/0xfc0 >>> [] kthread+0xd8/0xf0 >>> [] ret_from_fork+0x3f/0x70 >>> [] 0x >>> # cat /proc/23016/stack >>> [] target_wait_for_sess_cmds+0x49/0x1a0 >>> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] >>> [] iscsit_close_connection+0x162/0x870 >>> [] iscsit_take_action_for_connection_exit+0x7f/0x100 >>> [] iscsi_target_tx_thread+0x1aa/0x1d0 >>> [] kthread+0xd8/0xf0 >>> [] ret_from_fork+0x3f/0x70 >>> [] 0x >>> # cat /proc/23018/stack >>> [] target_wait_for_sess_cmds+0x49/0x1a0 >>> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] >>> [] iscsit_close_connection+0x162/0x870 >>> [] iscsit_take_action_for_connection_exit+0x7f/0x100 >>> [] iscsi_target_tx_thread+0x1aa/0x1d0 >>> [] kthread+0xd8/0xf0 >>> [] ret_from_fork+0x3f/0x70 >>> [] 0x >>> >>> From dmesg: >>> [ 394.476332] INFO: rcu_sched self-detected stall on CPU >>> [ 394.476334] 20-...: (23976 ticks this GP) >>> idle=edd/141/0 softirq=292/292 fqs=18788 >>> [ 394.476336] (t=24003 jiffies g=3146 c=3145 q=0) >>> [ 394.476337] Task dump for CPU 20: >>> [ 394.476338] kworker/u68:2 R running task0 12906 2 >>> 0x0008 >>> [ 394.476345] Workqueue: isert_comp_wq isert_cq_work [ib_isert] >>> [ 394.476346] 883f2fe38000 f805705e 883f7fd03da8 >>> 810ac8ff >>> [ 394.476347] 0014 81adb680 883f7fd03dc0 >>> 810af239 >>> [ 394.476348] 00
Re: iscsi_trx going into D state
Nicholas, I've found that the kernels I used were not able to be inspected using crash and I could not build the debug info for them. So I built a new 4.9 kernel and verified that I could inspect the crash. It is located at [1]. [1] http://mirrors.betterservers.com/trace/crash2.tar.xz Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Dec 12, 2016 at 4:57 PM, Robert LeBlanc wrote: > Nicholas, > > After lots of set backs and having to give up trying to get kernel > dumps on our "production" systems, I've been able to work out the > issues we had with kdump and replicate the issue on my dev boxes. I > have dumps from 4.4.30 and 4.9-rc8 (makedumpfile would not dump, so it > is a straight copy of /proc/vmcore from the crash kernel). In each > crash directory, I put a details.txt file that has the process IDs > that were having problems and a brief description of the set-up at the > time. This was mostly replicated by starting fio and pulling the > Infiniband cable until fio gave up. This hardware also has Mellanox > ConnectX4-LX cards and I also replicated the issue over RoCE using 4.9 > since it has the drivers in-box. Please let me know if you need more > info, I can test much faster now. The cores/kernels/modules are > located at [1]. > > [1] http://mirrors.betterservers.com/trace/crash.tar.xz > > Thanks, > Robert > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Fri, Nov 4, 2016 at 3:57 PM, Robert LeBlanc wrote: >> We hit this yesterday, this time it was on the tx thread (the other >> ones before seem to be on the rx thread). We weren't able to get a >> kernel dump on this. We'll try to get one next time. >> >> # ps axuw | grep "D.*iscs[i]" >> root 12383 0.0 0.0 0 0 ?DNov03 0:04 [iscsi_np] >> root 23016 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] >> root 23018 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] >> # cat /proc/12383/stack >> [] iscsit_stop_session+0x19f/0x1d0 >> [] iscsi_check_for_session_reinstatement+0x1e6/0x270 >> [] iscsi_target_check_for_existing_instances+0x30/0x40 >> [] iscsi_target_do_login+0x140/0x640 >> [] iscsi_target_start_negotiation+0x1c/0xb0 >> [] iscsi_target_login_thread+0xa9b/0xfc0 >> [] kthread+0xd8/0xf0 >> [] ret_from_fork+0x3f/0x70 >> [] 0x >> # cat /proc/23016/stack >> [] target_wait_for_sess_cmds+0x49/0x1a0 >> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] >> [] iscsit_close_connection+0x162/0x870 >> [] iscsit_take_action_for_connection_exit+0x7f/0x100 >> [] iscsi_target_tx_thread+0x1aa/0x1d0 >> [] kthread+0xd8/0xf0 >> [] ret_from_fork+0x3f/0x70 >> [] 0x >> # cat /proc/23018/stack >> [] target_wait_for_sess_cmds+0x49/0x1a0 >> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] >> [] iscsit_close_connection+0x162/0x870 >> [] iscsit_take_action_for_connection_exit+0x7f/0x100 >> [] iscsi_target_tx_thread+0x1aa/0x1d0 >> [] kthread+0xd8/0xf0 >> [] ret_from_fork+0x3f/0x70 >> [] 0x >> >> From dmesg: >> [ 394.476332] INFO: rcu_sched self-detected stall on CPU >> [ 394.476334] 20-...: (23976 ticks this GP) >> idle=edd/141/0 softirq=292/292 fqs=18788 >> [ 394.476336] (t=24003 jiffies g=3146 c=3145 q=0) >> [ 394.476337] Task dump for CPU 20: >> [ 394.476338] kworker/u68:2 R running task0 12906 2 >> 0x0008 >> [ 394.476345] Workqueue: isert_comp_wq isert_cq_work [ib_isert] >> [ 394.476346] 883f2fe38000 f805705e 883f7fd03da8 >> 810ac8ff >> [ 394.476347] 0014 81adb680 883f7fd03dc0 >> 810af239 >> [ 394.476348] 0015 883f7fd03df0 810e1cd0 >> 883f7fd17b80 >> [ 394.476348] Call Trace: >> [ 394.476354][] sched_show_task+0xaf/0x110 >> [ 394.476355] [] dump_cpu_task+0x39/0x40 >> [ 394.476357] [] rcu_dump_cpu_stacks+0x80/0xb0 >> [ 394.476359] [] rcu_check_callbacks+0x540/0x820 >> [ 394.476360] [] ? account_system_time+0x81/0x110 >> [ 394.476363] [] ? tick_sched_do_timer+0x50/0x50 >> [ 394.476364] [] update_process_times+0x39/0x60 >> [ 394.476365] [] tick_sched_handle.isra.17+0x25/0x60 >> [ 394.476366] [] tick_sched_timer+0x3d/0x70 >> [ 394.476368] [] __hrtimer_run_queues+0x102/0x290 >> [ 394.476369] [] hrtimer_interrupt+0xa8/0x1a0 >> [ 394.476372] [] local_apic_timer_interrupt+0x35/0x60 >> [ 394.476374] [] smp_apic_timer_interrupt+0x3d/0x50 >> [ 394.476376] [] apic_timer_interrupt+0x87/0x90 >> [ 394.476379][] ? console_unlock+0x41e/0x4e0 >> [ 394.476380] [] vprintk_emit+0x2fc/0x500 >> [ 394.476382] [] vprintk_default+0x1f/0x30 >> [ 394.476384] [] printk+0x5d/0x74 >> [ 394.476388] [] transport_lookup_cmd_lun+0x1d1/0x200 >> [ 394.476390] [] iscsit_setup_scsi_cmd+0x230/0x540 >> [ 394.476392] [] isert_rx_do_work+0x3f3/0x7f0 [ib_isert] >> [ 394.476394] [] isert_cq_work+0x184/0x770 [ib_isert] >> [
Re: iscsi_trx going into D state
Nicholas, After lots of set backs and having to give up trying to get kernel dumps on our "production" systems, I've been able to work out the issues we had with kdump and replicate the issue on my dev boxes. I have dumps from 4.4.30 and 4.9-rc8 (makedumpfile would not dump, so it is a straight copy of /proc/vmcore from the crash kernel). In each crash directory, I put a details.txt file that has the process IDs that were having problems and a brief description of the set-up at the time. This was mostly replicated by starting fio and pulling the Infiniband cable until fio gave up. This hardware also has Mellanox ConnectX4-LX cards and I also replicated the issue over RoCE using 4.9 since it has the drivers in-box. Please let me know if you need more info, I can test much faster now. The cores/kernels/modules are located at [1]. [1] http://mirrors.betterservers.com/trace/crash.tar.xz Thanks, Robert Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Nov 4, 2016 at 3:57 PM, Robert LeBlanc wrote: > We hit this yesterday, this time it was on the tx thread (the other > ones before seem to be on the rx thread). We weren't able to get a > kernel dump on this. We'll try to get one next time. > > # ps axuw | grep "D.*iscs[i]" > root 12383 0.0 0.0 0 0 ?DNov03 0:04 [iscsi_np] > root 23016 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] > root 23018 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] > # cat /proc/12383/stack > [] iscsit_stop_session+0x19f/0x1d0 > [] iscsi_check_for_session_reinstatement+0x1e6/0x270 > [] iscsi_target_check_for_existing_instances+0x30/0x40 > [] iscsi_target_do_login+0x140/0x640 > [] iscsi_target_start_negotiation+0x1c/0xb0 > [] iscsi_target_login_thread+0xa9b/0xfc0 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > # cat /proc/23016/stack > [] target_wait_for_sess_cmds+0x49/0x1a0 > [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] > [] iscsit_close_connection+0x162/0x870 > [] iscsit_take_action_for_connection_exit+0x7f/0x100 > [] iscsi_target_tx_thread+0x1aa/0x1d0 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > # cat /proc/23018/stack > [] target_wait_for_sess_cmds+0x49/0x1a0 > [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] > [] iscsit_close_connection+0x162/0x870 > [] iscsit_take_action_for_connection_exit+0x7f/0x100 > [] iscsi_target_tx_thread+0x1aa/0x1d0 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > > From dmesg: > [ 394.476332] INFO: rcu_sched self-detected stall on CPU > [ 394.476334] 20-...: (23976 ticks this GP) > idle=edd/141/0 softirq=292/292 fqs=18788 > [ 394.476336] (t=24003 jiffies g=3146 c=3145 q=0) > [ 394.476337] Task dump for CPU 20: > [ 394.476338] kworker/u68:2 R running task0 12906 2 > 0x0008 > [ 394.476345] Workqueue: isert_comp_wq isert_cq_work [ib_isert] > [ 394.476346] 883f2fe38000 f805705e 883f7fd03da8 > 810ac8ff > [ 394.476347] 0014 81adb680 883f7fd03dc0 > 810af239 > [ 394.476348] 0015 883f7fd03df0 810e1cd0 > 883f7fd17b80 > [ 394.476348] Call Trace: > [ 394.476354][] sched_show_task+0xaf/0x110 > [ 394.476355] [] dump_cpu_task+0x39/0x40 > [ 394.476357] [] rcu_dump_cpu_stacks+0x80/0xb0 > [ 394.476359] [] rcu_check_callbacks+0x540/0x820 > [ 394.476360] [] ? account_system_time+0x81/0x110 > [ 394.476363] [] ? tick_sched_do_timer+0x50/0x50 > [ 394.476364] [] update_process_times+0x39/0x60 > [ 394.476365] [] tick_sched_handle.isra.17+0x25/0x60 > [ 394.476366] [] tick_sched_timer+0x3d/0x70 > [ 394.476368] [] __hrtimer_run_queues+0x102/0x290 > [ 394.476369] [] hrtimer_interrupt+0xa8/0x1a0 > [ 394.476372] [] local_apic_timer_interrupt+0x35/0x60 > [ 394.476374] [] smp_apic_timer_interrupt+0x3d/0x50 > [ 394.476376] [] apic_timer_interrupt+0x87/0x90 > [ 394.476379][] ? console_unlock+0x41e/0x4e0 > [ 394.476380] [] vprintk_emit+0x2fc/0x500 > [ 394.476382] [] vprintk_default+0x1f/0x30 > [ 394.476384] [] printk+0x5d/0x74 > [ 394.476388] [] transport_lookup_cmd_lun+0x1d1/0x200 > [ 394.476390] [] iscsit_setup_scsi_cmd+0x230/0x540 > [ 394.476392] [] isert_rx_do_work+0x3f3/0x7f0 [ib_isert] > [ 394.476394] [] isert_cq_work+0x184/0x770 [ib_isert] > [ 394.476396] [] process_one_work+0x14f/0x400 > [ 394.476397] [] worker_thread+0x114/0x470 > [ 394.476398] [] ? __schedule+0x34a/0x7f0 > [ 394.476399] [] ? rescuer_thread+0x310/0x310 > [ 394.476400] [] kthread+0xd8/0xf0 > [ 394.476402] [] ? kthread_park+0x60/0x60 > [ 394.476403] [] ret_from_fork+0x3f/0x70 > [ 394.476404] [] ? kthread_park+0x60/0x60 > [ 405.716632] Unexpected ret: -104 send data 360 > [ 405.721711] tx_data returned -32, expecting 360. > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA
Re: iscsi_trx going into D state
We hit this yesterday, this time it was on the tx thread (the other ones before seem to be on the rx thread). We weren't able to get a kernel dump on this. We'll try to get one next time. # ps axuw | grep "D.*iscs[i]" root 12383 0.0 0.0 0 0 ?DNov03 0:04 [iscsi_np] root 23016 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] root 23018 0.0 0.0 0 0 ?DNov03 0:00 [iscsi_ttx] # cat /proc/12383/stack [] iscsit_stop_session+0x19f/0x1d0 [] iscsi_check_for_session_reinstatement+0x1e6/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x140/0x640 [] iscsi_target_start_negotiation+0x1c/0xb0 [] iscsi_target_login_thread+0xa9b/0xfc0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x # cat /proc/23016/stack [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x870 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_tx_thread+0x1aa/0x1d0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x # cat /proc/23018/stack [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x870 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_tx_thread+0x1aa/0x1d0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x >From dmesg: [ 394.476332] INFO: rcu_sched self-detected stall on CPU [ 394.476334] 20-...: (23976 ticks this GP) idle=edd/141/0 softirq=292/292 fqs=18788 [ 394.476336] (t=24003 jiffies g=3146 c=3145 q=0) [ 394.476337] Task dump for CPU 20: [ 394.476338] kworker/u68:2 R running task0 12906 2 0x0008 [ 394.476345] Workqueue: isert_comp_wq isert_cq_work [ib_isert] [ 394.476346] 883f2fe38000 f805705e 883f7fd03da8 810ac8ff [ 394.476347] 0014 81adb680 883f7fd03dc0 810af239 [ 394.476348] 0015 883f7fd03df0 810e1cd0 883f7fd17b80 [ 394.476348] Call Trace: [ 394.476354][] sched_show_task+0xaf/0x110 [ 394.476355] [] dump_cpu_task+0x39/0x40 [ 394.476357] [] rcu_dump_cpu_stacks+0x80/0xb0 [ 394.476359] [] rcu_check_callbacks+0x540/0x820 [ 394.476360] [] ? account_system_time+0x81/0x110 [ 394.476363] [] ? tick_sched_do_timer+0x50/0x50 [ 394.476364] [] update_process_times+0x39/0x60 [ 394.476365] [] tick_sched_handle.isra.17+0x25/0x60 [ 394.476366] [] tick_sched_timer+0x3d/0x70 [ 394.476368] [] __hrtimer_run_queues+0x102/0x290 [ 394.476369] [] hrtimer_interrupt+0xa8/0x1a0 [ 394.476372] [] local_apic_timer_interrupt+0x35/0x60 [ 394.476374] [] smp_apic_timer_interrupt+0x3d/0x50 [ 394.476376] [] apic_timer_interrupt+0x87/0x90 [ 394.476379][] ? console_unlock+0x41e/0x4e0 [ 394.476380] [] vprintk_emit+0x2fc/0x500 [ 394.476382] [] vprintk_default+0x1f/0x30 [ 394.476384] [] printk+0x5d/0x74 [ 394.476388] [] transport_lookup_cmd_lun+0x1d1/0x200 [ 394.476390] [] iscsit_setup_scsi_cmd+0x230/0x540 [ 394.476392] [] isert_rx_do_work+0x3f3/0x7f0 [ib_isert] [ 394.476394] [] isert_cq_work+0x184/0x770 [ib_isert] [ 394.476396] [] process_one_work+0x14f/0x400 [ 394.476397] [] worker_thread+0x114/0x470 [ 394.476398] [] ? __schedule+0x34a/0x7f0 [ 394.476399] [] ? rescuer_thread+0x310/0x310 [ 394.476400] [] kthread+0xd8/0xf0 [ 394.476402] [] ? kthread_park+0x60/0x60 [ 394.476403] [] ret_from_fork+0x3f/0x70 [ 394.476404] [] ? kthread_park+0x60/0x60 [ 405.716632] Unexpected ret: -104 send data 360 [ 405.721711] tx_data returned -32, expecting 360. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Oct 31, 2016 at 10:34 AM, Robert LeBlanc wrote: > Nicholas, > > Thanks for following up on this. We have been chasing other bugs in > our provisioning and as such has reduced our load on the boxes. We are > hoping to get that all straightened out this week and do some more > testing. So far we have not had any iSCSI in D state since the patch, > be we haven't been able to test it well either. We will keep you > updated. > > Thank you, > Robert LeBlanc > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Sat, Oct 29, 2016 at 4:29 PM, Nicholas A. Bellinger > wrote: >> Hi Robert, >> >> On Wed, 2016-10-19 at 10:41 -0600, Robert LeBlanc wrote: >>> Nicholas, >>> >>> I didn't have high hopes for the patch because we were not seeing >>> TMR_ABORT_TASK (or 'abort') in dmesg or /var/log/messages, but it >>> seemed to help regardless. Our clients finally OOMed from the hung >>> sessions, so we are having to reboot them and we will do some more >>> testing. We haven't put the updated kernel on our clients yet. Our >>> clients have iSCSI root disks so I'm not sure if we can get a vmcore >>> on those, but we will do what we can to get you a vmcore from the >>
Re: iscsi_trx going into D state
Nicholas, Thanks for following up on this. We have been chasing other bugs in our provisioning and as such has reduced our load on the boxes. We are hoping to get that all straightened out this week and do some more testing. So far we have not had any iSCSI in D state since the patch, be we haven't been able to test it well either. We will keep you updated. Thank you, Robert LeBlanc Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Sat, Oct 29, 2016 at 4:29 PM, Nicholas A. Bellinger wrote: > Hi Robert, > > On Wed, 2016-10-19 at 10:41 -0600, Robert LeBlanc wrote: >> Nicholas, >> >> I didn't have high hopes for the patch because we were not seeing >> TMR_ABORT_TASK (or 'abort') in dmesg or /var/log/messages, but it >> seemed to help regardless. Our clients finally OOMed from the hung >> sessions, so we are having to reboot them and we will do some more >> testing. We haven't put the updated kernel on our clients yet. Our >> clients have iSCSI root disks so I'm not sure if we can get a vmcore >> on those, but we will do what we can to get you a vmcore from the >> target if it happens again. >> > > Just checking in to see if you've observed further issues with > iser-target ports, and/or able to generate a crashdump with v4.4.y..? > >> As far as our configuration: It is a superMicro box with 6 SAMSUNG >> MZ7LM3T8HCJM-5 SSDs. Two are for root and four are in mdadm >> RAID-10 for exporting via iSCSI/iSER. We have ZFS on top of the >> RAID-10 for checksum and snapshots only and we export ZVols to the >> clients (one or more per VM on the client). We do not persist the >> export info (targetcli saveconfig), but regenerate it from scripts. >> The client receives two or more of these exports and puts them in a >> RAID-1 device. The exports are served by iSER one one port and also by >> normal iSCSI on a different port for compatibility, but not normally >> used. If you need more info about the config, please let me know. It >> was kind of a vague request so I'm not sure what exactly is important >> to you. > > Thanks for the extra details of your hardware + user-space > configuration. > >> Thanks for helping us with this, >> Robert LeBlanc >> >> When we have problems, we usually see this in the logs: >> Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login timeout on >> Network Portal 0.0.0.0:3260 >> Oct 17 08:57:50 prv-0-12-sanstack kernel: Unexpected ret: -104 send data 48 >> Oct 17 08:57:50 prv-0-12-sanstack kernel: tx_data returned -32, expecting 48. >> Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login negotiation failed. >> >> I found some backtraces in the logs, not sure if this is helpful, this >> is before your patch (your patch booted at Oct 18 10:36:59): >> Oct 17 15:43:12 prv-0-12-sanstack kernel: INFO: rcu_sched >> self-detected stall on CPU >> Oct 17 15:43:12 prv-0-12-sanstack kernel: #0115-...: (41725 ticks this >> GP) idle=b59/141/0 softirq=535/535 fqs=30992 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: #011 (t=42006 jiffies g=1550 >> c=1549 q=0) >> Oct 17 15:43:12 prv-0-12-sanstack kernel: Task dump for CPU 5: >> Oct 17 15:43:12 prv-0-12-sanstack kernel: kworker/u68:2 R running >> task0 17967 2 0x0008 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: Workqueue: isert_comp_wq >> isert_cq_work [ib_isert] >> Oct 17 15:43:12 prv-0-12-sanstack kernel: 883f4c0dca80 >> af8ca7a4 883f7fb43da8 810ac83f >> Oct 17 15:43:12 prv-0-12-sanstack kernel: 0005 >> 81adb680 883f7fb43dc0 810af179 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: 0006 >> 883f7fb43df0 810e1c10 883f7fb57b80 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: Call Trace: >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> sched_show_task+0xaf/0x110 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> dump_cpu_task+0x39/0x40 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> rcu_dump_cpu_stacks+0x80/0xb0 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> rcu_check_callbacks+0x540/0x820 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? >> account_system_time+0x81/0x110 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? >> tick_sched_do_timer+0x50/0x50 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> update_process_times+0x39/0x60 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> tick_sched_handle.isra.17+0x25/0x60 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> tick_sched_timer+0x3d/0x70 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> __hrtimer_run_queues+0x102/0x290 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> hrtimer_interrupt+0xa8/0x1a0 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> local_apic_timer_interrupt+0x35/0x60 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> smp_apic_timer_interrupt+0x3d/0x50 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> apic_timer_interrupt+0x87/0x90 >> Oct 17 15:43:12 prv-0-12-sanstack kernel: [] >> ? console_unlock+0x41e/0x4e0
Re: iscsi_trx going into D state
Hi Robert, On Wed, 2016-10-19 at 10:41 -0600, Robert LeBlanc wrote: > Nicholas, > > I didn't have high hopes for the patch because we were not seeing > TMR_ABORT_TASK (or 'abort') in dmesg or /var/log/messages, but it > seemed to help regardless. Our clients finally OOMed from the hung > sessions, so we are having to reboot them and we will do some more > testing. We haven't put the updated kernel on our clients yet. Our > clients have iSCSI root disks so I'm not sure if we can get a vmcore > on those, but we will do what we can to get you a vmcore from the > target if it happens again. > Just checking in to see if you've observed further issues with iser-target ports, and/or able to generate a crashdump with v4.4.y..? > As far as our configuration: It is a superMicro box with 6 SAMSUNG > MZ7LM3T8HCJM-5 SSDs. Two are for root and four are in mdadm > RAID-10 for exporting via iSCSI/iSER. We have ZFS on top of the > RAID-10 for checksum and snapshots only and we export ZVols to the > clients (one or more per VM on the client). We do not persist the > export info (targetcli saveconfig), but regenerate it from scripts. > The client receives two or more of these exports and puts them in a > RAID-1 device. The exports are served by iSER one one port and also by > normal iSCSI on a different port for compatibility, but not normally > used. If you need more info about the config, please let me know. It > was kind of a vague request so I'm not sure what exactly is important > to you. Thanks for the extra details of your hardware + user-space configuration. > Thanks for helping us with this, > Robert LeBlanc > > When we have problems, we usually see this in the logs: > Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login timeout on > Network Portal 0.0.0.0:3260 > Oct 17 08:57:50 prv-0-12-sanstack kernel: Unexpected ret: -104 send data 48 > Oct 17 08:57:50 prv-0-12-sanstack kernel: tx_data returned -32, expecting 48. > Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login negotiation failed. > > I found some backtraces in the logs, not sure if this is helpful, this > is before your patch (your patch booted at Oct 18 10:36:59): > Oct 17 15:43:12 prv-0-12-sanstack kernel: INFO: rcu_sched > self-detected stall on CPU > Oct 17 15:43:12 prv-0-12-sanstack kernel: #0115-...: (41725 ticks this > GP) idle=b59/141/0 softirq=535/535 fqs=30992 > Oct 17 15:43:12 prv-0-12-sanstack kernel: #011 (t=42006 jiffies g=1550 > c=1549 q=0) > Oct 17 15:43:12 prv-0-12-sanstack kernel: Task dump for CPU 5: > Oct 17 15:43:12 prv-0-12-sanstack kernel: kworker/u68:2 R running > task0 17967 2 0x0008 > Oct 17 15:43:12 prv-0-12-sanstack kernel: Workqueue: isert_comp_wq > isert_cq_work [ib_isert] > Oct 17 15:43:12 prv-0-12-sanstack kernel: 883f4c0dca80 > af8ca7a4 883f7fb43da8 810ac83f > Oct 17 15:43:12 prv-0-12-sanstack kernel: 0005 > 81adb680 883f7fb43dc0 810af179 > Oct 17 15:43:12 prv-0-12-sanstack kernel: 0006 > 883f7fb43df0 810e1c10 883f7fb57b80 > Oct 17 15:43:12 prv-0-12-sanstack kernel: Call Trace: > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > sched_show_task+0xaf/0x110 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > dump_cpu_task+0x39/0x40 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > rcu_dump_cpu_stacks+0x80/0xb0 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > rcu_check_callbacks+0x540/0x820 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? > account_system_time+0x81/0x110 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? > tick_sched_do_timer+0x50/0x50 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > update_process_times+0x39/0x60 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > tick_sched_handle.isra.17+0x25/0x60 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > tick_sched_timer+0x3d/0x70 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > __hrtimer_run_queues+0x102/0x290 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > hrtimer_interrupt+0xa8/0x1a0 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > local_apic_timer_interrupt+0x35/0x60 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > smp_apic_timer_interrupt+0x3d/0x50 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > apic_timer_interrupt+0x87/0x90 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > ? console_unlock+0x41e/0x4e0 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > vprintk_emit+0x2fc/0x500 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > vprintk_default+0x1f/0x30 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > printk+0x5d/0x74 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > transport_lookup_cmd_lun+0x1d1/0x200 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > iscsit_setup_scsi_cmd+0x230/0x540 > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > isert_rx_do_work+0x3f3/0x7f0 [ib_isert] > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > isert_cq_work+0x184/0x770 [ib_isert] > Oct 17 15:43:12 prv-0-12-sanstack kernel: [] > process_one_work+0x14f/0x400 > Oct 17 1
Re: iscsi_trx going into D state
Nicholas, I didn't have high hopes for the patch because we were not seeing TMR_ABORT_TASK (or 'abort') in dmesg or /var/log/messages, but it seemed to help regardless. Our clients finally OOMed from the hung sessions, so we are having to reboot them and we will do some more testing. We haven't put the updated kernel on our clients yet. Our clients have iSCSI root disks so I'm not sure if we can get a vmcore on those, but we will do what we can to get you a vmcore from the target if it happens again. As far as our configuration: It is a superMicro box with 6 SAMSUNG MZ7LM3T8HCJM-5 SSDs. Two are for root and four are in mdadm RAID-10 for exporting via iSCSI/iSER. We have ZFS on top of the RAID-10 for checksum and snapshots only and we export ZVols to the clients (one or more per VM on the client). We do not persist the export info (targetcli saveconfig), but regenerate it from scripts. The client receives two or more of these exports and puts them in a RAID-1 device. The exports are served by iSER one one port and also by normal iSCSI on a different port for compatibility, but not normally used. If you need more info about the config, please let me know. It was kind of a vague request so I'm not sure what exactly is important to you. Thanks for helping us with this, Robert LeBlanc When we have problems, we usually see this in the logs: Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login timeout on Network Portal 0.0.0.0:3260 Oct 17 08:57:50 prv-0-12-sanstack kernel: Unexpected ret: -104 send data 48 Oct 17 08:57:50 prv-0-12-sanstack kernel: tx_data returned -32, expecting 48. Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login negotiation failed. I found some backtraces in the logs, not sure if this is helpful, this is before your patch (your patch booted at Oct 18 10:36:59): Oct 17 15:43:12 prv-0-12-sanstack kernel: INFO: rcu_sched self-detected stall on CPU Oct 17 15:43:12 prv-0-12-sanstack kernel: #0115-...: (41725 ticks this GP) idle=b59/141/0 softirq=535/535 fqs=30992 Oct 17 15:43:12 prv-0-12-sanstack kernel: #011 (t=42006 jiffies g=1550 c=1549 q=0) Oct 17 15:43:12 prv-0-12-sanstack kernel: Task dump for CPU 5: Oct 17 15:43:12 prv-0-12-sanstack kernel: kworker/u68:2 R running task0 17967 2 0x0008 Oct 17 15:43:12 prv-0-12-sanstack kernel: Workqueue: isert_comp_wq isert_cq_work [ib_isert] Oct 17 15:43:12 prv-0-12-sanstack kernel: 883f4c0dca80 af8ca7a4 883f7fb43da8 810ac83f Oct 17 15:43:12 prv-0-12-sanstack kernel: 0005 81adb680 883f7fb43dc0 810af179 Oct 17 15:43:12 prv-0-12-sanstack kernel: 0006 883f7fb43df0 810e1c10 883f7fb57b80 Oct 17 15:43:12 prv-0-12-sanstack kernel: Call Trace: Oct 17 15:43:12 prv-0-12-sanstack kernel: [] sched_show_task+0xaf/0x110 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] dump_cpu_task+0x39/0x40 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] rcu_dump_cpu_stacks+0x80/0xb0 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] rcu_check_callbacks+0x540/0x820 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? account_system_time+0x81/0x110 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? tick_sched_do_timer+0x50/0x50 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] update_process_times+0x39/0x60 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] tick_sched_handle.isra.17+0x25/0x60 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] tick_sched_timer+0x3d/0x70 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] __hrtimer_run_queues+0x102/0x290 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] hrtimer_interrupt+0xa8/0x1a0 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] local_apic_timer_interrupt+0x35/0x60 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] smp_apic_timer_interrupt+0x3d/0x50 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] apic_timer_interrupt+0x87/0x90 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? console_unlock+0x41e/0x4e0 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] vprintk_emit+0x2fc/0x500 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] vprintk_default+0x1f/0x30 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] printk+0x5d/0x74 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] transport_lookup_cmd_lun+0x1d1/0x200 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] iscsit_setup_scsi_cmd+0x230/0x540 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] isert_rx_do_work+0x3f3/0x7f0 [ib_isert] Oct 17 15:43:12 prv-0-12-sanstack kernel: [] isert_cq_work+0x184/0x770 [ib_isert] Oct 17 15:43:12 prv-0-12-sanstack kernel: [] process_one_work+0x14f/0x400 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] worker_thread+0x114/0x470 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? __schedule+0x34a/0x7f0 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? rescuer_thread+0x310/0x310 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] kthread+0xd8/0xf0 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? kthread_park+0x60/0x60 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ret_from_fork+0x3f/0x70 Oct 17 15:43:12 prv-0-12-sanstack kernel: [] ? kthread_park+0x60/0x60
Re: iscsi_trx going into D state
On Tue, 2016-10-18 at 16:13 -0600, Robert LeBlanc wrote: > Nicholas, > > We patched this in and for the first time in many reboots, we didn't > have iSCSI going straight into D state. We have had to work on a > couple of other things, so we don't know if this is just a coincidence > or not. We will reboot back into the old kernel and back a few times > and do some more testing, but so far it has given us a little bit of > hope that we may be narrowing down on the root cause. We will report > back once we have some more info. > > Thank you, > Robert LeBlanc > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > Hello Robert, Thanks for the update. Btw, if the original /var/log/messages reproduction logs for iser-target are still handy, I'm happy to have a look to confirm. Feel free to send them along here, or off-list if necessary. For further reference, you can also enable Linux kernel crash dump (LKCD) at build time using CONFIG_CRASH_DUMP=y, so it's possible to manually generate a vmcore dumpfile of the running system via 'echo c > /proc/sysrq-trigger', once the bug occurs. http://cateee.net/lkddb/web-lkddb/CRASH_DUMP.html Note in order to fully debug within this in a LKCD environment, it requires the vmcore dump from /var/crash/, unstripped vmlinux, target_core_mod, iscsi_target_mod and ib_isert modules matching the specific particular x86_64 build setup of the running system. Also, can you share a bit more about the details of your particular iser-target + backend setup..? -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Nicholas, We patched this in and for the first time in many reboots, we didn't have iSCSI going straight into D state. We have had to work on a couple of other things, so we don't know if this is just a coincidence or not. We will reboot back into the old kernel and back a few times and do some more testing, but so far it has given us a little bit of hope that we may be narrowing down on the root cause. We will report back once we have some more info. Thank you, Robert LeBlanc Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Tue, Oct 18, 2016 at 1:05 AM, Nicholas A. Bellinger wrote: > Hello Robert, Zhu & Co, > > Thanks for your detailed bug report. Comments inline below. > > On Mon, 2016-10-17 at 22:42 -0600, Robert LeBlanc wrote: >> Sorry I forget that Android has an aversion to plain text emails. >> >> If we can provide any information to help, let us know. We are willing >> to patch in more debug statements or whatever you think might help. >> Today has been a difficult day. Thanks for looking into it, I tried >> looking at it, but it is way over my head. >> >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> >> >> On Mon, Oct 17, 2016 at 9:06 PM, Zhu Lingshan wrote: >> > Hi Robert, >> > >> > I think the reason why you can not logout the targets is that iscsi_np in D >> > status. I think the patches fixed something, but it seems to be more than >> > one code path can trigger these similar issues. as you can see, there are >> > several call stacks, I am still working on it. Actually in my environment I >> > see there is another call stack not listed in your mail >> > >> > Thanks, >> > BR >> > Zhu Lingshan >> > >> > >> > On 10/18/2016 03:11 AM, Robert LeBlanc wrote: >> >> >> >> Sorry hit send too soon. >> >> >> >> In addition, on the client we see: >> >> # ps -aux | grep D | grep kworker >> >> root 5583 0.0 0.0 0 0 ?D11:55 0:03 >> >> [kworker/11:0] >> >> root 7721 0.1 0.0 0 0 ?D12:00 0:04 >> >> [kworker/4:25] >> >> root 10877 0.0 0.0 0 0 ?D09:27 0:00 >> >> [kworker/22:1] >> >> root 11246 0.0 0.0 0 0 ?D10:28 0:00 >> >> [kworker/30:2] >> >> root 14034 0.0 0.0 0 0 ?D12:20 0:02 >> >> [kworker/19:15] >> >> root 14048 0.0 0.0 0 0 ?D12:20 0:00 >> >> [kworker/16:0] >> >> root 15871 0.0 0.0 0 0 ?D12:25 0:00 >> >> [kworker/13:0] >> >> root 17442 0.0 0.0 0 0 ?D12:28 0:00 >> >> [kworker/9:1] >> >> root 17816 0.0 0.0 0 0 ?D12:30 0:00 >> >> [kworker/11:1] >> >> root 18744 0.0 0.0 0 0 ?D12:32 0:00 >> >> [kworker/10:2] >> >> root 19060 0.0 0.0 0 0 ?D12:32 0:00 >> >> [kworker/29:0] >> >> root 21748 0.0 0.0 0 0 ?D12:40 0:00 >> >> [kworker/21:0] >> >> root 21967 0.0 0.0 0 0 ?D12:40 0:00 >> >> [kworker/22:0] >> >> root 21978 0.0 0.0 0 0 ?D12:40 0:00 >> >> [kworker/22:2] >> >> root 22024 0.0 0.0 0 0 ?D12:40 0:00 >> >> [kworker/22:4] >> >> root 22035 0.0 0.0 0 0 ?D12:40 0:00 >> >> [kworker/22:5] >> >> root 22060 0.0 0.0 0 0 ?D12:40 0:00 >> >> [kworker/16:1] >> >> root 22282 0.0 0.0 0 0 ?D12:41 0:00 >> >> [kworker/26:0] >> >> root 22362 0.0 0.0 0 0 ?D12:42 0:00 >> >> [kworker/18:9] >> >> root 22426 0.0 0.0 0 0 ?D12:42 0:00 >> >> [kworker/16:3] >> >> root 23298 0.0 0.0 0 0 ?D12:43 0:00 >> >> [kworker/12:1] >> >> root 23302 0.0 0.0 0 0 ?D12:43 0:00 >> >> [kworker/12:5] >> >> root 24264 0.0 0.0 0 0 ?D12:46 0:00 >> >> [kworker/30:1] >> >> root 24271 0.0 0.0 0 0 ?D12:46 0:00 >> >> [kworker/14:8] >> >> root 24441 0.0 0.0 0 0 ?D12:47 0:00 >> >> [kworker/9:7] >> >> root 24443 0.0 0.0 0 0 ?D12:47 0:00 >> >> [kworker/9:9] >> >> root 25005 0.0 0.0 0 0 ?D12:48 0:00 >> >> [kworker/30:3] >> >> root 25158 0.0 0.0 0 0 ?D12:49 0:00 >> >> [kworker/9:12] >> >> root 26382 0.0 0.0 0 0 ?D12:52 0:00 >> >> [kworker/13:2] >> >> root 26453 0.0 0.0 0 0 ?D12:52 0:00 >> >> [kworker/21:2] >> >> root 26724 0.0 0.0 0 0 ?D12:53 0:00 >> >> [kworker/19:1] >> >> root 28400 0.0 0.0 0 0 ?D05:20 0:00 >> >> [kworker/25:1] >> >> root 29552 0.0 0.0 0 0 ?D11:40 0:00 >> >> [kworker/17:1] >> >> root 29811
Re: iscsi_trx going into D state
On Tue, 2016-10-18 at 00:05 -0700, Nicholas A. Bellinger wrote: > Hello Robert, Zhu & Co, > > Thanks for your detailed bug report. Comments inline below. > > On Mon, 2016-10-17 at 22:42 -0600, Robert LeBlanc wrote: > > Sorry I forget that Android has an aversion to plain text emails. > > > > If we can provide any information to help, let us know. We are willing > > to patch in more debug statements or whatever you think might help. > > Today has been a difficult day. Thanks for looking into it, I tried > > looking at it, but it is way over my head. > > > > > > Robert LeBlanc > > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > > > > On Mon, Oct 17, 2016 at 9:06 PM, Zhu Lingshan wrote: > > > Hi Robert, > > > > > > I think the reason why you can not logout the targets is that iscsi_np in > > > D > > > status. I think the patches fixed something, but it seems to be more than > > > one code path can trigger these similar issues. as you can see, there are > > > several call stacks, I am still working on it. Actually in my environment > > > I > > > see there is another call stack not listed in your mail > > > > > > Thanks, > > > BR > > > Zhu Lingshan > > > > > > > > > On 10/18/2016 03:11 AM, Robert LeBlanc wrote: > > >> > > >> Sorry hit send too soon. > > >> > > >> In addition, on the client we see: > > >> # ps -aux | grep D | grep kworker > > >> root 5583 0.0 0.0 0 0 ?D11:55 0:03 > > >> [kworker/11:0] > > >> root 7721 0.1 0.0 0 0 ?D12:00 0:04 > > >> [kworker/4:25] > > >> root 10877 0.0 0.0 0 0 ?D09:27 0:00 > > >> [kworker/22:1] > > >> root 11246 0.0 0.0 0 0 ?D10:28 0:00 > > >> [kworker/30:2] > > >> root 14034 0.0 0.0 0 0 ?D12:20 0:02 > > >> [kworker/19:15] > > >> root 14048 0.0 0.0 0 0 ?D12:20 0:00 > > >> [kworker/16:0] > > >> root 15871 0.0 0.0 0 0 ?D12:25 0:00 > > >> [kworker/13:0] > > >> root 17442 0.0 0.0 0 0 ?D12:28 0:00 > > >> [kworker/9:1] > > >> root 17816 0.0 0.0 0 0 ?D12:30 0:00 > > >> [kworker/11:1] > > >> root 18744 0.0 0.0 0 0 ?D12:32 0:00 > > >> [kworker/10:2] > > >> root 19060 0.0 0.0 0 0 ?D12:32 0:00 > > >> [kworker/29:0] > > >> root 21748 0.0 0.0 0 0 ?D12:40 0:00 > > >> [kworker/21:0] > > >> root 21967 0.0 0.0 0 0 ?D12:40 0:00 > > >> [kworker/22:0] > > >> root 21978 0.0 0.0 0 0 ?D12:40 0:00 > > >> [kworker/22:2] > > >> root 22024 0.0 0.0 0 0 ?D12:40 0:00 > > >> [kworker/22:4] > > >> root 22035 0.0 0.0 0 0 ?D12:40 0:00 > > >> [kworker/22:5] > > >> root 22060 0.0 0.0 0 0 ?D12:40 0:00 > > >> [kworker/16:1] > > >> root 22282 0.0 0.0 0 0 ?D12:41 0:00 > > >> [kworker/26:0] > > >> root 22362 0.0 0.0 0 0 ?D12:42 0:00 > > >> [kworker/18:9] > > >> root 22426 0.0 0.0 0 0 ?D12:42 0:00 > > >> [kworker/16:3] > > >> root 23298 0.0 0.0 0 0 ?D12:43 0:00 > > >> [kworker/12:1] > > >> root 23302 0.0 0.0 0 0 ?D12:43 0:00 > > >> [kworker/12:5] > > >> root 24264 0.0 0.0 0 0 ?D12:46 0:00 > > >> [kworker/30:1] > > >> root 24271 0.0 0.0 0 0 ?D12:46 0:00 > > >> [kworker/14:8] > > >> root 24441 0.0 0.0 0 0 ?D12:47 0:00 > > >> [kworker/9:7] > > >> root 24443 0.0 0.0 0 0 ?D12:47 0:00 > > >> [kworker/9:9] > > >> root 25005 0.0 0.0 0 0 ?D12:48 0:00 > > >> [kworker/30:3] > > >> root 25158 0.0 0.0 0 0 ?D12:49 0:00 > > >> [kworker/9:12] > > >> root 26382 0.0 0.0 0 0 ?D12:52 0:00 > > >> [kworker/13:2] > > >> root 26453 0.0 0.0 0 0 ?D12:52 0:00 > > >> [kworker/21:2] > > >> root 26724 0.0 0.0 0 0 ?D12:53 0:00 > > >> [kworker/19:1] > > >> root 28400 0.0 0.0 0 0 ?D05:20 0:00 > > >> [kworker/25:1] > > >> root 29552 0.0 0.0 0 0 ?D11:40 0:00 > > >> [kworker/17:1] > > >> root 29811 0.0 0.0 0 0 ?D11:40 0:00 > > >> [kworker/7:10] > > >> root 31903 0.0 0.0 0 0 ?D11:43 0:00 > > >> [kworker/26:1] > > >> > > >> And all of the processes have this stack: > > >> [] iser_release_work+0x25/0x60 [ib_iser] > > >> [] process_one_work+0x14f/0x400 > > >> [] worker_thread+0x114/0x470 > > >> [] kthread+0xd8/0xf0 > > >> [] ret_from_fork+0x3f/0x70 > > >> [] 0x > > >> > > >> We are not able
Re: iscsi_trx going into D state
Hello Robert, Zhu & Co, Thanks for your detailed bug report. Comments inline below. On Mon, 2016-10-17 at 22:42 -0600, Robert LeBlanc wrote: > Sorry I forget that Android has an aversion to plain text emails. > > If we can provide any information to help, let us know. We are willing > to patch in more debug statements or whatever you think might help. > Today has been a difficult day. Thanks for looking into it, I tried > looking at it, but it is way over my head. > > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Mon, Oct 17, 2016 at 9:06 PM, Zhu Lingshan wrote: > > Hi Robert, > > > > I think the reason why you can not logout the targets is that iscsi_np in D > > status. I think the patches fixed something, but it seems to be more than > > one code path can trigger these similar issues. as you can see, there are > > several call stacks, I am still working on it. Actually in my environment I > > see there is another call stack not listed in your mail > > > > Thanks, > > BR > > Zhu Lingshan > > > > > > On 10/18/2016 03:11 AM, Robert LeBlanc wrote: > >> > >> Sorry hit send too soon. > >> > >> In addition, on the client we see: > >> # ps -aux | grep D | grep kworker > >> root 5583 0.0 0.0 0 0 ?D11:55 0:03 > >> [kworker/11:0] > >> root 7721 0.1 0.0 0 0 ?D12:00 0:04 > >> [kworker/4:25] > >> root 10877 0.0 0.0 0 0 ?D09:27 0:00 > >> [kworker/22:1] > >> root 11246 0.0 0.0 0 0 ?D10:28 0:00 > >> [kworker/30:2] > >> root 14034 0.0 0.0 0 0 ?D12:20 0:02 > >> [kworker/19:15] > >> root 14048 0.0 0.0 0 0 ?D12:20 0:00 > >> [kworker/16:0] > >> root 15871 0.0 0.0 0 0 ?D12:25 0:00 > >> [kworker/13:0] > >> root 17442 0.0 0.0 0 0 ?D12:28 0:00 > >> [kworker/9:1] > >> root 17816 0.0 0.0 0 0 ?D12:30 0:00 > >> [kworker/11:1] > >> root 18744 0.0 0.0 0 0 ?D12:32 0:00 > >> [kworker/10:2] > >> root 19060 0.0 0.0 0 0 ?D12:32 0:00 > >> [kworker/29:0] > >> root 21748 0.0 0.0 0 0 ?D12:40 0:00 > >> [kworker/21:0] > >> root 21967 0.0 0.0 0 0 ?D12:40 0:00 > >> [kworker/22:0] > >> root 21978 0.0 0.0 0 0 ?D12:40 0:00 > >> [kworker/22:2] > >> root 22024 0.0 0.0 0 0 ?D12:40 0:00 > >> [kworker/22:4] > >> root 22035 0.0 0.0 0 0 ?D12:40 0:00 > >> [kworker/22:5] > >> root 22060 0.0 0.0 0 0 ?D12:40 0:00 > >> [kworker/16:1] > >> root 22282 0.0 0.0 0 0 ?D12:41 0:00 > >> [kworker/26:0] > >> root 22362 0.0 0.0 0 0 ?D12:42 0:00 > >> [kworker/18:9] > >> root 22426 0.0 0.0 0 0 ?D12:42 0:00 > >> [kworker/16:3] > >> root 23298 0.0 0.0 0 0 ?D12:43 0:00 > >> [kworker/12:1] > >> root 23302 0.0 0.0 0 0 ?D12:43 0:00 > >> [kworker/12:5] > >> root 24264 0.0 0.0 0 0 ?D12:46 0:00 > >> [kworker/30:1] > >> root 24271 0.0 0.0 0 0 ?D12:46 0:00 > >> [kworker/14:8] > >> root 24441 0.0 0.0 0 0 ?D12:47 0:00 > >> [kworker/9:7] > >> root 24443 0.0 0.0 0 0 ?D12:47 0:00 > >> [kworker/9:9] > >> root 25005 0.0 0.0 0 0 ?D12:48 0:00 > >> [kworker/30:3] > >> root 25158 0.0 0.0 0 0 ?D12:49 0:00 > >> [kworker/9:12] > >> root 26382 0.0 0.0 0 0 ?D12:52 0:00 > >> [kworker/13:2] > >> root 26453 0.0 0.0 0 0 ?D12:52 0:00 > >> [kworker/21:2] > >> root 26724 0.0 0.0 0 0 ?D12:53 0:00 > >> [kworker/19:1] > >> root 28400 0.0 0.0 0 0 ?D05:20 0:00 > >> [kworker/25:1] > >> root 29552 0.0 0.0 0 0 ?D11:40 0:00 > >> [kworker/17:1] > >> root 29811 0.0 0.0 0 0 ?D11:40 0:00 > >> [kworker/7:10] > >> root 31903 0.0 0.0 0 0 ?D11:43 0:00 > >> [kworker/26:1] > >> > >> And all of the processes have this stack: > >> [] iser_release_work+0x25/0x60 [ib_iser] > >> [] process_one_work+0x14f/0x400 > >> [] worker_thread+0x114/0x470 > >> [] kthread+0xd8/0xf0 > >> [] ret_from_fork+0x3f/0x70 > >> [] 0x > >> > >> We are not able to log out of the sessions in all cases. And have to > >> restart the box. > >> > >> iscsiadm -m session will show messages like: > >> iscsiadm: could not read session targetname: 5 > >> iscsiadm: could not find session info for session100 > >> iscsiadm: could not read session targetname: 5 > >> iscsiadm: could
Re: iscsi_trx going into D state
Sorry I forget that Android has an aversion to plain text emails. If we can provide any information to help, let us know. We are willing to patch in more debug statements or whatever you think might help. Today has been a difficult day. Thanks for looking into it, I tried looking at it, but it is way over my head. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Oct 17, 2016 at 9:06 PM, Zhu Lingshan wrote: > Hi Robert, > > I think the reason why you can not logout the targets is that iscsi_np in D > status. I think the patches fixed something, but it seems to be more than > one code path can trigger these similar issues. as you can see, there are > several call stacks, I am still working on it. Actually in my environment I > see there is another call stack not listed in your mail > > Thanks, > BR > Zhu Lingshan > > > On 10/18/2016 03:11 AM, Robert LeBlanc wrote: >> >> Sorry hit send too soon. >> >> In addition, on the client we see: >> # ps -aux | grep D | grep kworker >> root 5583 0.0 0.0 0 0 ?D11:55 0:03 >> [kworker/11:0] >> root 7721 0.1 0.0 0 0 ?D12:00 0:04 >> [kworker/4:25] >> root 10877 0.0 0.0 0 0 ?D09:27 0:00 >> [kworker/22:1] >> root 11246 0.0 0.0 0 0 ?D10:28 0:00 >> [kworker/30:2] >> root 14034 0.0 0.0 0 0 ?D12:20 0:02 >> [kworker/19:15] >> root 14048 0.0 0.0 0 0 ?D12:20 0:00 >> [kworker/16:0] >> root 15871 0.0 0.0 0 0 ?D12:25 0:00 >> [kworker/13:0] >> root 17442 0.0 0.0 0 0 ?D12:28 0:00 >> [kworker/9:1] >> root 17816 0.0 0.0 0 0 ?D12:30 0:00 >> [kworker/11:1] >> root 18744 0.0 0.0 0 0 ?D12:32 0:00 >> [kworker/10:2] >> root 19060 0.0 0.0 0 0 ?D12:32 0:00 >> [kworker/29:0] >> root 21748 0.0 0.0 0 0 ?D12:40 0:00 >> [kworker/21:0] >> root 21967 0.0 0.0 0 0 ?D12:40 0:00 >> [kworker/22:0] >> root 21978 0.0 0.0 0 0 ?D12:40 0:00 >> [kworker/22:2] >> root 22024 0.0 0.0 0 0 ?D12:40 0:00 >> [kworker/22:4] >> root 22035 0.0 0.0 0 0 ?D12:40 0:00 >> [kworker/22:5] >> root 22060 0.0 0.0 0 0 ?D12:40 0:00 >> [kworker/16:1] >> root 22282 0.0 0.0 0 0 ?D12:41 0:00 >> [kworker/26:0] >> root 22362 0.0 0.0 0 0 ?D12:42 0:00 >> [kworker/18:9] >> root 22426 0.0 0.0 0 0 ?D12:42 0:00 >> [kworker/16:3] >> root 23298 0.0 0.0 0 0 ?D12:43 0:00 >> [kworker/12:1] >> root 23302 0.0 0.0 0 0 ?D12:43 0:00 >> [kworker/12:5] >> root 24264 0.0 0.0 0 0 ?D12:46 0:00 >> [kworker/30:1] >> root 24271 0.0 0.0 0 0 ?D12:46 0:00 >> [kworker/14:8] >> root 24441 0.0 0.0 0 0 ?D12:47 0:00 >> [kworker/9:7] >> root 24443 0.0 0.0 0 0 ?D12:47 0:00 >> [kworker/9:9] >> root 25005 0.0 0.0 0 0 ?D12:48 0:00 >> [kworker/30:3] >> root 25158 0.0 0.0 0 0 ?D12:49 0:00 >> [kworker/9:12] >> root 26382 0.0 0.0 0 0 ?D12:52 0:00 >> [kworker/13:2] >> root 26453 0.0 0.0 0 0 ?D12:52 0:00 >> [kworker/21:2] >> root 26724 0.0 0.0 0 0 ?D12:53 0:00 >> [kworker/19:1] >> root 28400 0.0 0.0 0 0 ?D05:20 0:00 >> [kworker/25:1] >> root 29552 0.0 0.0 0 0 ?D11:40 0:00 >> [kworker/17:1] >> root 29811 0.0 0.0 0 0 ?D11:40 0:00 >> [kworker/7:10] >> root 31903 0.0 0.0 0 0 ?D11:43 0:00 >> [kworker/26:1] >> >> And all of the processes have this stack: >> [] iser_release_work+0x25/0x60 [ib_iser] >> [] process_one_work+0x14f/0x400 >> [] worker_thread+0x114/0x470 >> [] kthread+0xd8/0xf0 >> [] ret_from_fork+0x3f/0x70 >> [] 0x >> >> We are not able to log out of the sessions in all cases. And have to >> restart the box. >> >> iscsiadm -m session will show messages like: >> iscsiadm: could not read session targetname: 5 >> iscsiadm: could not find session info for session100 >> iscsiadm: could not read session targetname: 5 >> iscsiadm: could not find session info for session101 >> iscsiadm: could not read session targetname: 5 >> iscsiadm: could not find session info for session103 >> ... >> >> I can't find any way to force iscsiadm to clean up these sessions >> possibly due to tasks in D state. >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> >> >> On Mo
Re: iscsi_trx going into D state
Hi Robert, I think the reason why you can not logout the targets is that iscsi_np in D status. I think the patches fixed something, but it seems to be more than one code path can trigger these similar issues. as you can see, there are several call stacks, I am still working on it. Actually in my environment I see there is another call stack not listed in your mail Thanks, BR Zhu Lingshan On 10/18/2016 03:11 AM, Robert LeBlanc wrote: Sorry hit send too soon. In addition, on the client we see: # ps -aux | grep D | grep kworker root 5583 0.0 0.0 0 0 ?D11:55 0:03 [kworker/11:0] root 7721 0.1 0.0 0 0 ?D12:00 0:04 [kworker/4:25] root 10877 0.0 0.0 0 0 ?D09:27 0:00 [kworker/22:1] root 11246 0.0 0.0 0 0 ?D10:28 0:00 [kworker/30:2] root 14034 0.0 0.0 0 0 ?D12:20 0:02 [kworker/19:15] root 14048 0.0 0.0 0 0 ?D12:20 0:00 [kworker/16:0] root 15871 0.0 0.0 0 0 ?D12:25 0:00 [kworker/13:0] root 17442 0.0 0.0 0 0 ?D12:28 0:00 [kworker/9:1] root 17816 0.0 0.0 0 0 ?D12:30 0:00 [kworker/11:1] root 18744 0.0 0.0 0 0 ?D12:32 0:00 [kworker/10:2] root 19060 0.0 0.0 0 0 ?D12:32 0:00 [kworker/29:0] root 21748 0.0 0.0 0 0 ?D12:40 0:00 [kworker/21:0] root 21967 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:0] root 21978 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:2] root 22024 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:4] root 22035 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:5] root 22060 0.0 0.0 0 0 ?D12:40 0:00 [kworker/16:1] root 22282 0.0 0.0 0 0 ?D12:41 0:00 [kworker/26:0] root 22362 0.0 0.0 0 0 ?D12:42 0:00 [kworker/18:9] root 22426 0.0 0.0 0 0 ?D12:42 0:00 [kworker/16:3] root 23298 0.0 0.0 0 0 ?D12:43 0:00 [kworker/12:1] root 23302 0.0 0.0 0 0 ?D12:43 0:00 [kworker/12:5] root 24264 0.0 0.0 0 0 ?D12:46 0:00 [kworker/30:1] root 24271 0.0 0.0 0 0 ?D12:46 0:00 [kworker/14:8] root 24441 0.0 0.0 0 0 ?D12:47 0:00 [kworker/9:7] root 24443 0.0 0.0 0 0 ?D12:47 0:00 [kworker/9:9] root 25005 0.0 0.0 0 0 ?D12:48 0:00 [kworker/30:3] root 25158 0.0 0.0 0 0 ?D12:49 0:00 [kworker/9:12] root 26382 0.0 0.0 0 0 ?D12:52 0:00 [kworker/13:2] root 26453 0.0 0.0 0 0 ?D12:52 0:00 [kworker/21:2] root 26724 0.0 0.0 0 0 ?D12:53 0:00 [kworker/19:1] root 28400 0.0 0.0 0 0 ?D05:20 0:00 [kworker/25:1] root 29552 0.0 0.0 0 0 ?D11:40 0:00 [kworker/17:1] root 29811 0.0 0.0 0 0 ?D11:40 0:00 [kworker/7:10] root 31903 0.0 0.0 0 0 ?D11:43 0:00 [kworker/26:1] And all of the processes have this stack: [] iser_release_work+0x25/0x60 [ib_iser] [] process_one_work+0x14f/0x400 [] worker_thread+0x114/0x470 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x We are not able to log out of the sessions in all cases. And have to restart the box. iscsiadm -m session will show messages like: iscsiadm: could not read session targetname: 5 iscsiadm: could not find session info for session100 iscsiadm: could not read session targetname: 5 iscsiadm: could not find session info for session101 iscsiadm: could not read session targetname: 5 iscsiadm: could not find session info for session103 ... I can't find any way to force iscsiadm to clean up these sessions possibly due to tasks in D state. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Oct 17, 2016 at 10:32 AM, Robert LeBlanc wrote: Some more info as we hit this this morning. We have volumes mirrored between two targets and we had one target on the kernel with the three patches mentioned in this thread [0][1][2] and the other was on a kernel without the patches. We decided that after a week and a half we wanted to get both targets on the same kernel so we rebooted the non-patched target. Within an hour we saw iSCSI in D state with the same stack trace so it seems that we are not hitting any of the WARN_ON lines. We are getting both iscsi_trx and iscsi_np both in D state, this time we have two iscsi_trx processes in D state. I don't know if stale sessions on the clients could be contributing to this issue (the target trying to close non-existent sessions??). Thi
Re: iscsi_trx going into D state
Sorry hit send too soon. In addition, on the client we see: # ps -aux | grep D | grep kworker root 5583 0.0 0.0 0 0 ?D11:55 0:03 [kworker/11:0] root 7721 0.1 0.0 0 0 ?D12:00 0:04 [kworker/4:25] root 10877 0.0 0.0 0 0 ?D09:27 0:00 [kworker/22:1] root 11246 0.0 0.0 0 0 ?D10:28 0:00 [kworker/30:2] root 14034 0.0 0.0 0 0 ?D12:20 0:02 [kworker/19:15] root 14048 0.0 0.0 0 0 ?D12:20 0:00 [kworker/16:0] root 15871 0.0 0.0 0 0 ?D12:25 0:00 [kworker/13:0] root 17442 0.0 0.0 0 0 ?D12:28 0:00 [kworker/9:1] root 17816 0.0 0.0 0 0 ?D12:30 0:00 [kworker/11:1] root 18744 0.0 0.0 0 0 ?D12:32 0:00 [kworker/10:2] root 19060 0.0 0.0 0 0 ?D12:32 0:00 [kworker/29:0] root 21748 0.0 0.0 0 0 ?D12:40 0:00 [kworker/21:0] root 21967 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:0] root 21978 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:2] root 22024 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:4] root 22035 0.0 0.0 0 0 ?D12:40 0:00 [kworker/22:5] root 22060 0.0 0.0 0 0 ?D12:40 0:00 [kworker/16:1] root 22282 0.0 0.0 0 0 ?D12:41 0:00 [kworker/26:0] root 22362 0.0 0.0 0 0 ?D12:42 0:00 [kworker/18:9] root 22426 0.0 0.0 0 0 ?D12:42 0:00 [kworker/16:3] root 23298 0.0 0.0 0 0 ?D12:43 0:00 [kworker/12:1] root 23302 0.0 0.0 0 0 ?D12:43 0:00 [kworker/12:5] root 24264 0.0 0.0 0 0 ?D12:46 0:00 [kworker/30:1] root 24271 0.0 0.0 0 0 ?D12:46 0:00 [kworker/14:8] root 24441 0.0 0.0 0 0 ?D12:47 0:00 [kworker/9:7] root 24443 0.0 0.0 0 0 ?D12:47 0:00 [kworker/9:9] root 25005 0.0 0.0 0 0 ?D12:48 0:00 [kworker/30:3] root 25158 0.0 0.0 0 0 ?D12:49 0:00 [kworker/9:12] root 26382 0.0 0.0 0 0 ?D12:52 0:00 [kworker/13:2] root 26453 0.0 0.0 0 0 ?D12:52 0:00 [kworker/21:2] root 26724 0.0 0.0 0 0 ?D12:53 0:00 [kworker/19:1] root 28400 0.0 0.0 0 0 ?D05:20 0:00 [kworker/25:1] root 29552 0.0 0.0 0 0 ?D11:40 0:00 [kworker/17:1] root 29811 0.0 0.0 0 0 ?D11:40 0:00 [kworker/7:10] root 31903 0.0 0.0 0 0 ?D11:43 0:00 [kworker/26:1] And all of the processes have this stack: [] iser_release_work+0x25/0x60 [ib_iser] [] process_one_work+0x14f/0x400 [] worker_thread+0x114/0x470 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x We are not able to log out of the sessions in all cases. And have to restart the box. iscsiadm -m session will show messages like: iscsiadm: could not read session targetname: 5 iscsiadm: could not find session info for session100 iscsiadm: could not read session targetname: 5 iscsiadm: could not find session info for session101 iscsiadm: could not read session targetname: 5 iscsiadm: could not find session info for session103 ... I can't find any way to force iscsiadm to clean up these sessions possibly due to tasks in D state. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Oct 17, 2016 at 10:32 AM, Robert LeBlanc wrote: > Some more info as we hit this this morning. We have volumes mirrored > between two targets and we had one target on the kernel with the three > patches mentioned in this thread [0][1][2] and the other was on a > kernel without the patches. We decided that after a week and a half we > wanted to get both targets on the same kernel so we rebooted the > non-patched target. Within an hour we saw iSCSI in D state with the > same stack trace so it seems that we are not hitting any of the > WARN_ON lines. We are getting both iscsi_trx and iscsi_np both in D > state, this time we have two iscsi_trx processes in D state. I don't > know if stale sessions on the clients could be contributing to this > issue (the target trying to close non-existent sessions??). This is on > 4.4.23. Any more debug info we can throw at this problem to help? > > Thank you, > Robert LeBlanc > > # ps aux | grep D | grep iscsi > root 16525 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_np] > root 16614 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_trx] > root 16674 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_trx] > > # for i in 16525 16614 16674; do echo $i; cat /p
Re: iscsi_trx going into D state
In addition, on the client we see: Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Mon, Oct 17, 2016 at 10:32 AM, Robert LeBlanc wrote: > Some more info as we hit this this morning. We have volumes mirrored > between two targets and we had one target on the kernel with the three > patches mentioned in this thread [0][1][2] and the other was on a > kernel without the patches. We decided that after a week and a half we > wanted to get both targets on the same kernel so we rebooted the > non-patched target. Within an hour we saw iSCSI in D state with the > same stack trace so it seems that we are not hitting any of the > WARN_ON lines. We are getting both iscsi_trx and iscsi_np both in D > state, this time we have two iscsi_trx processes in D state. I don't > know if stale sessions on the clients could be contributing to this > issue (the target trying to close non-existent sessions??). This is on > 4.4.23. Any more debug info we can throw at this problem to help? > > Thank you, > Robert LeBlanc > > # ps aux | grep D | grep iscsi > root 16525 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_np] > root 16614 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_trx] > root 16674 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_trx] > > # for i in 16525 16614 16674; do echo $i; cat /proc/$i/stack; done > 16525 > [] iscsit_stop_session+0x19f/0x1d0 > [] iscsi_check_for_session_reinstatement+0x1e6/0x270 > [] iscsi_target_check_for_existing_instances+0x30/0x40 > [] iscsi_target_do_login+0x140/0x640 > [] iscsi_target_start_negotiation+0x1c/0xb0 > [] iscsi_target_login_thread+0xa9b/0xfc0 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > 16614 > [] target_wait_for_sess_cmds+0x49/0x1a0 > [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] > [] iscsit_close_connection+0x162/0x870 > [] iscsit_take_action_for_connection_exit+0x7f/0x100 > [] iscsi_target_rx_thread+0x5a0/0xe80 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > 16674 > [] target_wait_for_sess_cmds+0x49/0x1a0 > [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] > [] iscsit_close_connection+0x162/0x870 > [] iscsit_take_action_for_connection_exit+0x7f/0x100 > [] iscsi_target_rx_thread+0x5a0/0xe80 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > > > [0] https://www.spinics.net/lists/target-devel/msg13463.html > [1] http://marc.info/?l=linux-scsi&m=147282568910535&w=2 > [2] http://www.spinics.net/lists/linux-scsi/msg100221.html > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > > > On Fri, Oct 7, 2016 at 8:59 PM, Zhu Lingshan wrote: >> Hi Robert, >> >> I also see this issue, but this is not the only code path can trigger this >> problem, I think you may also see iscsi_np in D status. I fixed one code >> path whitch still not merged to mainline. I will forward you my patch later. >> Note: my patch only fixed one code path, you may see other call statck with >> D status. >> >> Thanks, >> BR >> Zhu Lingshan >> >> >> 在 2016/10/1 1:14, Robert LeBlanc 写道: >>> >>> We are having a reoccurring problem where iscsi_trx is going into D >>> state. It seems like it is waiting for a session tear down to happen >>> or something, but keeps waiting. We have to reboot these targets on >>> occasion. This is running the 4.4.12 kernel and we have seen it on >>> several previous 4.4.x and 4.2.x kernels. There is no message in dmesg >>> or /var/log/messages. This seems to happen with increased frequency >>> when we have a disruption in our Infiniband fabric, but can happen >>> without any changes to the fabric (other than hosts rebooting). >>> >>> # ps aux | grep iscsi | grep D >>> root 4185 0.0 0.0 0 0 ?DSep29 0:00 >>> [iscsi_trx] >>> root 18505 0.0 0.0 0 0 ?DSep29 0:00 >>> [iscsi_np] >>> >>> # cat /proc/4185/stack >>> [] target_wait_for_sess_cmds+0x49/0x1a0 >>> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] >>> [] iscsit_close_connection+0x162/0x840 >>> [] iscsit_take_action_for_connection_exit+0x7f/0x100 >>> [] iscsi_target_rx_thread+0x5a0/0xe80 >>> [] kthread+0xd8/0xf0 >>> [] ret_from_fork+0x3f/0x70 >>> [] 0x >>> >>> # cat /proc/18505/stack >>> [] iscsit_stop_session+0x1b1/0x1c0 >>> [] iscsi_check_for_session_reinstatement+0x1e6/0x270 >>> [] iscsi_target_check_for_existing_instances+0x30/0x40 >>> [] iscsi_target_do_login+0x140/0x640 >>> [] iscsi_target_start_negotiation+0x1c/0xb0 >>> [] iscsi_target_login_thread+0xa9b/0xfc0 >>> [] kthread+0xd8/0xf0 >>> [] ret_from_fork+0x3f/0x70 >>> [] 0x >>> >>> What can we do to help get this resolved? >>> >>> Thanks, >>> >>> >>> Robert LeBlanc >>> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >>> -- >>> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in >>> the body of a message to majord...@vger
Re: iscsi_trx going into D state
Some more info as we hit this this morning. We have volumes mirrored between two targets and we had one target on the kernel with the three patches mentioned in this thread [0][1][2] and the other was on a kernel without the patches. We decided that after a week and a half we wanted to get both targets on the same kernel so we rebooted the non-patched target. Within an hour we saw iSCSI in D state with the same stack trace so it seems that we are not hitting any of the WARN_ON lines. We are getting both iscsi_trx and iscsi_np both in D state, this time we have two iscsi_trx processes in D state. I don't know if stale sessions on the clients could be contributing to this issue (the target trying to close non-existent sessions??). This is on 4.4.23. Any more debug info we can throw at this problem to help? Thank you, Robert LeBlanc # ps aux | grep D | grep iscsi root 16525 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_np] root 16614 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_trx] root 16674 0.0 0.0 0 0 ?D08:50 0:00 [iscsi_trx] # for i in 16525 16614 16674; do echo $i; cat /proc/$i/stack; done 16525 [] iscsit_stop_session+0x19f/0x1d0 [] iscsi_check_for_session_reinstatement+0x1e6/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x140/0x640 [] iscsi_target_start_negotiation+0x1c/0xb0 [] iscsi_target_login_thread+0xa9b/0xfc0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x 16614 [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x870 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_rx_thread+0x5a0/0xe80 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x 16674 [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x870 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_rx_thread+0x5a0/0xe80 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x [0] https://www.spinics.net/lists/target-devel/msg13463.html [1] http://marc.info/?l=linux-scsi&m=147282568910535&w=2 [2] http://www.spinics.net/lists/linux-scsi/msg100221.html Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Oct 7, 2016 at 8:59 PM, Zhu Lingshan wrote: > Hi Robert, > > I also see this issue, but this is not the only code path can trigger this > problem, I think you may also see iscsi_np in D status. I fixed one code > path whitch still not merged to mainline. I will forward you my patch later. > Note: my patch only fixed one code path, you may see other call statck with > D status. > > Thanks, > BR > Zhu Lingshan > > > 在 2016/10/1 1:14, Robert LeBlanc 写道: >> >> We are having a reoccurring problem where iscsi_trx is going into D >> state. It seems like it is waiting for a session tear down to happen >> or something, but keeps waiting. We have to reboot these targets on >> occasion. This is running the 4.4.12 kernel and we have seen it on >> several previous 4.4.x and 4.2.x kernels. There is no message in dmesg >> or /var/log/messages. This seems to happen with increased frequency >> when we have a disruption in our Infiniband fabric, but can happen >> without any changes to the fabric (other than hosts rebooting). >> >> # ps aux | grep iscsi | grep D >> root 4185 0.0 0.0 0 0 ?DSep29 0:00 >> [iscsi_trx] >> root 18505 0.0 0.0 0 0 ?DSep29 0:00 >> [iscsi_np] >> >> # cat /proc/4185/stack >> [] target_wait_for_sess_cmds+0x49/0x1a0 >> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] >> [] iscsit_close_connection+0x162/0x840 >> [] iscsit_take_action_for_connection_exit+0x7f/0x100 >> [] iscsi_target_rx_thread+0x5a0/0xe80 >> [] kthread+0xd8/0xf0 >> [] ret_from_fork+0x3f/0x70 >> [] 0x >> >> # cat /proc/18505/stack >> [] iscsit_stop_session+0x1b1/0x1c0 >> [] iscsi_check_for_session_reinstatement+0x1e6/0x270 >> [] iscsi_target_check_for_existing_instances+0x30/0x40 >> [] iscsi_target_do_login+0x140/0x640 >> [] iscsi_target_start_negotiation+0x1c/0xb0 >> [] iscsi_target_login_thread+0xa9b/0xfc0 >> [] kthread+0xd8/0xf0 >> [] ret_from_fork+0x3f/0x70 >> [] 0x >> >> What can we do to help get this resolved? >> >> Thanks, >> >> >> Robert LeBlanc >> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 >> -- >> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in >> the body of a message to majord...@vger.kernel.org >> More majordomo info at http://vger.kernel.org/majordomo-info.html >> > -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Hi Robert, I also see this issue, but this is not the only code path can trigger this problem, I think you may also see iscsi_np in D status. I fixed one code path whitch still not merged to mainline. I will forward you my patch later. Note: my patch only fixed one code path, you may see other call statck with D status. Thanks, BR Zhu Lingshan 在 2016/10/1 1:14, Robert LeBlanc 写道: We are having a reoccurring problem where iscsi_trx is going into D state. It seems like it is waiting for a session tear down to happen or something, but keeps waiting. We have to reboot these targets on occasion. This is running the 4.4.12 kernel and we have seen it on several previous 4.4.x and 4.2.x kernels. There is no message in dmesg or /var/log/messages. This seems to happen with increased frequency when we have a disruption in our Infiniband fabric, but can happen without any changes to the fabric (other than hosts rebooting). # ps aux | grep iscsi | grep D root 4185 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_trx] root 18505 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_np] # cat /proc/4185/stack [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x840 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_rx_thread+0x5a0/0xe80 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x # cat /proc/18505/stack [] iscsit_stop_session+0x1b1/0x1c0 [] iscsi_check_for_session_reinstatement+0x1e6/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x140/0x640 [] iscsi_target_start_negotiation+0x1c/0xb0 [] iscsi_target_login_thread+0xa9b/0xfc0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x What can we do to help get this resolved? Thanks, Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Thanks, we will apply that too. We'd like to get this stable. We'll report back on what we find with these patches. Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Wed, Oct 5, 2016 at 12:03 PM, Christoph Hellwig wrote: > Hi Robert, > > I actually got the name wrong, the patch wasn't from Lee, but from Zhu, > another SuSE engineer. This is the one: > > http://www.spinics.net/lists/target-devel/msg13463.html -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Hi Robert, I actually got the name wrong, the patch wasn't from Lee, but from Zhu, another SuSE engineer. This is the one: http://www.spinics.net/lists/target-devel/msg13463.html -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
We are not able to identify the patch that you mentioned from Lee, can you give us a commit or a link to the patch? Thanks, Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Tue, Oct 4, 2016 at 5:46 AM, Christoph Hellwig wrote: > On Tue, Oct 04, 2016 at 11:11:18AM +0200, Hannes Reinecke wrote: >> Hmm. Looking at the code it looks as we might miss some calls to >> 'complete'. Can you try with the attached patch? > > That only looks slightly better than the original. What this really > needs is a waitqueue and and waitevent on sess->ncon. Although > that will need a bit more refactoring around that code. There also > are a few more ovbious issues around it, e.g. iscsit_close_connection > needs to use atomic_dec_and_test on sess->nconn instead of having > separate atomic_dec and atomic_read calls, and a lot of the 0 or 1 > atomic_ts in this code should be replaced with atomic bitops. > > Btw, there also was a fix from Lee in this area that added a missing > wakeup, make sure your tree already has that. -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
Do you want me to try this patch or wait for some of the suggestions Christoph brought up to be Incorporated? Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Tue, Oct 4, 2016 at 5:46 AM, Christoph Hellwig wrote: > On Tue, Oct 04, 2016 at 11:11:18AM +0200, Hannes Reinecke wrote: >> Hmm. Looking at the code it looks as we might miss some calls to >> 'complete'. Can you try with the attached patch? > > That only looks slightly better than the original. What this really > needs is a waitqueue and and waitevent on sess->ncon. Although > that will need a bit more refactoring around that code. There also > are a few more ovbious issues around it, e.g. iscsit_close_connection > needs to use atomic_dec_and_test on sess->nconn instead of having > separate atomic_dec and atomic_read calls, and a lot of the 0 or 1 > atomic_ts in this code should be replaced with atomic bitops. > > Btw, there also was a fix from Lee in this area that added a missing > wakeup, make sure your tree already has that. -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
On Tue, Oct 04, 2016 at 11:11:18AM +0200, Hannes Reinecke wrote: > Hmm. Looking at the code it looks as we might miss some calls to > 'complete'. Can you try with the attached patch? That only looks slightly better than the original. What this really needs is a waitqueue and and waitevent on sess->ncon. Although that will need a bit more refactoring around that code. There also are a few more ovbious issues around it, e.g. iscsit_close_connection needs to use atomic_dec_and_test on sess->nconn instead of having separate atomic_dec and atomic_read calls, and a lot of the 0 or 1 atomic_ts in this code should be replaced with atomic bitops. Btw, there also was a fix from Lee in this area that added a missing wakeup, make sure your tree already has that. -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: iscsi_trx going into D state
On 10/04/2016 09:55 AM, Johannes Thumshirn wrote:
> On Fri, Sep 30, 2016 at 11:14:57AM -0600, Robert LeBlanc wrote:
>> We are having a reoccurring problem where iscsi_trx is going into D
>> state. It seems like it is waiting for a session tear down to happen
>> or something, but keeps waiting. We have to reboot these targets on
>> occasion. This is running the 4.4.12 kernel and we have seen it on
>> several previous 4.4.x and 4.2.x kernels. There is no message in dmesg
>> or /var/log/messages. This seems to happen with increased frequency
>> when we have a disruption in our Infiniband fabric, but can happen
>> without any changes to the fabric (other than hosts rebooting).
>>
>> # ps aux | grep iscsi | grep D
>> root 4185 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_trx]
>> root 18505 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_np]
>>
>> # cat /proc/4185/stack
>> [] target_wait_for_sess_cmds+0x49/0x1a0
>> [] isert_wait_conn+0x1ab/0x2f0 [ib_isert]
>> [] iscsit_close_connection+0x162/0x840
>> [] iscsit_take_action_for_connection_exit+0x7f/0x100
>> [] iscsi_target_rx_thread+0x5a0/0xe80
>> [] kthread+0xd8/0xf0
>> [] ret_from_fork+0x3f/0x70
>> [] 0x
>>
>> # cat /proc/18505/stack
>> [] iscsit_stop_session+0x1b1/0x1c0
>> [] iscsi_check_for_session_reinstatement+0x1e6/0x270
>> [] iscsi_target_check_for_existing_instances+0x30/0x40
>> [] iscsi_target_do_login+0x140/0x640
>> [] iscsi_target_start_negotiation+0x1c/0xb0
>> [] iscsi_target_login_thread+0xa9b/0xfc0
>> [] kthread+0xd8/0xf0
>> [] ret_from_fork+0x3f/0x70
>> [] 0x
>>
>> What can we do to help get this resolved?
>>
>> Thanks,
>>
>>
>> Robert LeBlanc
>> PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
>> the body of a message to majord...@vger.kernel.org
>> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
> Hi,
> I've encountered the same issue and found a hack to fix it at [1] but I think
> the correct way for handling this issue would be like you said to tear down
> the session in case a TASK ABORT times out. Unfortunately I'm not really
> familiar with the target code myself so I mainly use this reply to get me into
> the Cc loop.
>
> [1] http://marc.info/?l=linux-scsi&m=147282568910535&w=2
>
>
Hmm. Looking at the code it looks as we might miss some calls to
'complete'. Can you try with the attached patch?
Cheers,
Hannes
--
Dr. Hannes Reinecke zSeries & Storage
h...@suse.de +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
>From d481d8c27df8c09ea3798ce4a7217a26c3533161 Mon Sep 17 00:00:00 2001
From: Hannes Reinecke
Date: Tue, 4 Oct 2016 11:05:46 +0200
Subject: [PATCH] iscsi_target: sanitze sess_wait_on_completion
When closing a session we only should set 'sess_wait_on_completion'
if we are actually calling wait_for_completion(). And we should indeed
call 'complete' in these cases, too.
And add some WARN_ON() if we mess up with calculating the number
of completions, too.
Signed-off-by: Hannes Reinecke
---
drivers/target/iscsi/iscsi_target.c | 10 +++---
1 file changed, 7 insertions(+), 3 deletions(-)
diff --git a/drivers/target/iscsi/iscsi_target.c b/drivers/target/iscsi/iscsi_target.c
index 39b928c..313724c 100644
--- a/drivers/target/iscsi/iscsi_target.c
+++ b/drivers/target/iscsi/iscsi_target.c
@@ -4287,6 +4287,7 @@ int iscsit_close_connection(
if (!atomic_read(&sess->session_reinstatement) &&
atomic_read(&sess->session_fall_back_to_erl0)) {
spin_unlock_bh(&sess->conn_lock);
+ WARN_ON(atomic_read(&sess->sleep_on_sess_wait_comp));
iscsit_close_session(sess);
return 0;
@@ -4557,7 +4558,6 @@ int iscsit_free_session(struct iscsi_session *sess)
int is_last;
spin_lock_bh(&sess->conn_lock);
- atomic_set(&sess->sleep_on_sess_wait_comp, 1);
list_for_each_entry_safe(conn, conn_tmp, &sess->sess_conn_list,
conn_list) {
@@ -4585,7 +4585,10 @@ int iscsit_free_session(struct iscsi_session *sess)
if (atomic_read(&sess->nconn)) {
spin_unlock_bh(&sess->conn_lock);
+ atomic_inc(&sess->sleep_on_sess_wait_comp);
wait_for_completion(&sess->session_wait_comp);
+ atomic_dec(&sess->sleep_on_sess_wait_comp);
+ WARN_ON(atomic_read(&sess->sleep_on_sess_wait_comp));
} else
spin_unlock_bh(&sess->conn_lock);
@@ -4603,8 +4606,6 @@ void iscsit_stop_session(
int is_last;
spin_lock_bh(&sess->conn_lock);
- if (session_sleep)
- atomic_set(&sess->sleep_on_sess_wait_comp, 1);
if (connection_sleep) {
list_for_each_entry_safe(conn, conn_tmp, &sess->sess_conn_list,
@@ -4636,7 +4637,10 @@ void iscsit_stop_session(
if (session_sleep && atomic_read(&sess->nconn)) {
spin_unlock_bh(&sess->conn_lock);
+ atomic_inc(&sess->sleep_on_sess_wait_comp);
wait_for_completion(&sess->sessi
Re: iscsi_trx going into D state
On Fri, Sep 30, 2016 at 11:14:57AM -0600, Robert LeBlanc wrote: > We are having a reoccurring problem where iscsi_trx is going into D > state. It seems like it is waiting for a session tear down to happen > or something, but keeps waiting. We have to reboot these targets on > occasion. This is running the 4.4.12 kernel and we have seen it on > several previous 4.4.x and 4.2.x kernels. There is no message in dmesg > or /var/log/messages. This seems to happen with increased frequency > when we have a disruption in our Infiniband fabric, but can happen > without any changes to the fabric (other than hosts rebooting). > > # ps aux | grep iscsi | grep D > root 4185 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_trx] > root 18505 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_np] > > # cat /proc/4185/stack > [] target_wait_for_sess_cmds+0x49/0x1a0 > [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] > [] iscsit_close_connection+0x162/0x840 > [] iscsit_take_action_for_connection_exit+0x7f/0x100 > [] iscsi_target_rx_thread+0x5a0/0xe80 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > > # cat /proc/18505/stack > [] iscsit_stop_session+0x1b1/0x1c0 > [] iscsi_check_for_session_reinstatement+0x1e6/0x270 > [] iscsi_target_check_for_existing_instances+0x30/0x40 > [] iscsi_target_do_login+0x140/0x640 > [] iscsi_target_start_negotiation+0x1c/0xb0 > [] iscsi_target_login_thread+0xa9b/0xfc0 > [] kthread+0xd8/0xf0 > [] ret_from_fork+0x3f/0x70 > [] 0x > > What can we do to help get this resolved? > > Thanks, > > > Robert LeBlanc > PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 > -- > To unsubscribe from this list: send the line "unsubscribe linux-scsi" in > the body of a message to majord...@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html Hi, I've encountered the same issue and found a hack to fix it at [1] but I think the correct way for handling this issue would be like you said to tear down the session in case a TASK ABORT times out. Unfortunately I'm not really familiar with the target code myself so I mainly use this reply to get me into the Cc loop. [1] http://marc.info/?l=linux-scsi&m=147282568910535&w=2 -- Johannes Thumshirn Storage jthumsh...@suse.de+49 911 74053 689 SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg GF: Felix Imendörffer, Jane Smithard, Graham Norton HRB 21284 (AG Nürnberg) Key fingerprint = EC38 9CAB C2C4 F25D 8600 D0D0 0393 969D 2D76 0850 -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
iscsi_trx going into D state
We are having a reoccurring problem where iscsi_trx is going into D state. It seems like it is waiting for a session tear down to happen or something, but keeps waiting. We have to reboot these targets on occasion. This is running the 4.4.12 kernel and we have seen it on several previous 4.4.x and 4.2.x kernels. There is no message in dmesg or /var/log/messages. This seems to happen with increased frequency when we have a disruption in our Infiniband fabric, but can happen without any changes to the fabric (other than hosts rebooting). # ps aux | grep iscsi | grep D root 4185 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_trx] root 18505 0.0 0.0 0 0 ?DSep29 0:00 [iscsi_np] # cat /proc/4185/stack [] target_wait_for_sess_cmds+0x49/0x1a0 [] isert_wait_conn+0x1ab/0x2f0 [ib_isert] [] iscsit_close_connection+0x162/0x840 [] iscsit_take_action_for_connection_exit+0x7f/0x100 [] iscsi_target_rx_thread+0x5a0/0xe80 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x # cat /proc/18505/stack [] iscsit_stop_session+0x1b1/0x1c0 [] iscsi_check_for_session_reinstatement+0x1e6/0x270 [] iscsi_target_check_for_existing_instances+0x30/0x40 [] iscsi_target_do_login+0x140/0x640 [] iscsi_target_start_negotiation+0x1c/0xb0 [] iscsi_target_login_thread+0xa9b/0xfc0 [] kthread+0xd8/0xf0 [] ret_from_fork+0x3f/0x70 [] 0x What can we do to help get this resolved? Thanks, Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 -- To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
