Re: [Iscsitarget-devel] Abort Task storm leads to conn_close issue

[Steffen P. <swp...@am...>]

Hi Arne,

I would like to thank you for the patch - we applied it Feb 6th this year and it is now June 5th and we have had no further occurrences of the conn_close bug.

I would like to request for your patch to be included in the trunk if that is possible.

Thank you for providing the patch source code.

Steffen

_______________________________________________________________________________________________
Steffen Plotner                            Amherst College            Tel (413) 542-2348
Systems/Network Administrator/Programmer   PO BOX 5000                Fax (413) 542-2626
Systems & Networking                       Amherst, MA 01002-5000     swp...@am...


> -----Original Message-----
> From: Arne Redlich [mailto:arn...@go...]
> Sent: Tuesday, February 04, 2014 3:13 PM
> To: Steffen Plotner
> Cc: isc...@li...
> Subject: Re: [Iscsitarget-devel] Abort Task storm leads to conn_close
> issue
> 
> Hi Steffen,
> 
> Thanks for the bug report / analysis.
> 
> 2014-02-04 Steffen Plotner <swp...@am...>:
> > Hi,
> >
> > I have finally observed a few more details about the latest conn_close
> > crashes in IET. Before the crash we have a rash of Abort Task events
> logged
> > by the kernel. As noted by Ross Walker in previous posts, this
> indicates a
> > connectivity problem. In our case we don't normally see those either,
> except
> > during backup times. We block the IO just for 5 seconds and we will
> see a
> > few hundred Abort Task events. This works mostly and has worked in the
> past,
> > except that we have added more virtual  machine hosts (vmware),
> increasing
> > cluster sizes and hence increasing the number of TCP connections that
> need
> > to recover.
> >
> > I have observed that after a few hundred Abort Task events there is
> the
> > possibility of a conn_close crash (not always).
> >
> > We are currently running svn version 498.
> >
> > Other references found, about this problem:
> > https://groups.google.com/forum/#!topic/iscsitarget/8kcVmhMInUs
> >
> > From the kernel messages below, it looks like we are within an
> interrupt
> > routine - why are we stuck for 60s? The instruction pointer is on a
> > spinlock? What is locked up? Is there something locked by
> iscsi_trgt:istd
> > which is then required during the conn_close?
> 
> ^^^ This is the key: while a spinlock is held a (soft) interrupt comes
> in and its handler tries to acquire the same spinlock.
> Upon closer inspection the spinlock in question turns out to be conn-
> >list_lock.
> 
> The ad-hoc fix is to prevent softirqs from interfering while holding
> this lock by updating all consumers to use the *_bh flavour of the
> locking calls. Does the attached patch (merely compile tested!) help?
> 
> HTH,
> Arne
> 
> From: Arne Redlich <arn...@go...>
> Date: Tue, 4 Feb 2014 20:41:39 +0100
> Subject: [PATCH] Use conn->list_lock only soft interrupts disabled
> 
> Otherwise we're in for a deadlock with the network softirq:
> 
> kernel: BUG: soft lockup - CPU#5 stuck for 60s! [istd9:13929]
> kernel: CPU 5:
> kernel: Modules linked in: iscsi_trgt(U) netconsole autofs4
> ip_conntrack_netbios_ns ipt_REJECT xt_tcpudp xt_state ip_conntrack
> nfnetlink iptable_filter ip_tables x_tables dm_round_robin
> dm_multipath scsi_dh video backlight sbs power_meter hwmon i2c_ec
> i2c_core dell_wmi wmi button battery asus_acpi acpi_memhotplug ac
> parport_pc lp parport joydev sr_mod cdrom sg ixgbe(U) qla2xxx
> i7core_edac bnx2 tpm_tis edac_mc tpm tpm_bios 8021q scsi_transport_fc
> serio_raw pcspkr dca dm_raid45 dm_message dm_region_hash dm_mem_cache
> dm_snapshot dm_zero dm_mirror dm_log dm_mod ata_piix libata shpchp
> megaraid_sas sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
> kernel: Pid: 13929, comm: istd9 Tainted: G     ---- 2.6.18-308.4.1.el5
> #1
> kernel: RIP: 0010:[<ffffffff80064bdf>]  [<ffffffff80064bdf>]
> .text.lock.spinlock+0x5/0x30
> kernel: RSP: 0018:ffff8106451f7b88  EFLAGS: 00000286
> kernel: RAX: 00000000ffffffff RBX: ffff810115bbec00 RCX:
> 00000000fbfce19a
> kernel: RDX: ffff810c10c83e68 RSI: ffff810c10c83980 RDI:
> ffff810c16c46058
> kernel: RBP: ffff8106451f7b00 R08: 0000000000000003 R09:
> 00000000fbfce19a
> kernel: R10: 0000000080000000 R11: 0000000000000014 R12:
> ffffffff8005dc8e
> kernel: R13: ffff810c16c46000 R14: ffffffff8007944e R15:
> ffff8106451f7b00
> kernel: FS:  0000000000000000(0000) GS:ffff81062fcdae40(0000)
> knlGS:0000000000000000
> kernel: CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
> kernel: CR2: 000000000ef82af0 CR3: 0000000000201000 CR4:
> 00000000000006a0
> kernel:
> kernel: Call Trace:
> kernel:  <IRQ>  [<ffffffff885c5042>] :iscsi_trgt:conn_close+0x26/0x97
> kernel:  [<ffffffff885c538f>] :iscsi_trgt:iet_state_change+0x24/0x3e
> kernel:  [<ffffffff800541df>] tcp_fin+0x19c/0x1ec
> 
> Signed-off-by: Arne Redlich <arn...@go...>
> ---
>  kernel/conn.c    |    4 ++--
>  kernel/iscsi.c   |   12 ++++++------
>  kernel/nthread.c |    4 ++--
>  3 files changed, 10 insertions(+), 10 deletions(-)
> 
> diff --git a/kernel/conn.c b/kernel/conn.c
> index 3740557..5c39adb 100644
> --- a/kernel/conn.c
> +++ b/kernel/conn.c
> @@ -218,7 +218,7 @@ void conn_close(struct iscsi_conn *conn)
>   if (test_and_clear_bit(CONN_ACTIVE, &conn->state))
>   set_bit(CONN_CLOSING, &conn->state);
> 
> - spin_lock(&conn->list_lock);
> + spin_lock_bh(&conn->list_lock);
>   list_for_each_entry(cmnd, &conn->pdu_list, conn_list) {
>   set_cmnd_tmfabort(cmnd);
>   if (cmnd->lun) {
> @@ -226,7 +226,7 @@ void conn_close(struct iscsi_conn *conn)
>   iscsi_cmnd_set_sense(cmnd, UNIT_ATTENTION, 0x6e, 0x0);
>   }
>   }
> - spin_unlock(&conn->list_lock);
> + spin_unlock_bh(&conn->list_lock);
> 
>   nthread_wakeup(conn->session->target);
>  }
> diff --git a/kernel/iscsi.c b/kernel/iscsi.c
> index 9ad3047..6ce74b5 100644
> --- a/kernel/iscsi.c
> +++ b/kernel/iscsi.c
> @@ -159,11 +159,11 @@ struct iscsi_cmnd *cmnd_alloc(struct iscsi_conn
> *conn, int req)
>   INIT_LIST_HEAD(&cmnd->conn_list);
>   INIT_LIST_HEAD(&cmnd->hash_list);
>   cmnd->conn = conn;
> - spin_lock(&conn->list_lock);
> + spin_lock_bh(&conn->list_lock);
>   atomic_inc(&conn->nr_cmnds);
>   if (req)
>   list_add_tail(&cmnd->conn_list, &conn->pdu_list);
> - spin_unlock(&conn->list_lock);
> + spin_unlock_bh(&conn->list_lock);
>   cmnd->tio = NULL;
> 
>   dprintk(D_GENERIC, "%p:%p\n", conn, cmnd);
> @@ -202,7 +202,7 @@ static void iscsi_cmnds_init_write(struct list_head
> *send)
>   struct iscsi_conn *conn = cmnd->conn;
>   struct list_head *pos, *next;
> 
> - spin_lock(&conn->list_lock);
> + spin_lock_bh(&conn->list_lock);
> 
>   list_for_each_safe(pos, next, send) {
>   cmnd = list_entry(pos, struct iscsi_cmnd, list);
> @@ -214,7 +214,7 @@ static void iscsi_cmnds_init_write(struct list_head
> *send)
>   list_add_tail(&cmnd->list, &conn->write_list);
>   }
> 
> - spin_unlock(&conn->list_lock);
> + spin_unlock_bh(&conn->list_lock);
> 
>   nthread_wakeup(conn->session->target);
>  }
> @@ -448,10 +448,10 @@ static void iscsi_cmnd_remove(struct iscsi_cmnd
> *cmnd)
>   BUG();
>   }
>   list_del(&cmnd->list);
> - spin_lock(&conn->list_lock);
> + spin_lock_bh(&conn->list_lock);
>   atomic_dec(&conn->nr_cmnds);
>   list_del(&cmnd->conn_list);
> - spin_unlock(&conn->list_lock);
> + spin_unlock_bh(&conn->list_lock);
> 
>   if (cmnd->tio)
>   tio_put(cmnd->tio);
> diff --git a/kernel/nthread.c b/kernel/nthread.c
> index db19544..20db2c5 100644
> --- a/kernel/nthread.c
> +++ b/kernel/nthread.c
> @@ -58,12 +58,12 @@ static struct iscsi_cmnd *
> iscsi_get_send_cmnd(struct iscsi_conn *conn)
>  {
>   struct iscsi_cmnd *cmnd = NULL;
> 
> - spin_lock(&conn->list_lock);
> + spin_lock_bh(&conn->list_lock);
>   if (!list_empty(&conn->write_list)) {
>   cmnd = list_entry(conn->write_list.next, struct iscsi_cmnd, list);
>   list_del_init(&cmnd->list);
>   }
> - spin_unlock(&conn->list_lock);
> + spin_unlock_bh(&conn->list_lock);
> 
>   return cmnd;
>  }
> --
> 1.7.9.5