From patchwork Fri Jun 30 07:22:52 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Nicholas A. Bellinger" X-Patchwork-Id: 9818581 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 35C0B603D7 for ; Fri, 30 Jun 2017 07:23:08 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 1F6C628504 for ; Fri, 30 Jun 2017 07:22:57 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 132B7285CC; Fri, 30 Jun 2017 07:22:57 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.9 required=2.0 tests=BAYES_00,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id E700728504 for ; Fri, 30 Jun 2017 07:22:55 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751745AbdF3HWz (ORCPT ); Fri, 30 Jun 2017 03:22:55 -0400 Received: from mail.linux-iscsi.org ([67.23.28.174]:41148 "EHLO linux-iscsi.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751710AbdF3HWy (ORCPT ); Fri, 30 Jun 2017 03:22:54 -0400 Received: from [192.168.1.66] (75-37-194-224.lightspeed.lsatca.sbcglobal.net [75.37.194.224]) (using SSLv3 with cipher AES256-SHA (256/256 bits)) (No client certificate requested) (Authenticated sender: nab) by linux-iscsi.org (Postfix) with ESMTPSA id B5BE7174108; Fri, 30 Jun 2017 07:27:10 +0000 (UTC) Message-ID: <1498807372.24896.45.camel@haakon3.risingtidesystems.com> Subject: Re: kernel BUG at drivers/scsi/qla2xxx/qla_target.c:3319! From: "Nicholas A. Bellinger" To: Pascal de Bruijn Cc: "Madhani, Himanshu" , target-devel , "Tran, Quinn" Date: Fri, 30 Jun 2017 00:22:52 -0700 In-Reply-To: <0883cc0b-1cd8-66e7-e2d0-8bd9c0c76b9d@unilogic.nl> References: <1498429881.26123.55.camel@haakon3.risingtidesystems.com> <0883cc0b-1cd8-66e7-e2d0-8bd9c0c76b9d@unilogic.nl> X-Mailer: Evolution 3.4.4-1 Mime-Version: 1.0 Sender: target-devel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: target-devel@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP Hi Pascal & Co, On Mon, 2017-06-26 at 15:20 +0200, Pascal de Bruijn wrote: > In the meanwhile I think we now know what's causing the circumstances > that lets this issue surface. > > We can reliably reproduce the issue when we run 'iozone -a -I' in a VM > that's placed on the LIO provided storage and kick off a md check: > > echo check > /sys/block/md0/md/sync_action > > This is also probably why we were experiencing these issues consistently > on the night between Saturday and Sunday, as an md check would be kicked > off from cron. > > Since we were experimenting with md tuning udev rules, particularly our > sync_speed_min change may have exacerbated things: > > SUBSYSTEM=="block", KERNEL=="md*", ACTION=="change", > TEST=="md/sync_speed_min", ATTR{md/sync_speed_min}="100000" > SUBSYSTEM=="block", KERNEL=="md*", ACTION=="change", > TEST=="md/sync_speed_max", ATTR{md/sync_speed_max}="1000000" > So it looks like the backend storage device provided to LIO is reaching sufficiently high enough latency to cause ESX ABORT_TASK timeouts to fire.. > > After staring at this, there are two scenarios during ABORT_TASK where > > this scenario could occur. > > > > Namely, there are two cases where tcm_qla2xxx.c calls > > tcm_qla2xxx_free_cmd() internally during ABORT_TASK: > > > > - During tcm_qla2xxx_handle_data_work() when cmd->aborted is detected. > > - During tcm_qla2xxx_aborted_task() when QLA_TGT_STATE_NEW or > > QLA_TGT_STATE_DATA_IN are set. > > > > My guess is the latter case is happening, that is resulting in > > tcm_qla2xxx_free_cmd() queuing up qla_tgt_cmd->work from > > transport_cmd_finish_abort() -> tcm_qla2xxx_aborted_task(), immediately > > before target_put_sess_cmd() is called from core_tmr_abort_task() to > > perform the final kref_put(&cmd->kref, ...). > > > > The second is the following patch to catch this scenario in progress > > during qlt_free_cmd(), and clear ->cmd_in-wq + dump the state before > > doing a cancel_work_sync(). > > > > diff --git a/drivers/scsi/qla2xxx/qla_target.h b/drivers/scsi/qla2xxx/qla_target.h > > index d644202..65752af 100644 > > --- a/drivers/scsi/qla2xxx/qla_target.h > > +++ b/drivers/scsi/qla2xxx/qla_target.h > > @@ -876,7 +876,7 @@ struct qla_tgt_cmd { > > unsigned int q_full:1; > > unsigned int term_exchg:1; > > unsigned int cmd_sent_to_fw:1; > > - unsigned int cmd_in_wq:1; > > + unsigned int cmd_in_wq; > > unsigned int aborted:1; > > unsigned int data_work:1; > > unsigned int data_work_free:1; > > diff --git a/drivers/scsi/qla2xxx/tcm_qla2xxx.c b/drivers/scsi/qla2xxx/tcm_qla2xxx.c > > index 75aeb9f..3ceb371 100644 > > --- a/drivers/scsi/qla2xxx/tcm_qla2xxx.c > > +++ b/drivers/scsi/qla2xxx/tcm_qla2xxx.c > > @@ -336,6 +336,17 @@ static void tcm_qla2xxx_release_cmd(struct se_cmd *se_cmd) > > } > > > > cmd = container_of(se_cmd, struct qla_tgt_cmd, se_cmd); > > + > > + if (cmpxchg(&cmd->cmd_in_wq, 1, 0) == 1) { > > + printk("Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1" > > + " state: %d data_work: %d data_work_free: %d trc_flags: 0x%08x" > > + " se_cmd->se_cmd_flags: 0x%08x se_cmd->transport_state: 0x%08x\n" > > + " se_cmd->t_task_cdb: 0x%02x\n", cmd->state, cmd->data_work, > > + cmd->data_work_free, cmd->trc_flags, cmd->se_cmd.se_cmd_flags, > > + cmd->se_cmd.transport_state, cmd->se_cmd.t_task_cdb[0]); > > + cancel_work_sync(&cmd->work); > > + } > > + > > qlt_free_cmd(cmd); > > } > > This patch does apply cleanly to v4.9.34, however it did not compile, as > data_work, data_work_free and trc_flags are not yet present. After > removing those references it did compile fine. > > Here's the relevant part of dmesg: > > [ 103.740391] md: data-check of RAID array md0 > [ 103.740395] md: minimum _guaranteed_ speed: 100000 KB/sec/disk. > [ 103.740397] md: using maximum available idle IO bandwidth (but not more than 1000000 KB/sec) for data-check. > [ 103.740416] md: using 128k window, over a total of 405798912k. > [ 435.673247] ABORT_TASK: Found referenced qla2xxx task_tag: 1222180 > [ 435.927330] Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1 state: 2 se_cmd->se_cmd_flags: 0x01c00109 se_cmd->transport_state: 0x00000091 se_cmd->t_task_cdb: 0x2a > [ 435.927351] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1222180 > [ 565.785280] qla2xxx/21:00:00:24:ff:08:c4:8a: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION. > [ 702.818402] ABORT_TASK: Found referenced qla2xxx task_tag: 1230964 > [ 703.090441] Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1 state: 2 se_cmd->se_cmd_flags: 0x01c00109 se_cmd->transport_state: 0x00000091 se_cmd->t_task_cdb: 0x2a > [ 703.090457] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1230964 > [ 888.912452] ABORT_TASK: Found referenced qla2xxx task_tag: 1215316 > [ 889.133709] Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1 state: 2 se_cmd->se_cmd_flags: 0x01c00109 se_cmd->transport_state: 0x00000091 se_cmd->t_task_cdb: 0x2a > [ 889.133713] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1215316 > [ 1741.356248] ABORT_TASK: Found referenced qla2xxx task_tag: 1222900 > [ 1741.609044] Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1 state: 2 se_cmd->se_cmd_flags: 0x01c00109 se_cmd->transport_state: 0x00000091 se_cmd->t_task_cdb: 0x2a > [ 1741.609047] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1222900 > [ 2365.885579] qla2xxx/21:00:00:24:ff:01:fa:9d: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION. > [ 2425.729887] ABORT_TASK: Found referenced qla2xxx task_tag: 1242772 > [ 2425.901292] Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1 state: 2 se_cmd->se_cmd_flags: 0x01c00109 se_cmd->transport_state: 0x00000091se_cmd->t_task_cdb: 0x2a > [ 2425.901296] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: > 1242772 > [ 2778.797321] md: md0: data-check done. > [ 4165.989290] qla2xxx/21:00:00:24:ff:01:fa:9d: Unsupported SCSI Opcode > 0x85, sending CHECK_CONDITION. > > Presumably every "Cancelling..." would have been a lockup? Fantastic, this is exactly the info I was looking for. :) So decoding the 'Canceling outstanding qla_tgt_cmd->cmd_in_wq = 1' bits: *) qla_tgt_cmd->state: 2 qla_tgt_cmd->state = 2 is QLA_TGT_STATE_DATA_IN, which means FCP data-out was successfully received, and the WRITE CDB has been submitted into LIO backend storage. *) se_cmd->se_cmd_flags: 0x01c00109 This bitmask means the following flags are set: SCF_SUPPORTED_SAM_OPCODE SCF_SCSI_DATA_CDB SCF_SE_LUN_CMD SCF_ACK_KREF SCF_USE_CPUID SCF_TASK_ATTR_SET Nothing out of the ordinarily here.. *) se_cmd->transport_state: 0x00000091 CMD_T_ABORTED CMD_T_SENT; CMD_T_DEV_ACTIVE; This means the WRITE command sent to the backend device, but did not complete before it was explicitly aborted by the ESX host. Based on what's in the logs above, this also looks as expected. *) se_cmd->t_task_cdb: 0x2a So this command is a WRITE_10 = 0x2a. This would indicate WRITE latency for the LIO backend storage is getting sufficiently high to trigger ESX host side ABORT_TASK timeouts, which are much more aggressive than normal Linux host I/O timeouts. So separate from the qla2xxx BUG_ON here discussed below, the high backend device latency is worth looking into, as usually once ESX host starts triggering ABORT_TASK timeouts it ends up taking the datastore offline. That said, I'm certain you're hitting the bogus tcm_qla2xxx_free_cmd() in tcm_qla2xxx_aborted_task(), which based on the initial analysis is definitely the wrong thing to do. So here's a patch against v4.12-rc that addresses the scenario you where able to trigger, and fixes the second scenario as well. As you noted above, it will take a little massaging to apply to v4.9.x due to qla_tgt_cmd->cmd->cmd_flags becoming qla_tgt_cmd->data_work and ->data_work_free. But that shouldn't be too hard. :) So please test without the initial debug patch on your v4.9.y based setup. Himanshu + Quinn, please review as after further groking of what Pascal has observed, these are two obvious bugs. From 4db6a8145940d0bbd10265020d681961ce2d3238 Mon Sep 17 00:00:00 2001 From: Nicholas Bellinger Date: Fri, 30 Jun 2017 00:08:13 -0700 Subject: [PATCH] qla2xxx: Fix incorrect tcm_qla2xxx_free_cmd use during TMR ABORT This patch drops two incorrect usages of tcm_qla2xxx_free_cmd() during TMR ABORT within tcm_qla2xxx_handle_data_work() and tcm_qla2xxx_aborted_task(), which where attempting to dispatch into workqueue context to do tcm_qla2xxx_complete_free() and subsequently invoke transport_generic_free_cmd(). This is incorrect because during TMR ABORT target-core will drop the outstanding se_cmd->cmd_kref references once it has quiesced the se_cmd via transport_wait_for_tasks(), and in the case of qla2xxx it should not attempt to do it's own transport_generic_free_cmd(). As reported by Pascal, this was originally manifesting as a BUG_ON(cmd->cmd_in_wq) in qlt_free_cmd() during TMR ABORT with a LIO backend with sufficently high WRITE latency to trigger a host side TMR ABORT_TASK to occur. In addition, for the case in tcm_qla2xxx_write_pending_status() and tcm_qla2xxx_handle_data_work() that waits for outstanding FCP WRITE data transfer to complete before preceedin with a TMR ABORT, avoid using se_cmd->t_transport_stop_comp that is already used by transport_wait_for_tasks() and use a qla2xxx internal struct completion instead. Reported-by: Pascal de Bruijn Cc: Himanshu Madhani Cc: Quinn Tran Cc: # 3.10+ Signed-off-by: Nicholas Bellinger Acked-by: Himanshu Madhani --- drivers/scsi/qla2xxx/qla_target.c | 4 ++++ drivers/scsi/qla2xxx/qla_target.h | 1 + drivers/scsi/qla2xxx/tcm_qla2xxx.c | 36 +++--------------------------------- 3 files changed, 8 insertions(+), 33 deletions(-) -- To unsubscribe from this list: send the line "unsubscribe target-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html diff --git a/drivers/scsi/qla2xxx/qla_target.c b/drivers/scsi/qla2xxx/qla_target.c index 401e245..8f8ece9 100644 --- a/drivers/scsi/qla2xxx/qla_target.c +++ b/drivers/scsi/qla2xxx/qla_target.c @@ -4079,6 +4079,8 @@ static struct qla_tgt_cmd *qlt_get_tag(scsi_qla_host_t *vha, cmd = &((struct qla_tgt_cmd *)se_sess->sess_cmd_map)[tag]; memset(cmd, 0, sizeof(struct qla_tgt_cmd)); + init_completion(&cmd->write_pending_abort_comp); + memcpy(&cmd->atio, atio, sizeof(*atio)); cmd->state = QLA_TGT_STATE_NEW; cmd->tgt = vha->vha_tgt.qla_tgt; @@ -5083,6 +5085,8 @@ static int __qlt_send_busy(struct scsi_qla_host *vha, qlt_incr_num_pend_cmds(vha); INIT_LIST_HEAD(&cmd->cmd_list); + init_completion(&cmd->write_pending_abort_comp); + memcpy(&cmd->atio, atio, sizeof(*atio)); cmd->tgt = vha->vha_tgt.qla_tgt; diff --git a/drivers/scsi/qla2xxx/qla_target.h b/drivers/scsi/qla2xxx/qla_target.h index d644202..939e93c5 100644 --- a/drivers/scsi/qla2xxx/qla_target.h +++ b/drivers/scsi/qla2xxx/qla_target.h @@ -868,6 +868,7 @@ struct qla_tgt_cmd { unsigned char sense_buffer[TRANSPORT_SENSE_BUFFER]; spinlock_t cmd_lock; + struct completion write_pending_abort_comp; /* to save extra sess dereferences */ unsigned int conf_compl_supported:1; unsigned int sg_mapped:1; diff --git a/drivers/scsi/qla2xxx/tcm_qla2xxx.c b/drivers/scsi/qla2xxx/tcm_qla2xxx.c index 75aeb9f..8c1bf9b 100644 --- a/drivers/scsi/qla2xxx/tcm_qla2xxx.c +++ b/drivers/scsi/qla2xxx/tcm_qla2xxx.c @@ -415,6 +415,7 @@ static int tcm_qla2xxx_write_pending(struct se_cmd *se_cmd) static int tcm_qla2xxx_write_pending_status(struct se_cmd *se_cmd) { + struct qla_tgt_cmd *cmd = container_of(se_cmd, struct qla_tgt_cmd, se_cmd); unsigned long flags; /* * Check for WRITE_PENDING status to determine if we need to wait for @@ -424,8 +425,7 @@ static int tcm_qla2xxx_write_pending_status(struct se_cmd *se_cmd) if (se_cmd->t_state == TRANSPORT_WRITE_PENDING || se_cmd->t_state == TRANSPORT_COMPLETE_QF_WP) { spin_unlock_irqrestore(&se_cmd->t_state_lock, flags); - wait_for_completion_timeout(&se_cmd->t_transport_stop_comp, - 50); + wait_for_completion(&cmd->write_pending_abort_comp); return 0; } spin_unlock_irqrestore(&se_cmd->t_state_lock, flags); @@ -501,7 +501,6 @@ static int tcm_qla2xxx_handle_cmd(scsi_qla_host_t *vha, struct qla_tgt_cmd *cmd, static void tcm_qla2xxx_handle_data_work(struct work_struct *work) { struct qla_tgt_cmd *cmd = container_of(work, struct qla_tgt_cmd, work); - unsigned long flags; /* * Ensure that the complete FCP WRITE payload has been received. @@ -509,17 +508,6 @@ static void tcm_qla2xxx_handle_data_work(struct work_struct *work) */ cmd->cmd_in_wq = 0; - spin_lock_irqsave(&cmd->cmd_lock, flags); - cmd->data_work = 1; - if (cmd->aborted) { - cmd->data_work_free = 1; - spin_unlock_irqrestore(&cmd->cmd_lock, flags); - - tcm_qla2xxx_free_cmd(cmd); - return; - } - spin_unlock_irqrestore(&cmd->cmd_lock, flags); - cmd->vha->tgt_counters.qla_core_ret_ctio++; if (!cmd->write_data_transferred) { /* @@ -527,7 +515,7 @@ static void tcm_qla2xxx_handle_data_work(struct work_struct *work) * waiting upon completion in tcm_qla2xxx_write_pending_status() */ if (cmd->se_cmd.transport_state & CMD_T_ABORTED) { - complete(&cmd->se_cmd.t_transport_stop_comp); + complete(&cmd->write_pending_abort_comp); return; } @@ -753,31 +741,13 @@ static void tcm_qla2xxx_queue_tm_rsp(struct se_cmd *se_cmd) qlt_xmit_tm_rsp(mcmd); } -#define DATA_WORK_NOT_FREE(_cmd) (_cmd->data_work && !_cmd->data_work_free) static void tcm_qla2xxx_aborted_task(struct se_cmd *se_cmd) { struct qla_tgt_cmd *cmd = container_of(se_cmd, struct qla_tgt_cmd, se_cmd); - unsigned long flags; if (qlt_abort_cmd(cmd)) return; - - spin_lock_irqsave(&cmd->cmd_lock, flags); - if ((cmd->state == QLA_TGT_STATE_NEW)|| - ((cmd->state == QLA_TGT_STATE_DATA_IN) && - DATA_WORK_NOT_FREE(cmd))) { - cmd->data_work_free = 1; - spin_unlock_irqrestore(&cmd->cmd_lock, flags); - /* - * cmd has not reached fw, Use this trigger to free it. - */ - tcm_qla2xxx_free_cmd(cmd); - return; - } - spin_unlock_irqrestore(&cmd->cmd_lock, flags); - return; - } static void tcm_qla2xxx_clear_sess_lookup(struct tcm_qla2xxx_lport *,