Message-ID: <f3362c6f-b4b6-2914-0652-d786e19b6b03@opensource.wdc.com>
Date:   Fri, 4 Feb 2022 09:36:43 +0900
From:   Damien Le Moal <damien.lemoal@...nsource.wdc.com>
To:     John Garry <john.garry@...wei.com>, jejb@...ux.ibm.com,
        martin.petersen@...cle.com, artur.paszkiewicz@...el.com,
        jinpu.wang@...ud.ionos.com, chenxiang66@...ilicon.com,
        Ajish.Koshy@...rochip.com
Cc:     yanaijie@...wei.com, linux-doc@...r.kernel.org,
        linux-kernel@...r.kernel.org, linux-scsi@...r.kernel.org,
        linuxarm@...wei.com, liuqi115@...wei.com, Viswas.G@...rochip.com
Subject: Re: [PATCH 00/16] scsi: libsas and users: Factor out LLDD TMF code

On 2/4/22 00:55, John Garry wrote:
> On 03/02/2022 09:44, Damien Le Moal wrote:
> 
> Hi Damien,
> 
>>>>> [  385.102073] sas: Enter sas_scsi_recover_host busy: 1 failed: 1
>>>>> [  385.108026] sas: sas_scsi_find_task: aborting task 0x000000007068ed73
>>>>> [  405.561099] pm80xx0:: pm8001_exec_internal_task_abort  757:TMF task
> 
> Contrary to mentioning TMF in the log, this is not a TMF but rather an 
> internal abort timing out. I don't think that this should ever happen. 
> This command should just abort pending IO commands in the controller and 
> not send anything to the target. So for this to timeout means a HW fault 
> or driver bug. And I did not touch this code for pm8001.
> 
>>>>> timeout.
>>>>> [  405.568236] sas: sas_scsi_find_task: task 0x000000007068ed73 is
>>>>> aborted
>>>>> [  405.574930] sas: sas_eh_handle_sas_errors: task 0x000000007068ed73 is
>>>>> aborted
>>>>> [  411.192602] ata21.00: qc timeout (cmd 0xec)
>>>>> [  431.672122] pm80xx0:: pm8001_exec_internal_task_abort  757:TMF task
>>>>> timeout.
>>>>> [  431.679282] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4)
>>>>> [  431.685544] ata21.00: revalidation failed (errno=-5)
>>>>> [  441.911948] ata21.00: qc timeout (cmd 0xec)
>>>>> [  462.391545] pm80xx0:: pm8001_exec_internal_task_abort  757:TMF task
>>>>> timeout.
>>>>> [  462.398696] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4)
>>>>> [  462.404992] ata21.00: revalidation failed (errno=-5)
>>>>> [  492.598769] ata21.00: qc timeout (cmd 0xec)
>>>>> ...
>>>>>
> 
> Do you have a fuller dmesg with my series?

Here it is below. Conditions: I rebased everything on Linus latest
master, applied your series and the patch you sent below, rebooted with
pm80xx module option logging_level=31.

Device scan is all OK. With the system idle, I simply start libzbc tests
on the SATA SMR drive I have on the HBA.

The first command issued is 0x63 == NCQ NON DATA and seems to be OK, but
it seems that there are inconsistencies. And that may be what breaks the
adapter/driver state because everything after that command miserably
fails and does not complete.

The inconsistency is this line says:
[  137.193944] pm80xx0:: pm80xx_chip_sata_req  4581:no data
Which seems to be sensical for NCQ_NON_DATA command, but then, this line
seems wrong:
[  137.228015] pm80xx0:: mpi_sata_completion  2515:FPDMA len = 8

I need to go and check the specs what the FIS reply format is for
NCQ_NON_DATA.


[  137.187184] pm80xx0:: pm8001_queue_command  408:pm8001_task_exec device
[  137.193944] pm80xx0:: pm80xx_chip_sata_req  4581:no data
[  137.199339] pm80xx0:: pm80xx_chip_sata_req  4682:Sending Normal SATA
command 0x63 inb 4
[  137.207577] pm80xx0:: pm8001_mpi_msg_consume  1446:: CI=46 PI=47
msgHeader=8104200d
[  137.215399] pm80xx0:: mpi_sata_completion  2481:IO_SUCCESS
[  137.220961] pm80xx0:: mpi_sata_completion  2503:SAS_PROTO_RESPONSE
len = 20
[  137.228015] pm80xx0:: mpi_sata_completion  2515:FPDMA len = 8
[  137.233878] pm80xx0:: pm8001_mpi_msg_free_set  1403: CI=47 PI=47
[  137.236696] pm80xx0:: pm8001_queue_command  408:pm8001_task_exec device
[  137.247102] pm80xx0:: pm80xx_chip_sata_req  4585:DMA
[  137.252186] pm80xx0:: pm80xx_chip_sata_req  4593:FPDMA
[  137.257400] pm80xx0:: pm80xx_chip_sata_req  4682:Sending Normal SATA
command 0x65 inb f
[  167.506280] sas: Enter sas_scsi_recover_host busy: 1 failed: 1
[  167.512363] sas: sas_scsi_find_task: aborting task 0x00000000aa372627
[  167.519049] pm80xx0:: pm8001_chip_abort_task  4607:cmd_tag = 2, abort
task tag = 0x1
[  187.969173] pm80xx0:: pm8001_exec_internal_task_abort  753:TMF task
timeout.
[  187.976450] sas: sas_scsi_find_task: task 0x00000000aa372627 is aborted
[  187.983244] sas: sas_eh_handle_sas_errors: task 0x00000000aa372627 is
aborted
[  188.144734] pm80xx0:: pm8001_queue_command  408:pm8001_task_exec device
[  188.151555] pm80xx0:: pm80xx_chip_sata_req  4588:PIO
[  188.156648] pm80xx0:: pm80xx_chip_sata_req  4682:Sending Normal SATA
command 0xec inb 8
[  193.600813] ata21.00: qc timeout (cmd 0xec)
[  193.605976] pm80xx0:: pm8001_chip_abort_task  4607:cmd_tag = 4, abort
task tag = 0x3
[  214.080236] pm80xx0:: pm8001_exec_internal_task_abort  753:TMF task
timeout.
[  214.087563] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[  214.093929] ata21.00: revalidation failed (errno=-5)
[  214.256233] pm80xx0:: pm8001_queue_command  408:pm8001_task_exec device
[  214.263043] pm80xx0:: pm80xx_chip_sata_req  4588:PIO
[  214.268128] pm80xx0:: pm80xx_chip_sata_req  4682:Sending Normal SATA
command 0xec inb 8
[  224.319899] ata21.00: qc timeout (cmd 0xec)
[  224.324317] pm80xx0:: pm8001_chip_abort_task  4607:cmd_tag = 6, abort
task tag = 0x5
[  244.799433] pm80xx0:: pm8001_exec_internal_task_abort  753:TMF task
timeout.
[  244.806750] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[  244.813110] ata21.00: revalidation failed (errno=-5)
[  244.975500] pm80xx0:: pm8001_queue_command  408:pm8001_task_exec device
[  244.982314] pm80xx0:: pm80xx_chip_sata_req  4588:PIO
[  244.987400] pm80xx0:: pm80xx_chip_sata_req  4682:Sending Normal SATA
command 0xec inb 8
[  275.006814] ata21.00: qc timeout (cmd 0xec)
[  275.011236] pm80xx0:: pm8001_chip_abort_task  4607:cmd_tag = 8, abort
task tag = 0x7
[  295.486387] pm80xx0:: pm8001_exec_internal_task_abort  753:TMF task
timeout.
[  295.494025] ata21.00: failed to IDENTIFY (I/O error, err_mask=0x4)
[  295.500390] ata21.00: revalidation failed (errno=-5)
[  295.509179] ata21.00: disable device
[  295.670556] sas: --- Exit sas_scsi_recover_host: busy: 0 failed: 1
tries: 1
[  295.670570] sd 19:0:2:0: [sdj] REPORT ZONES start lba 0 failed
[  295.689972] sd 19:0:2:0: [sdj] REPORT ZONES: Result: hostbyte=DID_OK
driverbyte=DRIVER_OK
[  295.700621] sd 19:0:2:0: [sdj] Sense Key : Not Ready [current]
[  295.708975] sd 19:0:2:0: [sdj] Add. Sense: Logical unit not ready,
hard reset required
[  295.719331] sd 19:0:2:0: [sdj] 0 4096-byte logical blocks: (0 B/0 B)
[  295.728727] sd 19:0:2:0: [sdj] Write Protect is on
[  295.737928] sdj: detected capacity change from 39063650304 to 0
[  295.826347] sd 19:0:2:0: [sdj] tag#158 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  295.838761] sd 19:0:2:0: [sdj] tag#158 CDB: Test Unit Ready 00 00 00
00 00 00
[  295.920864] sd 19:0:2:0: [sdj] tag#780 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  295.933341] sd 19:0:2:0: [sdj] tag#780 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.010417] sd 19:0:2:0: [sdj] tag#248 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.022275] sd 19:0:2:0: [sdj] tag#248 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.101348] sd 19:0:2:0: [sdj] tag#949 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.113924] sd 19:0:2:0: [sdj] tag#949 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.192258] sd 19:0:2:0: [sdj] tag#25 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.204788] sd 19:0:2:0: [sdj] tag#25 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.284546] sd 19:0:2:0: [sdj] tag#273 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.297126] sd 19:0:2:0: [sdj] tag#273 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.376896] sd 19:0:2:0: [sdj] tag#653 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.389475] sd 19:0:2:0: [sdj] tag#653 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.468095] sd 19:0:2:0: [sdj] tag#159 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.479974] sd 19:0:2:0: [sdj] tag#159 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.560861] sd 19:0:2:0: [sdj] tag#274 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.572792] sd 19:0:2:0: [sdj] tag#274 CDB: Test Unit Ready 00 00 00
00 00 00
[  296.654506] sd 19:0:2:0: [sdj] tag#727 FAILED Result:
hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[  296.667151] sd 19:0:2:0: [sdj] tag#727 CDB: Test Unit Ready 00 00 00
00 00 00

After these messages, the tests exit on failure (drive dropped) and
there are no more messages. Doing rmmod or anything else get stuck too.
I have to reset the machine to get back to a good state.

I am starting to think that NCQ NON DATA command is being very badly
handled... Switching the tests to run with all non-NCQ commands is
working fine, albeit horribly slow (much slower than with other HBAs,
e.g. Broadcom).

Digging...

> 
> ...
> 
>>> }
>>> - res = -TMF_RESP_FUNC_FAILED;
>>> + res = TMF_RESP_FUNC_FAILED;
>>>
>>> That's effectively the same as what I have in this series in
>>> sas_execute_tmf().
>>>
>>> However your testing is a SATA device, which I'll check further.
>> This did not help. Still seeing 100% reproducible hangs.
> 
> OK, but I think that we should also have this change as the mainline 
> codes looks broken to be begin with:
> 
> --->8 ---
> 
> [PATCH] scsi: libsas: Handle all errors in sas_scsi_find_task()
> 
> LLDD TMFs callbacks may return linux or other error codes instead of TMF
> codes. This may cause problems in sas_scsi_find_task() ->
> .lldd_query_task(), as only TMF codes are handled there. As such, we may
> not return a task_disposition type. Function sas_eh_handle_sas_errors() 
> only handles that type, and may exit error
> handling early for unrecognised types.
> 
> So use TASK_ABORT_FAILED for non-TMF types returned from
> .lldd_query_task(), on the assumption that the command may still be 
> alive and error handling should be escalated.
> 
> Signed-off-by: John Garry <john.garry@...wei.com>
> 
> diff --git a/drivers/scsi/libsas/sas_scsi_host.c 
> b/drivers/scsi/libsas/sas_scsi_host.c
> index 53d8b7ede0cd..02274f471308 100644
> --- a/drivers/scsi/libsas/sas_scsi_host.c
> +++ b/drivers/scsi/libsas/sas_scsi_host.c
> @@ -316,8 +316,11 @@ static enum task_disposition 
> sas_scsi_find_task(struct sas_task *task)
>   				pr_notice("%s: task 0x%p failed to abort\n",
>   					  __func__, task);
>   				return TASK_ABORT_FAILED;
> +			default:
> +				pr_notice("%s: task 0x%p result code %d not handled, assuming 
> failed\n",
> +					  __func__, task, res);
> +				return TASK_ABORT_FAILED;
>   			}
> -
>   		}
>   	}
>   	return res;
> 
> ---8< ----
> 
>>
>> I did a lot of testing/digging today, 
> 
> Thanks for the effort!
> 
>  > and the hang cause seems to be
>  > missing task completions.
>> At random, a task times out as its completion
> 
> That sounds fimilar to my general issue running this driver on an arm64 
> host...
> 
>> does not come, and subsequent abort trial for the task fail, revalidate
>> fails
> 
> I assume SMP IOs fail if revalidation fails - if this is the case, then 
> the controller seems to be in bad state.
> 
>> and the device is dropped (capacity goes to 0). But at that point,
>> doing rmmod/modprobe to reset the device does not work. sync cache
>> command issued at rmmod time never completes. I end up needing to power
>> cycle the machine every time...
>>
>> No clue about the root cause yet, but it definitely seem to be related
>> to NCQ/high QD operation. If I force my tests to use non-NCQ commands,
>> everything is fine and the tests run to completion without any issue.
>>
>> I wonder if their is a tag management bug somewhere...
> 
> Maybe. Not sure.
> 
> On a related point, Hannes' change here could avoid it:
> 
> https://lore.kernel.org/linux-scsi/20210222132405.91369-32-hare@suse.de/
> 
>>
>> I did stumble on something very ugly in libsas too: sas_ata_qc_issue()
>> drops and retake the ata port lock. No other ATA driver do that since
>> the ata completion also take that lock. The ata port lock is taken
>> before ata_qc_issue() is called with IRQ disabled (spin_lock_irqsave()).
>> So doing a spin_unlock()/spin_lock() in sas_ata_qc_issue() (called from
>> ata_qc_issue()) seems like a very bad idea. I removed that and
>> everything work the same way (the lld execute does not sleep). But that
>> did not solve the hang problem.
> 
> I would need to check why this is done again. Before my time...
> 
>>
>> Of note is this is all with your libsas patches applied. Without the
>> patches, I have KASAN screaming at me about use-after-free in completion
>> context. With your patches, KASAN is silent.
>>
>> Another thing: this driver does not allow changing the max qd... Very
>> annoying.
>>
>> echo 1 > /sys/block/sdX/device/queue_depth
>>
>> has no effect. QD stays at 32 for an ATA drive. Need to look into that too.
> 
> I had a look at this. It seems that we fail in 
> __ata_change_queue_depth() -> ata_scsi_find_dev() returning NULL.
> 
> Thanks again for your effort, I will continue to look.
> 
> john


-- 
Damien Le Moal
Western Digital Research

Powered by blists - more mailing lists