On Mon, 2017-07-10 at 20:41 -0700, Nicholas A. Bellinger wrote:
> On Mon, 2017-07-10 at 17:04 +0200, Pascal de Bruijn wrote:
> > On 07-07-17 06:26, Nicholas A. Bellinger wrote:
> > > On Mon, 2017-07-03 at 16:03 +0200, Pascal de Bruijn wrote:
> > >> So abort_task can still be observed, but they do not result in a
> > >> non-functional not-quite-PANICked machine anymore.
> > > Thank alot for the bug report and your continuous testing to get this
> > > resolved. The patch is queued up in target-pending/for-next with your
> > > Tested-by, and will be CC' to stable so the older v4.x.y and v3.x.y
> > > kernels get this fix as well.
> > >
> > > Thanks again.
> >
> > I'm afraid we may not be quite there yet after all...
> >
> > So we had the other two machines run an md check this weekend
> > as well, again with a rediculously high synx_speed_max:
> >
> > Jul 9 04:00:01 myhost kernel: [661309.794774] md: data-check of RAID array md0
> > Jul 9 04:00:01 myhost kernel: [661309.799173] md: minimum _guaranteed_ speed: 10000 KB/sec/disk.
> > Jul 9 04:00:01 myhost kernel: [661309.805219] md: using maximum available idle IO bandwidth (but not more than 1000000 KB/sec) for data-check.
> > Jul 9 04:00:01 myhost kernel: [661309.815194] md: using 128k window, over a total of 3252682752k.
> > Jul 9 04:00:42 myhost kernel: [661351.076391] qla2xxx/21:00:00:24:ff:4b:8f:58: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:02:01 myhost kernel: [661429.985082] qla2xxx/21:00:00:24:ff:4b:9e:19: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:04:24 myhost kernel: [661573.395245] qla2xxx/50:01:43:80:28:ca:86:36: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:04:57 myhost kernel: [661605.837694] qla2xxx/50:01:43:80:28:ca:86:e6: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:09:19 myhost kernel: [661868.261211] qla2xxx/21:00:00:24:ff:54:9e:ab: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:13:17 myhost kernel: [662105.788459] ABORT_TASK: Found referenced qla2xxx task_tag: 1175332
> > Jul 9 04:13:17 myhost kernel: [662105.794794] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag: 1175332
> > Jul 9 04:13:17 myhost kernel: [662105.990584] ABORT_TASK: Found referenced qla2xxx task_tag: 1175380
> > Jul 9 04:13:18 myhost kernel: [662106.510403] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1175380
> > Jul 9 04:13:20 myhost kernel: [662108.988526] ABORT_TASK: Found referenced qla2xxx task_tag: 1175620
> > Jul 9 04:13:31 myhost kernel: [662119.684969] ABORT_TASK: Found referenced qla2xxx task_tag: 1211140
>
> This means the outstanding I/O was located, but never completed back.
>
> Or, there is something else blocked waiting for completion like
> outstanding qla2xxx WRITE transfer, before the abort may proceed.
>
> > Jul 9 04:16:42 myhost kernel: [662310.617910] qla2xxx/21:00:00:24:ff:92:bf:43: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:18:00 myhost kernel: [662389.415853] qla2xxx/21:00:00:24:ff:54:a1:33: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:18:22 myhost kernel: [662411.066461] qla2xxx/21:00:00:24:ff:92:bf:59: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 04:20:23 myhost kernel: [662531.852833] qla2xxx/21:00:00:24:ff:3c:d0:94: Unsupported SCSI Opcode 0x85, sending CHECK_CONDITION.
> > Jul 9 07:00:28 myhost kernel: [672137.325166] md: md0: data-check done.
> >
>
> Btw, where there any hung task warnings while this was happening..?
>
> > The machine in question was still responsive (was accepting
> > SSH logins), however it seemed VMware hosts weren't seeing
> > the volume anymore (presumably due to the heavy IO on the backend).
> >
> > Also, several (12?) kworkers seemed stuck in a D state.
> >
>
> Next time that happens, do a 'cat /proc/$PID/stack' to see where those
> kworkers are blocked in un-interruptible sleep.
>
> > When my collegue tried to reboot the machine it got
> > (presumably) stuck on
> >
> > /usr/bin/targetctl clear
> >
> > After which it was forcefully rebooted :)
> >
> > Sorry we don't have any more detailed info at this point.
> > We haven't been able to reproduce this on a
> > different machine yet :(
>
> Ok, please try with the following debug patch to verify if it's blocked
> on qla_tgt_cmd->write_pending_abort_comp.
>
> diff --git a/drivers/scsi/qla2xxx/tcm_qla2xxx.c b/drivers/scsi/qla2xxx/tcm_qla2xxx.c
> index 8c1bf9b..1199969 100644
> --- a/drivers/scsi/qla2xxx/tcm_qla2xxx.c
> +++ b/drivers/scsi/qla2xxx/tcm_qla2xxx.c
> @@ -425,6 +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);
> + printk("Completing write_pending_abort_comp for tag: %llu\n", se_cmd->tag);
> wait_for_completion(&cmd->write_pending_abort_comp);
> return 0;
> }
> @@ -515,7 +516,11 @@ 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) {
> + u64 tag = cmd->se_cmd.tag;
> +
> + printk("Blocked on write_pending_abort_comp for tag: %llu\n", tag);
> complete(&cmd->write_pending_abort_comp);
> + printk("Awoke write_pending_abort_comp for tag: %llu\n", tag);
> return;
> }
>
Whoops, mixed up the printk() output above..
Please use this one instead:
diff --git a/drivers/scsi/qla2xxx/tcm_qla2xxx.c b/drivers/scsi/qla2xxx/tcm_qla2xxx.c
index 8c1bf9b..01ffb8a 100644
--- a/drivers/scsi/qla2xxx/tcm_qla2xxx.c
+++ b/drivers/scsi/qla2xxx/tcm_qla2xxx.c
@@ -417,6 +417,8 @@ 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;
+ u64 tag = se_cmd->tag;
+
/*
* Check for WRITE_PENDING status to determine if we need to wait for
* CTIO aborts to be posted via hardware in tcm_qla2xxx_handle_data().
@@ -425,7 +427,9 @@ 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);
+ printk("Blocked on write_pending_abort_comp for tag: %llu\n", tag);
wait_for_completion(&cmd->write_pending_abort_comp);
+ printk("Awoke write_pending_abort_comp for tag: %llu\n", tag);
return 0;
}
spin_unlock_irqrestore(&se_cmd->t_state_lock, flags);
@@ -508,6 +512,11 @@ static void tcm_qla2xxx_handle_data_work(struct work_struct *work)
*/
cmd->cmd_in_wq = 0;
+ if (cmd->se_cmd.transport_state & CMD_T_ABORTED) {
+ printk("Detected CMD_T_ABORTED from handle_data_work tag: %llu %u\n",
+ cmd->se_cmd.tag, cmd->write_data_transferred);
+ }
+
cmd->vha->tgt_counters.qla_core_ret_ctio++;
if (!cmd->write_data_transferred) {
/*
@@ -515,6 +524,8 @@ 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) {
+ printk("Completing write_pending_abort_comp for tag: %llu\n",
+ cmd->se_cmd.tag);
complete(&cmd->write_pending_abort_comp);
return;
}
--
To unsubscribe from this list: send the line "unsubscribe target-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
