| Message ID | 1664262298-239952-1-git-send-email-john.garry@huawei.com |
|---|---|
| Headers | show |
| Series | libsas and drivers: NCQ error handling | expand |
On Tue, Sep 27, 2022 at 03:04:51PM +0800, John Garry wrote: > As reported in [0], the pm8001 driver NCQ error handling more or less > duplicates what libata does in link error handling, as follows: > - abort all commands > - do autopsy with read log ext 10 command > - reset the target to recover, if necessary > > Indeed for the hisi_sas driver we want to add similar handling for NCQ > errors. > > This series add a new libsas API - sas_ata_device_link_abort() - to handle > host NCQ errors, and fixes up pm8001 and hisi_sas drivers to use it. > > A difference in the pm8001 driver NCQ error handling is that we send > SATA_ABORT per-task prior to read log ext10, but I feel that this should > not make a difference to the error handling. > > Damien kindly tested previous the series for pm8001, but any further pm8001 > testing would be appreciated as I have since tweaked pm8001 handling again. > This is because the pm8001 driver hangs on my arm64 machine read log ext10 > command. > > Finally with these changes we can make the libsas task alloc/free APIs > private, which they should always have been. > > Based on mkp-scsi @ 6.1/scsi-staging 57569c37f0ad ("scsi: iscsi: > iscsi_tcp: Fix null-ptr-deref while calling getpeername()") > > [0] https://lore.kernel.org/linux-scsi/8fb3b093-55f0-1fab-81f4-e8519810a978@huawei.com/ > > Changes since v4: > - Add Jason's tags (thanks) > - Rebase > > Changes since v3: > - Add Damien's tags (thanks) > - Modify hisi_sas processing as follows: > - use sas_task_abort() for rejected IO > - Modify abort task processing to issue softreset in certain circumstances > - rebase > > Changes since v2: > - Stop sending SATA_ABORT all for pm8001 handling > - Make "reset" optional in sas_ata_device_link_abort() > - Drop Jack's ACK > > John Garry (5): > scsi: libsas: Add sas_ata_device_link_abort() > scsi: hisi_sas: Move slot variable definition in hisi_sas_abort_task() > scsi: pm8001: Modify task abort handling for SATA task > scsi: pm8001: Use sas_ata_device_link_abort() to handle NCQ errors > scsi: libsas: Make sas_{alloc, alloc_slow, free}_task() private > > Xingui Yang (2): > scsi: hisi_sas: Add SATA_DISK_ERR bit handling for v3 hw > scsi: hisi_sas: Modify v3 HW SATA disk error state completion > processing > > drivers/scsi/hisi_sas/hisi_sas.h | 1 + > drivers/scsi/hisi_sas/hisi_sas_main.c | 26 +++- > drivers/scsi/hisi_sas/hisi_sas_v3_hw.c | 53 ++++++- > drivers/scsi/libsas/sas_ata.c | 12 ++ > drivers/scsi/libsas/sas_init.c | 3 - > drivers/scsi/libsas/sas_internal.h | 4 + > drivers/scsi/pm8001/pm8001_hwi.c | 186 ++++--------------------- > drivers/scsi/pm8001/pm8001_sas.c | 8 ++ > drivers/scsi/pm8001/pm8001_sas.h | 4 - > drivers/scsi/pm8001/pm80xx_hwi.c | 177 +++-------------------- > include/scsi/libsas.h | 4 - > include/scsi/sas_ata.h | 6 + > 12 files changed, 143 insertions(+), 341 deletions(-) > > -- > 2.35.3 > For pm80xx (pm8001 changes untested): Tested-by: Niklas Cassel <niklas.cassel@wdc.com> Notes unrelated to this patch: Both before and after this series, this driver prints: [ 215.845053] ata21.00: exception Emask 0x0 SAct 0xfc0000 SErr 0x0 action 0x6 [ 215.852308] ata21.00: failed command: WRITE FPDMA QUEUED [ 215.857801] ata21.00: cmd 61/00:00:00:3a:d3/01:00:b3:04:00/40 tag 18 ncq dma 131072 out res 43/04:00:ff:3a:d3/00:00:b3:04:00/40 Emask 0x400 (NCQ error) <F> [ 215.874396] ata21.00: status: { DRDY SENSE ERR } [ 215.879192] ata21.00: error: { ABRT } [ 215.882997] ata21.00: failed command: WRITE FPDMA QUEUED [ 215.888479] ata21.00: cmd 61/00:00:00:3b:d3/01:00:b3:04:00/40 tag 19 ncq dma 131072 out res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) [ 215.904814] ata21.00: failed command: WRITE FPDMA QUEUED [ 215.910311] ata21.00: cmd 61/00:00:00:3c:d3/01:00:b3:04:00/40 tag 20 ncq dma 131072 out res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) [ 215.932679] ata21.00: failed command: WRITE FPDMA QUEUED [ 215.941203] ata21.00: cmd 61/00:00:00:3d:d3/01:00:b3:04:00/40 tag 21 ncq dma 131072 out res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) [ 215.963616] ata21.00: failed command: WRITE FPDMA QUEUED [ 215.972150] ata21.00: cmd 61/00:00:00:3e:d3/01:00:b3:04:00/40 tag 22 ncq dma 131072 out res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) [ 215.994532] ata21.00: failed command: WRITE FPDMA QUEUED [ 216.003124] ata21.00: cmd 61/00:00:00:3f:d3/01:00:b3:04:00/40 tag 23 ncq dma 131072 out res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) HSM (Host State Machine) violation errors. For the same SATA drive connected via AHCI this will instead give: [ 3796.944923] ata14.00: exception Emask 0x0 SAct 0x80800003 SErr 0xc0000 action 0x0 [ 3796.959375] ata14.00: irq_stat 0x40000008 [ 3796.970140] ata14: SError: { CommWake 10B8B } [ 3796.981231] ata14.00: failed command: WRITE FPDMA QUEUED [ 3796.993237] ata14.00: cmd 61/00:08:00:7e:73/02:00:8e:08:00/40 tag 1 ncq dma 262144 out res 43/04:01:00:00:00/00:00:00:00:00/40 Emask 0x1 (device error) [ 3797.017984] ata14.00: status: { DRDY SENSE ERR } [ 3797.026833] ata14.00: error: { ABRT } [ 3797.034664] ata14.00: failed command: WRITE FPDMA QUEUED [ 3797.043015] ata14.00: cmd 61/00:b8:00:60:73/0a:00:8e:08:00/40 tag 23 ncq dma 1310720 out res 43/04:00:df:67:73/00:00:8e:08:00/40 Emask 0x400 (NCQ error) <F> [ 3797.065224] ata14.00: status: { DRDY SENSE ERR } [ 3797.072914] ata14.00: error: { ABRT } [ 3797.079598] ata14.00: failed command: WRITE FPDMA QUEUED [ 3797.087920] ata14.00: cmd 61/00:f8:00:6a:73/0a:00:8e:08:00/40 tag 31 ncq dma 1310720 out res 43/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 3797.109800] ata14.00: status: { DRDY SENSE ERR } [ 3797.117451] ata14.00: error: { ABRT } device error errors. Except for the I/O that caused the NCQ error, the remaining outstanding I/Os, regardless if they were aborted by the drive, as a side-effect of reading the NCQ error log (see 13.7.4 Queued Error Log (10h) in SATA 3.5a spec), or if they were aborted by the host (by sas_ata_device_link_abort()), I don't think it is correct to report these as HSM violation errors. HSM violation errors are e.g. when you try to issue a command to a drive that has ATA_BUSY bit set. Kind regards, Niklas
On 04/10/2022 14:05, Niklas Cassel wrote: >> 2.35.3 >> > For pm80xx (pm8001 changes untested): > Tested-by: Niklas Cassel<niklas.cassel@wdc.com> > > Thanks! > > Notes unrelated to this patch: > > Both before and after this series, this driver prints: > [ 215.845053] ata21.00: exception Emask 0x0 SAct 0xfc0000 SErr 0x0 action 0x6 > [ 215.852308] ata21.00: failed command: WRITE FPDMA QUEUED > [ 215.857801] ata21.00: cmd 61/00:00:00:3a:d3/01:00:b3:04:00/40 tag 18 ncq dma 131072 out > res 43/04:00:ff:3a:d3/00:00:b3:04:00/40 Emask 0x400 (NCQ error) <F> > [ 215.874396] ata21.00: status: { DRDY SENSE ERR } > [ 215.879192] ata21.00: error: { ABRT } > [ 215.882997] ata21.00: failed command: WRITE FPDMA QUEUED > [ 215.888479] ata21.00: cmd 61/00:00:00:3b:d3/01:00:b3:04:00/40 tag 19 ncq dma 131072 out > res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) > [ 215.904814] ata21.00: failed command: WRITE FPDMA QUEUED > [ 215.910311] ata21.00: cmd 61/00:00:00:3c:d3/01:00:b3:04:00/40 tag 20 ncq dma 131072 out > res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) > [ 215.932679] ata21.00: failed command: WRITE FPDMA QUEUED > [ 215.941203] ata21.00: cmd 61/00:00:00:3d:d3/01:00:b3:04:00/40 tag 21 ncq dma 131072 out > res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) > [ 215.963616] ata21.00: failed command: WRITE FPDMA QUEUED > [ 215.972150] ata21.00: cmd 61/00:00:00:3e:d3/01:00:b3:04:00/40 tag 22 ncq dma 131072 out > res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) > [ 215.994532] ata21.00: failed command: WRITE FPDMA QUEUED > [ 216.003124] ata21.00: cmd 61/00:00:00:3f:d3/01:00:b3:04:00/40 tag 23 ncq dma 131072 out > res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) > > HSM (Host State Machine) violation errors. > > For the same SATA drive connected via AHCI this will instead give: > > [ 3796.944923] ata14.00: exception Emask 0x0 SAct 0x80800003 SErr 0xc0000 action 0x0 > [ 3796.959375] ata14.00: irq_stat 0x40000008 > [ 3796.970140] ata14: SError: { CommWake 10B8B } > [ 3796.981231] ata14.00: failed command: WRITE FPDMA QUEUED > [ 3796.993237] ata14.00: cmd 61/00:08:00:7e:73/02:00:8e:08:00/40 tag 1 ncq dma 262144 out > res 43/04:01:00:00:00/00:00:00:00:00/40 Emask 0x1 (device error) > [ 3797.017984] ata14.00: status: { DRDY SENSE ERR } > [ 3797.026833] ata14.00: error: { ABRT } > [ 3797.034664] ata14.00: failed command: WRITE FPDMA QUEUED > [ 3797.043015] ata14.00: cmd 61/00:b8:00:60:73/0a:00:8e:08:00/40 tag 23 ncq dma 1310720 out > res 43/04:00:df:67:73/00:00:8e:08:00/40 Emask 0x400 (NCQ error) <F> > [ 3797.065224] ata14.00: status: { DRDY SENSE ERR } > [ 3797.072914] ata14.00: error: { ABRT } > [ 3797.079598] ata14.00: failed command: WRITE FPDMA QUEUED > [ 3797.087920] ata14.00: cmd 61/00:f8:00:6a:73/0a:00:8e:08:00/40 tag 31 ncq dma 1310720 out > res 43/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) > [ 3797.109800] ata14.00: status: { DRDY SENSE ERR } > [ 3797.117451] ata14.00: error: { ABRT } > > device error errors. > > > Except for the I/O that caused the NCQ error, the remaining outstanding I/Os, > regardless if they were aborted by the drive, as a side-effect of reading the > NCQ error log (see 13.7.4 Queued Error Log (10h) in SATA 3.5a spec), > or if they were aborted by the host (by sas_ata_device_link_abort()), > I don't think it is correct to report these as HSM violation errors. > > HSM violation errors are e.g. when you try to issue a command to a drive > that has ATA_BUSY bit set. We had a similar issue for hisi_sas and solved in patch 4/7: don't set ATA_ERR in the fis for those IO which complete with error, but abort the IO via sas_abort_task(). For pm80xx the IO is either rejected (actually completes with rejection) or is aborted via internal abort command. Maybe we can do similar for pm8001 as we allow the IO to complete in both cases with error. I'll check. Thanks, John
On 04/10/2022 15:04, John Garry wrote: >> Notes unrelated to this patch: >> >> Both before and after this series, this driver prints: >> [ 215.845053] ata21.00: exception Emask 0x0 SAct 0xfc0000 SErr 0x0 action 0x6 >> [ 215.852308] ata21.00: failed command: WRITE FPDMA QUEUED >> [ 215.857801] ata21.00: cmd 61/00:00:00:3a:d3/01:00:b3:04:00/40 tag 18 ncq dma 131072 out >> res 43/04:00:ff:3a:d3/00:00:b3:04:00/40 Emask 0x400 (NCQ error) <F> >> [ 215.874396] ata21.00: status: { DRDY SENSE ERR } >> [ 215.879192] ata21.00: error: { ABRT } >> [ 215.882997] ata21.00: failed command: WRITE FPDMA QUEUED >> [ 215.888479] ata21.00: cmd 61/00:00:00:3b:d3/01:00:b3:04:00/40 tag 19 ncq dma 131072 out >> res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) >> [ 215.904814] ata21.00: failed command: WRITE FPDMA QUEUED >> [ 215.910311] ata21.00: cmd 61/00:00:00:3c:d3/01:00:b3:04:00/40 tag 20 ncq dma 131072 out >> res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) >> [ 215.932679] ata21.00: failed command: WRITE FPDMA QUEUED >> [ 215.941203] ata21.00: cmd 61/00:00:00:3d:d3/01:00:b3:04:00/40 tag 21 ncq dma 131072 out >> res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) >> [ 215.963616] ata21.00: failed command: WRITE FPDMA QUEUED >> [ 215.972150] ata21.00: cmd 61/00:00:00:3e:d3/01:00:b3:04:00/40 tag 22 ncq dma 131072 out >> res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) >> [ 215.994532] ata21.00: failed command: WRITE FPDMA QUEUED >> [ 216.003124] ata21.00: cmd 61/00:00:00:3f:d3/01:00:b3:04:00/40 tag 23 ncq dma 131072 out >> res 00/00:00:00:00:00/00:00:00:00:00/00 Emask 0x2 (HSM violation) >> >> HSM (Host State Machine) violation errors. >> >> For the same SATA drive connected via AHCI this will instead give: >> >> [ 3796.944923] ata14.00: exception Emask 0x0 SAct 0x80800003 SErr 0xc0000 action 0x0 >> [ 3796.959375] ata14.00: irq_stat 0x40000008 >> [ 3796.970140] ata14: SError: { CommWake 10B8B } >> [ 3796.981231] ata14.00: failed command: WRITE FPDMA QUEUED >> [ 3796.993237] ata14.00: cmd 61/00:08:00:7e:73/02:00:8e:08:00/40 tag 1 ncq dma 262144 out >> res 43/04:01:00:00:00/00:00:00:00:00/40 Emask 0x1 (device error) >> [ 3797.017984] ata14.00: status: { DRDY SENSE ERR } >> [ 3797.026833] ata14.00: error: { ABRT } >> [ 3797.034664] ata14.00: failed command: WRITE FPDMA QUEUED >> [ 3797.043015] ata14.00: cmd 61/00:b8:00:60:73/0a:00:8e:08:00/40 tag 23 ncq dma 1310720 out >> res 43/04:00:df:67:73/00:00:8e:08:00/40 Emask 0x400 (NCQ error) <F> >> [ 3797.065224] ata14.00: status: { DRDY SENSE ERR } >> [ 3797.072914] ata14.00: error: { ABRT } >> [ 3797.079598] ata14.00: failed command: WRITE FPDMA QUEUED >> [ 3797.087920] ata14.00: cmd 61/00:f8:00:6a:73/0a:00:8e:08:00/40 tag 31 ncq dma 1310720 out >> res 43/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) >> [ 3797.109800] ata14.00: status: { DRDY SENSE ERR } >> [ 3797.117451] ata14.00: error: { ABRT } >> >> device error errors. >> >> >> Except for the I/O that caused the NCQ error, the remaining outstanding I/Os, >> regardless if they were aborted by the drive, as a side-effect of reading the >> NCQ error log (see 13.7.4 Queued Error Log (10h) in SATA 3.5a spec), >> or if they were aborted by the host (by sas_ata_device_link_abort()), >> I don't think it is correct to report these as HSM violation errors. >> >> HSM violation errors are e.g. when you try to issue a command to a drive >> that has ATA_BUSY bit set. > We had a similar issue for hisi_sas and solved in patch 4/7: don't set > ATA_ERR in the fis for those IO which complete with error, but abort the > IO via sas_abort_task(). > > For pm80xx the IO is either rejected (actually completes with rejection) > or is aborted via internal abort command. Maybe we can do similar for > pm8001 as we allow the IO to complete in both cases with error. I'll check. Hi Niklas, Could you try a change like this on top: void sas_ata_device_link_abort(struct domain_device *device, bool force_reset) { struct ata_port *ap = device->sata_dev.ap; struct ata_link *link = &ap->link; + device->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; + device->sata_dev.fis[3] = 0x04; link->eh_info.err_mask |= AC_ERR_DEV; if (force_reset) link->eh_info.action |= ATA_EH_RESET; ata_link_abort(link); } EXPORT_SYMBOL_GPL(sas_ata_device_link_abort); I tried it myself and it looked to work ok, except I have a problem with my arm64 system in that the read log ext times-out and all TF show "device error", like: [ 350.257870] ata1.00: qc timeout (cmd 0x47) [ 350.262054] pm80xx0:: mpi_sata_completion 2293: task null, freeing CCB tag 2 [ 350.269128] ata1.00: Read log 0x10 page 0x00 failed, Emask 0x40 [ 350.281581] ata1: failed to read log page 10h (errno=-5) [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen [ 350.584836] ata1.00: failed command: READ FPDMA QUEUED [ 350.589970] ata1.00: cmd 60/00:00:80:26:00/01:00:00:00:00/40 tag 0 ncq dma 131072 in res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 350.605533] ata1.00: status: { DRDY ERR } [ 350.609541] ata1.00: error: { ABRT } [ 350.613115] ata1.00: failed command: READ FPDMA QUEUED [ 350.618248] ata1.00: cmd 60/00:00:80:26:00/01:00:00:00:00/40 tag 1 ncq dma 131072 in res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 350.633809] ata1.00: status: { DRDY ERR [ 350.637813] ata1.00: error: { ABRT } [ 350.641384] ata1.00: failed command: READ FPDMA QUEUED [ 350.646515] ata1.00: cmd 60/00:00:80:26:00/01:00:00:00:00/40 tag 2 ncq dma 131072 in res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 350.662076] ata1.00: status: { DRDY ERR [ 350.666080] ata1.00: error: { ABRT } [ 350.669652] ata1.00: failed command: READ FPDMA QUEUED [ 350.674784] ata1.00: cmd 60/00:00:d8:26:00/01:00:00:00:00/40 tag 3 ncq dma 131072 in res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 350.690344] ata1.00: status: { DRDY ERR [ 350.694348] ata1.00: error: { ABRT } [ 350.697919] ata1.00: failed command: READ FPDMA QUEUED [ 350.703051] ata1.00: cmd 60/00:00:e0:26:00/01:00:00:00:00/40 tag 4 ncq dma 131072 in res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 350.718612] ata1.00: status: { DRDY ERR [ 350.722623] ata1.00: error: { ABRT } [ 350.726196] ata1.00: failed command: READ FPDMA QUEUED [ 350.731329] ata1.00: cmd 60/00:00:c8:26:00/01:00:00:00:00/40 tag 5 ncq dma 131072 in res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) ... Thanks, John
On Wed, Oct 05, 2022 at 09:53:52AM +0100, John Garry wrote: > On 04/10/2022 15:04, John Garry wrote: > > Hi Niklas, > > Could you try a change like this on top: > > void sas_ata_device_link_abort(struct domain_device *device, bool > force_reset) > { > struct ata_port *ap = device->sata_dev.ap; > struct ata_link *link = &ap->link; > > + device->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; > + device->sata_dev.fis[3] = 0x04; > > link->eh_info.err_mask |= AC_ERR_DEV; > if (force_reset) > link->eh_info.action |= ATA_EH_RESET; > ata_link_abort(link); > } > EXPORT_SYMBOL_GPL(sas_ata_device_link_abort); > > I tried it myself and it looked to work ok, except I have a problem with my > arm64 system in that the read log ext times-out and all TF show "device > error", like: Do you know why it fails to read the log? Can you read the NCQ Command Error log using ATA16 passthrough commands? sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc The first byte is the last NCQ tag (in hex) that failed. I tried your patch, and it looks good: [ 6656.228131] ata5.00: exception Emask 0x0 SAct 0x460000 SErr 0x0 action 0x0 [ 6656.252759] ata5.00: failed command: WRITE FPDMA QUEUED [ 6656.271554] ata5.00: cmd 61/00:00:00:d8:8a/04:00:ce:03:00/40 tag 17 ncq dma 524288 out res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 6656.309308] ata5.00: status: { DRDY ERR } [ 6656.316403] ata5.00: error: { ABRT } [ 6656.322300] ata5.00: failed command: WRITE FPDMA QUEUED [ 6656.330871] ata5.00: cmd 61/00:00:00:dc:8a/04:00:ce:03:00/40 tag 18 ncq dma 524288 out res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) [ 6656.356295] ata5.00: status: { DRDY ERR } [ 6656.362931] ata5.00: error: { ABRT } [ 6656.368897] ata5.00: failed command: WRITE FPDMA QUEUED [ 6656.377471] ata5.00: cmd 61/00:00:00:d4:8a/04:00:ce:03:00/40 tag 22 ncq dma 524288 out res 43/04:00:ff:d7:8a/00:00:ce:03:00/40 Emask 0x400 (NCQ error) <F> [ 6656.403149] ata5.00: status: { DRDY SENSE ERR } [ 6656.410624] ata5.00: error: { ABRT } However, since this is a change from the existing behavior of this driver, this could go as a separate patch, and does not need to delay this series. I also think that we should do a similar patch for sas_ata_task_done(): diff --git a/drivers/scsi/libsas/sas_ata.c b/drivers/scsi/libsas/sas_ata.c index d35c9296f738..648d0693ceee 100644 --- a/drivers/scsi/libsas/sas_ata.c +++ b/drivers/scsi/libsas/sas_ata.c @@ -140,7 +140,7 @@ static void sas_ata_task_done(struct sas_task *task) } dev->sata_dev.fis[3] = 0x04; /* status err */ - dev->sata_dev.fis[2] = ATA_ERR; + dev->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; } } To avoid all SAS errors from being reported as HSM errors. Kind regards, Niklas
On 10/6/22 06:28, Niklas Cassel wrote: > On Wed, Oct 05, 2022 at 09:53:52AM +0100, John Garry wrote: >> On 04/10/2022 15:04, John Garry wrote: >> >> Hi Niklas, >> >> Could you try a change like this on top: >> >> void sas_ata_device_link_abort(struct domain_device *device, bool >> force_reset) >> { >> struct ata_port *ap = device->sata_dev.ap; >> struct ata_link *link = &ap->link; >> >> + device->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; >> + device->sata_dev.fis[3] = 0x04; >> >> link->eh_info.err_mask |= AC_ERR_DEV; >> if (force_reset) >> link->eh_info.action |= ATA_EH_RESET; >> ata_link_abort(link); >> } >> EXPORT_SYMBOL_GPL(sas_ata_device_link_abort); >> >> I tried it myself and it looked to work ok, except I have a problem with my >> arm64 system in that the read log ext times-out and all TF show "device >> error", like: > > Do you know why it fails to read the log? > Can you read the NCQ Command Error log using ATA16 passthrough commands? > > sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc > > The first byte is the last NCQ tag (in hex) that failed. libata issues read log as a non-ncq command under EH. So the NCQ error log will not help. > > > I tried your patch, and it looks good: > > [ 6656.228131] ata5.00: exception Emask 0x0 SAct 0x460000 SErr 0x0 action 0x0 > [ 6656.252759] ata5.00: failed command: WRITE FPDMA QUEUED > [ 6656.271554] ata5.00: cmd 61/00:00:00:d8:8a/04:00:ce:03:00/40 tag 17 ncq dma 524288 out > res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) > [ 6656.309308] ata5.00: status: { DRDY ERR } > [ 6656.316403] ata5.00: error: { ABRT } > [ 6656.322300] ata5.00: failed command: WRITE FPDMA QUEUED > [ 6656.330871] ata5.00: cmd 61/00:00:00:dc:8a/04:00:ce:03:00/40 tag 18 ncq dma 524288 out > res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) > [ 6656.356295] ata5.00: status: { DRDY ERR } > [ 6656.362931] ata5.00: error: { ABRT } > [ 6656.368897] ata5.00: failed command: WRITE FPDMA QUEUED > [ 6656.377471] ata5.00: cmd 61/00:00:00:d4:8a/04:00:ce:03:00/40 tag 22 ncq dma 524288 out > res 43/04:00:ff:d7:8a/00:00:ce:03:00/40 Emask 0x400 (NCQ error) <F> > [ 6656.403149] ata5.00: status: { DRDY SENSE ERR } > [ 6656.410624] ata5.00: error: { ABRT } > > However, since this is a change from the existing behavior of this driver, > this could go as a separate patch, and does not need to delay this series. > > > > I also think that we should do a similar patch for sas_ata_task_done(): > > diff --git a/drivers/scsi/libsas/sas_ata.c b/drivers/scsi/libsas/sas_ata.c > index d35c9296f738..648d0693ceee 100644 > --- a/drivers/scsi/libsas/sas_ata.c > +++ b/drivers/scsi/libsas/sas_ata.c > @@ -140,7 +140,7 @@ static void sas_ata_task_done(struct sas_task *task) > } > > dev->sata_dev.fis[3] = 0x04; /* status err */ > - dev->sata_dev.fis[2] = ATA_ERR; > + dev->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; > } > } > > To avoid all SAS errors from being reported as HSM errors. > > > Kind regards, > Niklas
On Thu, Oct 06, 2022 at 06:36:05AM +0900, Damien Le Moal wrote: > On 10/6/22 06:28, Niklas Cassel wrote: > > On Wed, Oct 05, 2022 at 09:53:52AM +0100, John Garry wrote: > >> On 04/10/2022 15:04, John Garry wrote: > >> > >> Hi Niklas, > >> > >> Could you try a change like this on top: > >> > >> void sas_ata_device_link_abort(struct domain_device *device, bool > >> force_reset) > >> { > >> struct ata_port *ap = device->sata_dev.ap; > >> struct ata_link *link = &ap->link; > >> > >> + device->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; > >> + device->sata_dev.fis[3] = 0x04; > >> > >> link->eh_info.err_mask |= AC_ERR_DEV; > >> if (force_reset) > >> link->eh_info.action |= ATA_EH_RESET; > >> ata_link_abort(link); > >> } > >> EXPORT_SYMBOL_GPL(sas_ata_device_link_abort); > >> > >> I tried it myself and it looked to work ok, except I have a problem with my > >> arm64 system in that the read log ext times-out and all TF show "device > >> error", like: > > > > Do you know why it fails to read the log? > > Can you read the NCQ Command Error log using ATA16 passthrough commands? > > > > sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc > > > > The first byte is the last NCQ tag (in hex) that failed. > > libata issues read log as a non-ncq command under EH. So the NCQ error log > will not help. Hello Damien, John explained that he got a timeout from EH when reading the log: [ 350.281581] ata1: failed to read log page 10h (errno=-5) [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen ata_eh_read_log_10h() uses ata_read_log_page(), which will first try to read the log using READ LOG DMA EXT. If that fails, it will retry using READ LOG EXT. Therefore, to see if this is a driver specific bug, I suggested to try to read the NCQ Command Error log using ATA16 passthrough commands: $ sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc will read the log using READ LOG DMA EXT. $ sudo sg_sat_read_gplog --log=0x10 /dev/sdc will read the log using READ LOG EXT. Neither of these two suggested commands are NCQ commands. (Neither command is encapsulated in a RECEIVE FPDMA QUEUED, so I'm not sure what you mean.) Garry, I now see that: [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen Your port is frozen. ata_read_log_page() calls ata_exec_internal() which calls ata_exec_internal_sg(), which will simply return an error without sending down the command to the drive, if the port is frozen. Not sure why your port is frozen, mine is obviously not. ata_do_link_abort() calls ata_eh_set_pending() without activating fast drain: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-eh.c?h=v6.0#n989 So I'm not sure why your port is frozen. (The fast drain timer does freeze the port, but it shouldn't be enabled.) It might be worthwhile to see who freezes the port in your case. Kind regards, Niklas
On 10/6/22 07:11, Niklas Cassel wrote: > On Thu, Oct 06, 2022 at 06:36:05AM +0900, Damien Le Moal wrote: >> On 10/6/22 06:28, Niklas Cassel wrote: >>> On Wed, Oct 05, 2022 at 09:53:52AM +0100, John Garry wrote: >>>> On 04/10/2022 15:04, John Garry wrote: >>>> >>>> Hi Niklas, >>>> >>>> Could you try a change like this on top: >>>> >>>> void sas_ata_device_link_abort(struct domain_device *device, bool >>>> force_reset) >>>> { >>>> struct ata_port *ap = device->sata_dev.ap; >>>> struct ata_link *link = &ap->link; >>>> >>>> + device->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; >>>> + device->sata_dev.fis[3] = 0x04; >>>> >>>> link->eh_info.err_mask |= AC_ERR_DEV; >>>> if (force_reset) >>>> link->eh_info.action |= ATA_EH_RESET; >>>> ata_link_abort(link); >>>> } >>>> EXPORT_SYMBOL_GPL(sas_ata_device_link_abort); >>>> >>>> I tried it myself and it looked to work ok, except I have a problem with my >>>> arm64 system in that the read log ext times-out and all TF show "device >>>> error", like: >>> >>> Do you know why it fails to read the log? >>> Can you read the NCQ Command Error log using ATA16 passthrough commands? >>> >>> sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc >>> >>> The first byte is the last NCQ tag (in hex) that failed. >> >> libata issues read log as a non-ncq command under EH. So the NCQ error log >> will not help. > > Hello Damien, > > John explained that he got a timeout from EH when reading the log: > [ 350.281581] ata1: failed to read log page 10h (errno=-5) > [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen > > ata_eh_read_log_10h() uses ata_read_log_page(), which will first try to read > the log using READ LOG DMA EXT. If that fails, it will retry using READ LOG EXT. > > Therefore, to see if this is a driver specific bug, I suggested to try to read > the NCQ Command Error log using ATA16 passthrough commands: > > $ sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc > will read the log using READ LOG DMA EXT. > > $ sudo sg_sat_read_gplog --log=0x10 /dev/sdc > will read the log using READ LOG EXT. > > Neither of these two suggested commands are NCQ commands. > (Neither command is encapsulated in a RECEIVE FPDMA QUEUED, > so I'm not sure what you mean.) > > > Garry, I now see that: > [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen > Your port is frozen. > > ata_read_log_page() calls ata_exec_internal() which calls ata_exec_internal_sg(), > which will simply return an error without sending down the command to the drive, > if the port is frozen. > > Not sure why your port is frozen, mine is obviously not. > > ata_do_link_abort() calls ata_eh_set_pending() without activating fast drain: > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-eh.c?h=v6.0#n989 > > So I'm not sure why your port is frozen. > (The fast drain timer does freeze the port, but it shouldn't be enabled.) > It might be worthwhile to see who freezes the port in your case. Might come from the command timeout. John has had many problems with the pm80xx HBA in his Arm machine from a while back. Likely not a driver issue but a hw one... No-one seems to be able to recreate the same problem. We need to try the HBA on our Arm board to see what happens. > > > Kind regards, > Niklas
On 05/10/2022 23:42, Damien Le Moal wrote: >> Hello Damien, >> >> John explained that he got a timeout from EH when reading the log: >> [ 350.281581] ata1: failed to read log page 10h (errno=-5) >> [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen >> >> ata_eh_read_log_10h() uses ata_read_log_page(), which will first try to read >> the log using READ LOG DMA EXT. If that fails, it will retry using READ LOG EXT. >> >> Therefore, to see if this is a driver specific bug, I suggested to try to read >> the NCQ Command Error log using ATA16 passthrough commands: >> >> $ sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc >> will read the log using READ LOG DMA EXT. >> >> $ sudo sg_sat_read_gplog --log=0x10 /dev/sdc >> will read the log using READ LOG EXT. Note that I can't get a distro to boot on this system from the HDD for the same timeout problem (so no tools easily available). >> >> Neither of these two suggested commands are NCQ commands. >> (Neither command is encapsulated in a RECEIVE FPDMA QUEUED, >> so I'm not sure what you mean.) >> >> >> Garry, I now see that: >> [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen >> Your port is frozen. >> >> ata_read_log_page() calls ata_exec_internal() which calls ata_exec_internal_sg(), >> which will simply return an error without sending down the command to the drive, >> if the port is frozen. >> >> Not sure why your port is frozen, mine is obviously not. I think that it gets frozen when the internal command for read log ext times out. More below about that timeout. >> >> ata_do_link_abort() calls ata_eh_set_pending() without activating fast drain: >> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-eh.c?h=v6.0#n989 >> >> So I'm not sure why your port is frozen. >> (The fast drain timer does freeze the port, but it shouldn't be enabled.) >> It might be worthwhile to see who freezes the port in your case. > Might come from the command timeout. John has had many problems with the > pm80xx HBA in his Arm machine from a while back. Likely not a driver issue > but a hw one... No-one seems to be able to recreate the same problem. > > We need to try the HBA on our Arm board to see what happens. > Yeah, it just looks to be the longstanding issue of using this card on my arm64 machine - that is that I get IO timeouts quite regularly. I should have mentioned that yesterday. This just seems to be a driver issue. Interestingly this read log ext always seems to timeout, so maybe I could see if there is anything specific about this command which could give a clue to the underlying issue. But I have spent much time trying to debug this issue, so not too motivated any more if I’m completely honest ... Thanks, John
On 05/10/2022 22:28, Niklas Cassel wrote: > Do you know why it fails to read the log? > Can you read the NCQ Command Error log using ATA16 passthrough commands? > > sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc > > The first byte is the last NCQ tag (in hex) that failed. Please see other reply. > > > I tried your patch, and it looks good: Thanks, good to know. > > [ 6656.228131] ata5.00: exception Emask 0x0 SAct 0x460000 SErr 0x0 action 0x0 > [ 6656.252759] ata5.00: failed command: WRITE FPDMA QUEUED > [ 6656.271554] ata5.00: cmd 61/00:00:00:d8:8a/04:00:ce:03:00/40 tag 17 ncq dma 524288 out > res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) > [ 6656.309308] ata5.00: status: { DRDY ERR } > [ 6656.316403] ata5.00: error: { ABRT } > [ 6656.322300] ata5.00: failed command: WRITE FPDMA QUEUED > [ 6656.330871] ata5.00: cmd 61/00:00:00:dc:8a/04:00:ce:03:00/40 tag 18 ncq dma 524288 out > res 41/04:00:00:00:00/00:00:00:00:00/00 Emask 0x1 (device error) > [ 6656.356295] ata5.00: status: { DRDY ERR } > [ 6656.362931] ata5.00: error: { ABRT } > [ 6656.368897] ata5.00: failed command: WRITE FPDMA QUEUED > [ 6656.377471] ata5.00: cmd 61/00:00:00:d4:8a/04:00:ce:03:00/40 tag 22 ncq dma 524288 out > res 43/04:00:ff:d7:8a/00:00:ce:03:00/40 Emask 0x400 (NCQ error) <F> > [ 6656.403149] ata5.00: status: { DRDY SENSE ERR } > [ 6656.410624] ata5.00: error: { ABRT } > > However, since this is a change from the existing behavior of this driver, > this could go as a separate patch, and does not need to delay this series. > > ok, but I am not sure about this series for 6.1 since it's now, so I will just wait. > > I also think that we should do a similar patch for sas_ata_task_done(): > > diff --git a/drivers/scsi/libsas/sas_ata.c b/drivers/scsi/libsas/sas_ata.c > index d35c9296f738..648d0693ceee 100644 > --- a/drivers/scsi/libsas/sas_ata.c > +++ b/drivers/scsi/libsas/sas_ata.c > @@ -140,7 +140,7 @@ static void sas_ata_task_done(struct sas_task *task) > } > > dev->sata_dev.fis[3] = 0x04; /* status err */ > - dev->sata_dev.fis[2] = ATA_ERR; > + dev->sata_dev.fis[2] = ATA_ERR | ATA_DRDY; > } > } > > To avoid all SAS errors from being reported as HSM errors. Yeah, I tend to agree. I can put that change in another patch. Thanks, John
On Thu, Oct 06, 2022 at 09:33:23AM +0100, John Garry wrote: > On 05/10/2022 23:42, Damien Le Moal wrote: > > > Hello Damien, > > > > > > John explained that he got a timeout from EH when reading the log: > > > [ 350.281581] ata1: failed to read log page 10h (errno=-5) > > > [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen > > > > > > ata_eh_read_log_10h() uses ata_read_log_page(), which will first try to read > > > the log using READ LOG DMA EXT. If that fails, it will retry using READ LOG EXT. > > > > > > Therefore, to see if this is a driver specific bug, I suggested to try to read > > > the NCQ Command Error log using ATA16 passthrough commands: > > > > > > $ sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc > > > will read the log using READ LOG DMA EXT. > > > > > > $ sudo sg_sat_read_gplog --log=0x10 /dev/sdc > > > will read the log using READ LOG EXT. > > Note that I can't get a distro to boot on this system from the HDD for the > same timeout problem (so no tools easily available). > > > > > > > Neither of these two suggested commands are NCQ commands. > > > (Neither command is encapsulated in a RECEIVE FPDMA QUEUED, > > > so I'm not sure what you mean.) > > > > > > > > > Garry, I now see that: > > > [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen > > > Your port is frozen. > > > > > > ata_read_log_page() calls ata_exec_internal() which calls ata_exec_internal_sg(), > > > which will simply return an error without sending down the command to the drive, > > > if the port is frozen. > > > > > > Not sure why your port is frozen, mine is obviously not. > > I think that it gets frozen when the internal command for read log ext times > out. More below about that timeout. ata_read_log_page() will first try to read using READ LOG DMA EXT. If that fails it will retry with READ LOG EXT. Your log has this: [ 350.257870] ata1.00: qc timeout (cmd 0x47) So it is definitely ATA_CMD_READ_LOG_DMA_EXT that times out. On timeout, ata_exec_internal_sg() will freeze the port: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-core.c?h=v6.0#n1577 When ata_read_log_page() retries with the port frozen, READ LOG EXT will obviously fail (since the port is frozen). Not sure why READ LOG DMA EXT would timeout for you... Perhaps your drive does not implement this command, and incorrectly reports supporting this command via ata_id_has_read_log_dma_ext(). Perhaps you could try boot your kernel with libata.force=nodmalog on the kernel command line, so that ata_read_log_page() will use READ LOG EXT on the first try. Damien, it seems that there is no use in retrying if the port is frozen/we got a timeout, so perhaps: diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c index e74ab6c0f1a0..1aa628332c8e 100644 --- a/drivers/ata/libata-core.c +++ b/drivers/ata/libata-core.c @@ -2035,7 +2035,8 @@ unsigned int ata_read_log_page(struct ata_device *dev, u8 log, if (err_mask) { if (dma) { dev->horkage |= ATA_HORKAGE_NO_DMA_LOG; - goto retry; + if (err_mask != AC_ERR_TIMEOUT) + goto retry; } or: diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c index e74ab6c0f1a0..2fa03b7573ac 100644 --- a/drivers/ata/libata-core.c +++ b/drivers/ata/libata-core.c @@ -2035,7 +2035,8 @@ unsigned int ata_read_log_page(struct ata_device *dev, u8 log, if (err_mask) { if (dma) { dev->horkage |= ATA_HORKAGE_NO_DMA_LOG; - goto retry; + if (!(dev->link->ap->pflags & ATA_PFLAG_FROZEN)) + goto retry; } would be in order, so that we actually print the real error, instead of a bogus AC_ERR_SYSTEM (returned by ata_exec_internal_sg()) when the port is frozen. > > > > > > > ata_do_link_abort() calls ata_eh_set_pending() without activating fast drain: > > > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-eh.c?h=v6.0#n989 > > > > > > So I'm not sure why your port is frozen. > > > (The fast drain timer does freeze the port, but it shouldn't be enabled.) > > > It might be worthwhile to see who freezes the port in your case. > > Might come from the command timeout. John has had many problems with the > > pm80xx HBA in his Arm machine from a while back. Likely not a driver issue > > but a hw one... No-one seems to be able to recreate the same problem. > > > > We need to try the HBA on our Arm board to see what happens. > > > > Yeah, it just looks to be the longstanding issue of using this card on my > arm64 machine - that is that I get IO timeouts quite regularly. I should > have mentioned that yesterday. This just seems to be a driver issue. Out of curiosity, which arm64 SoC is this? While it is very unlikely that this is your problem, but I've encountered an issue on an ARM board before, where the PCIe controller was incorrectly configured in device tree, causing the controller to miss interrrupts, which presented itself to the user as timeouts in the WiFi driver: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=97131f85c08e024df49480ed499aae8fb754067f Kind regards, Niklas
On 06/10/2022 15:45, Niklas Cassel wrote: >> I think that it gets frozen when the internal command for read log ext times >> out. More below about that timeout. > ata_read_log_page() will first try to read using READ LOG DMA EXT. > If that fails it will retry with READ LOG EXT. > > Your log has this: > [ 350.257870] ata1.00: qc timeout (cmd 0x47) > > So it is definitely ATA_CMD_READ_LOG_DMA_EXT that times out. > > On timeout, ata_exec_internal_sg() will freeze the port: > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-core.c?h=v6.0#n1577 > > When ata_read_log_page() retries with the port frozen, > READ LOG EXT will obviously fail (since the port is frozen). > > Not sure why READ LOG DMA EXT would timeout for you... > Perhaps your drive does not implement this command, > and incorrectly reports supporting this command via > ata_id_has_read_log_dma_ext(). > > Perhaps you could try boot your kernel with libata.force=nodmalog > on the kernel command line, so that ata_read_log_page() will use > READ LOG EXT on the first try. > I tried that and unfortunately it does not appear to help. I get this log, which proves no dmalog [ 15.757617] ata1.00: FORCE: horkage modified (nodmalog) but then still fails with timeout: [ 123.094430] ata1.00: qc timeout (cmd 0x2f) [ 123.098637] pm80xx0:: mpi_sata_completion 2293: task null, freeing CCB tag 2 [ 123.105711] ata1.00: Read log 0x10 page 0x00 failed, Emask 0x5 [ 123.118081] ata1: failed to read log page 10h (errno=-5) > > Damien, it seems that there is no use in retrying if the port > is frozen/we got a timeout, so perhaps: > > diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c > index e74ab6c0f1a0..1aa628332c8e 100644 > --- a/drivers/ata/libata-core.c > +++ b/drivers/ata/libata-core.c > @@ -2035,7 +2035,8 @@ unsigned int ata_read_log_page(struct ata_device *dev, u8 log, > if (err_mask) { > if (dma) { > dev->horkage |= ATA_HORKAGE_NO_DMA_LOG; > - goto retry; > + if (err_mask != AC_ERR_TIMEOUT) > + goto retry; > } > > or: > > diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c > index e74ab6c0f1a0..2fa03b7573ac 100644 > --- a/drivers/ata/libata-core.c > +++ b/drivers/ata/libata-core.c > @@ -2035,7 +2035,8 @@ unsigned int ata_read_log_page(struct ata_device *dev, u8 log, > if (err_mask) { > if (dma) { > dev->horkage |= ATA_HORKAGE_NO_DMA_LOG; > - goto retry; > + if (!(dev->link->ap->pflags & ATA_PFLAG_FROZEN)) > + goto retry; > } > > would be in order, so that we actually print the real error, instead of a bogus > AC_ERR_SYSTEM (returned by ata_exec_internal_sg()) when the port is frozen. > >>>> ata_do_link_abort() calls ata_eh_set_pending() without activating fast drain: >>>> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-eh.c?h=v6.0#n989 >>>> >>>> So I'm not sure why your port is frozen. >>>> (The fast drain timer does freeze the port, but it shouldn't be enabled.) >>>> It might be worthwhile to see who freezes the port in your case. >>> Might come from the command timeout. John has had many problems with the >>> pm80xx HBA in his Arm machine from a while back. Likely not a driver issue >>> but a hw one... No-one seems to be able to recreate the same problem. >>> >>> We need to try the HBA on our Arm board to see what happens. >>> >> Yeah, it just looks to be the longstanding issue of using this card on my >> arm64 machine - that is that I get IO timeouts quite regularly. I should >> have mentioned that yesterday. This just seems to be a driver issue. > Out of curiosity, which arm64 SoC is this? HiSilicon hi1620 which contains a custom arm v8 implementation. Note that others have also seen the issue with this card on other arm implementations. > > While it is very unlikely that this is your problem, but I've encountered > an issue on an ARM board before, where the PCIe controller was incorrectly > configured in device tree, causing the controller to miss interrrupts, > which presented itself to the user as timeouts in the WiFi driver: > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=97131f85c08e024df49480ed499aae8fb754067f Unlikely. Indeed, when I was checking this issue some time go, I found that not only was there no completion interrupt but also no completion when I manually examine the completion ring buffer read and write pointers. Here's where I discuss this issue earlier a bit: https://lore.kernel.org/linux-scsi/PH0PR11MB511238B8FF7B44C375DDDFADEC519@PH0PR11MB5112.namprd11.prod.outlook.com/ Thanks, John
On 10/6/22 23:45, Niklas Cassel wrote: > On Thu, Oct 06, 2022 at 09:33:23AM +0100, John Garry wrote: >> On 05/10/2022 23:42, Damien Le Moal wrote: >>>> Hello Damien, >>>> >>>> John explained that he got a timeout from EH when reading the log: >>>> [ 350.281581] ata1: failed to read log page 10h (errno=-5) >>>> [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen >>>> >>>> ata_eh_read_log_10h() uses ata_read_log_page(), which will first try to read >>>> the log using READ LOG DMA EXT. If that fails, it will retry using READ LOG EXT. >>>> >>>> Therefore, to see if this is a driver specific bug, I suggested to try to read >>>> the NCQ Command Error log using ATA16 passthrough commands: >>>> >>>> $ sudo sg_sat_read_gplog -d --log=0x10 /dev/sdc >>>> will read the log using READ LOG DMA EXT. >>>> >>>> $ sudo sg_sat_read_gplog --log=0x10 /dev/sdc >>>> will read the log using READ LOG EXT. >> >> Note that I can't get a distro to boot on this system from the HDD for the >> same timeout problem (so no tools easily available). >> >>>> >>>> Neither of these two suggested commands are NCQ commands. >>>> (Neither command is encapsulated in a RECEIVE FPDMA QUEUED, >>>> so I'm not sure what you mean.) >>>> >>>> >>>> Garry, I now see that: >>>> [ 350.577181] ata1.00: exception Emask 0x1 SAct 0xffffffff SErr 0x0 action 0x6 frozen >>>> Your port is frozen. >>>> >>>> ata_read_log_page() calls ata_exec_internal() which calls ata_exec_internal_sg(), >>>> which will simply return an error without sending down the command to the drive, >>>> if the port is frozen. >>>> >>>> Not sure why your port is frozen, mine is obviously not. >> >> I think that it gets frozen when the internal command for read log ext times >> out. More below about that timeout. > > ata_read_log_page() will first try to read using READ LOG DMA EXT. > If that fails it will retry with READ LOG EXT. > > Your log has this: > [ 350.257870] ata1.00: qc timeout (cmd 0x47) > > So it is definitely ATA_CMD_READ_LOG_DMA_EXT that times out. > > On timeout, ata_exec_internal_sg() will freeze the port: > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-core.c?h=v6.0#n1577 > > When ata_read_log_page() retries with the port frozen, > READ LOG EXT will obviously fail (since the port is frozen). > > Not sure why READ LOG DMA EXT would timeout for you... > Perhaps your drive does not implement this command, > and incorrectly reports supporting this command via > ata_id_has_read_log_dma_ext(). > > Perhaps you could try boot your kernel with libata.force=nodmalog > on the kernel command line, so that ata_read_log_page() will use > READ LOG EXT on the first try. > > > Damien, it seems that there is no use in retrying if the port > is frozen/we got a timeout, so perhaps: > > diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c > index e74ab6c0f1a0..1aa628332c8e 100644 > --- a/drivers/ata/libata-core.c > +++ b/drivers/ata/libata-core.c > @@ -2035,7 +2035,8 @@ unsigned int ata_read_log_page(struct ata_device *dev, u8 log, > if (err_mask) { > if (dma) { > dev->horkage |= ATA_HORKAGE_NO_DMA_LOG; > - goto retry; > + if (err_mask != AC_ERR_TIMEOUT) > + goto retry; > } > > or: > > diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c > index e74ab6c0f1a0..2fa03b7573ac 100644 > --- a/drivers/ata/libata-core.c > +++ b/drivers/ata/libata-core.c > @@ -2035,7 +2035,8 @@ unsigned int ata_read_log_page(struct ata_device *dev, u8 log, > if (err_mask) { > if (dma) { > dev->horkage |= ATA_HORKAGE_NO_DMA_LOG; > - goto retry; > + if (!(dev->link->ap->pflags & ATA_PFLAG_FROZEN)) > + goto retry; Yes, something like this is needed. Though I would prefer having a little ata_port_frozen() helper for the condition. > } > > would be in order, so that we actually print the real error, instead of a bogus > AC_ERR_SYSTEM (returned by ata_exec_internal_sg()) when the port is frozen. yep. >> >>>> >>>> ata_do_link_abort() calls ata_eh_set_pending() without activating fast drain: >>>> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-eh.c?h=v6.0#n989 >>>> >>>> So I'm not sure why your port is frozen. >>>> (The fast drain timer does freeze the port, but it shouldn't be enabled.) >>>> It might be worthwhile to see who freezes the port in your case. >>> Might come from the command timeout. John has had many problems with the >>> pm80xx HBA in his Arm machine from a while back. Likely not a driver issue >>> but a hw one... No-one seems to be able to recreate the same problem. >>> >>> We need to try the HBA on our Arm board to see what happens. >>> >> >> Yeah, it just looks to be the longstanding issue of using this card on my >> arm64 machine - that is that I get IO timeouts quite regularly. I should >> have mentioned that yesterday. This just seems to be a driver issue. > > Out of curiosity, which arm64 SoC is this? > > While it is very unlikely that this is your problem, but I've encountered > an issue on an ARM board before, where the PCIe controller was incorrectly > configured in device tree, causing the controller to miss interrrupts, > which presented itself to the user as timeouts in the WiFi driver: > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=97131f85c08e024df49480ed499aae8fb754067f > > > Kind regards, > Niklas
Hi Niklas, > > For the record, I tested the pm80xx driver on a HoneyComb LX2 board > (an arm64 board using ACPI). > > I tried v6.1-rc1 both with and without your series in $subject. > > I couldn't see any issues. ok, thanks for the effort. > > > What I tried: > -Running fio: > fio --name=test --filename=/dev/sdc --ioengine=io_uring --rw=randrw --direct=1 --iodepth=32 --bs=1M > on three different HDDs simultaneously for 15+ minutes, > without any errors in fio or dmesg. > > -Creating and mounting a btrfs volume, doing a huge dd to the filesystem > without issues. > > -sg_sat_read_gplog -d --log=0x10 /dev/sda > which successfully returned the log. > > > It is worth mentioning that this arm64 board has reserved memory regions, > but does not yet have a firmware that supplies a IORT RMR (reserved memory > regions) revision E.d node, which means that in order to get this board to > boot successfully, we need to supply: > "arm-smmu.disable_bypass=0 iommu.passthrough=1" > on the kernel command line. hmmm... that's interesting. I can try again with the IOMMU turned off, but, as I recall, it did not make a difference before. I think that requiring reserved memory regions would totally bust the driver (if not present) with IOMMU enabled. As I recall, sas 3008 card would not work without RMR for us. It's also interesting that this LX2 board has A72 cores. For my system, we have newer custom arm v8 cores with quite weak memory ordering implementation. With that same system, I have detected a couple of other driver memory ordering bugs which we did not see on our A72-based platforms. I always suspected that this issue was a memory ordering issue, but since the hang so reliably occurs I ruled it out. Maybe it is... thanks, John
As reported in [0], the pm8001 driver NCQ error handling more or less duplicates what libata does in link error handling, as follows: - abort all commands - do autopsy with read log ext 10 command - reset the target to recover, if necessary Indeed for the hisi_sas driver we want to add similar handling for NCQ errors. This series add a new libsas API - sas_ata_device_link_abort() - to handle host NCQ errors, and fixes up pm8001 and hisi_sas drivers to use it. A difference in the pm8001 driver NCQ error handling is that we send SATA_ABORT per-task prior to read log ext10, but I feel that this should not make a difference to the error handling. Damien kindly tested previous the series for pm8001, but any further pm8001 testing would be appreciated as I have since tweaked pm8001 handling again. This is because the pm8001 driver hangs on my arm64 machine read log ext10 command. Finally with these changes we can make the libsas task alloc/free APIs private, which they should always have been. Based on mkp-scsi @ 6.1/scsi-staging 57569c37f0ad ("scsi: iscsi: iscsi_tcp: Fix null-ptr-deref while calling getpeername()") [0] https://lore.kernel.org/linux-scsi/8fb3b093-55f0-1fab-81f4-e8519810a978@huawei.com/ Changes since v4: - Add Jason's tags (thanks) - Rebase Changes since v3: - Add Damien's tags (thanks) - Modify hisi_sas processing as follows: - use sas_task_abort() for rejected IO - Modify abort task processing to issue softreset in certain circumstances - rebase Changes since v2: - Stop sending SATA_ABORT all for pm8001 handling - Make "reset" optional in sas_ata_device_link_abort() - Drop Jack's ACK John Garry (5): scsi: libsas: Add sas_ata_device_link_abort() scsi: hisi_sas: Move slot variable definition in hisi_sas_abort_task() scsi: pm8001: Modify task abort handling for SATA task scsi: pm8001: Use sas_ata_device_link_abort() to handle NCQ errors scsi: libsas: Make sas_{alloc, alloc_slow, free}_task() private Xingui Yang (2): scsi: hisi_sas: Add SATA_DISK_ERR bit handling for v3 hw scsi: hisi_sas: Modify v3 HW SATA disk error state completion processing drivers/scsi/hisi_sas/hisi_sas.h | 1 + drivers/scsi/hisi_sas/hisi_sas_main.c | 26 +++- drivers/scsi/hisi_sas/hisi_sas_v3_hw.c | 53 ++++++- drivers/scsi/libsas/sas_ata.c | 12 ++ drivers/scsi/libsas/sas_init.c | 3 - drivers/scsi/libsas/sas_internal.h | 4 + drivers/scsi/pm8001/pm8001_hwi.c | 186 ++++--------------------- drivers/scsi/pm8001/pm8001_sas.c | 8 ++ drivers/scsi/pm8001/pm8001_sas.h | 4 - drivers/scsi/pm8001/pm80xx_hwi.c | 177 +++-------------------- include/scsi/libsas.h | 4 - include/scsi/sas_ata.h | 6 + 12 files changed, 143 insertions(+), 341 deletions(-)