Re: failed command: WRITE FPDMA QUEUED with Samsung 860 EVO

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Tue, 8 Jan 2019 at 07:06, Sitsofe Wheeler <sitsofe@xxxxxxxxx> wrote:
>
> > As for the NCQ issues: it might be that the adapter has issues with NCQ
> > (quite some older adapters do).
> > It might also be a problem with the _previous_ command which failed; can
> > you enable libata tracing to figure out the command flow?
>
> OK I'll see if I can get around to this one tomorrow.

So I wound up attempting this from an Ubuntu 18.04.1 live cd (because
I was trying to minimize background disk usage). I deactivated
LVM/VG/mdadm devices before running the test (lvchange -a n ...;
vgchange -a n ...; mdadm --stop ...).

Kernel:
Linux ubuntu-server 4.15.0-29-generic #31-Ubuntu SMP Tue Jul 17
15:39:52 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Tracing setup (I don't know if this is correct - googling around for
"enable libata tracing" only turned up
https://github.com/torvalds/linux/blob/master/drivers/ata/libata-trace.c
which doesn't contain an example):
echo "libata*" > /sys/kernel/debug/tracing/set_ftrace_filter
echo 1 > /sys/kernel/debug/tracing/events/libata/enable

Clear dmesg and any tracing:
dmesg -C
echo "" > /sys/kernel/debug/tracing/trace

<Some fiddling around with apt/apt config to fetch down a copy of fio>

fio command used:
fio --readonly --name --rw=randread --filename /dev/sdb --bs=32k
--ioengine=libaio --iodepth=16 --direct=1 --runtime=20s --time_based
--max_latency=100ms
(this is so that fio quits when the latency becomes high due to the bus resets)

After fio exits:
dmesg
less  /sys/kernel/debug/tracing/trace

dmesg looks like this:
[ 2427.105459] ata2.00: exception Emask 0x0 SAct 0x7fffffff SErr 0x0 action 0x6
[ 2427.105465] ata2.00: irq_stat 0x40000008
[ 2427.105472] ata2.00: failed command: READ FPDMA QUEUED
[ 2427.105486] ata2.00: cmd 60/40:68:40:c1:00/00:00:00:00:00/40 tag 13
ncq dma 32768 in
                        res 41/84:40:40:c1:00/00:00:00:00:00/00 Emask
0x410 (ATA bus error) <F>
[ 2427.105490] ata2.00: status: { DRDY ERR }
[ 2427.105493] ata2.00: error: { ICRC ABRT }
[ 2427.105503] ata2: hard resetting link
[ 2427.576563] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 2427.576992] ata2.00: supports DRM functions and may not be fully accessible
[ 2427.581186] ata2.00: supports DRM functions and may not be fully accessible
[ 2427.584783] ata2.00: configured for UDMA/33
[ 2427.584857] ata2: EH complete
[ 2427.585742] ata2.00: Enabling discard_zeroes_data

The start of the trace file looks like this:
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
             fio-4212  [001] d...  2426.910197: ata_qc_issue:
ata_port=2 ata_dev=0 tag=15 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:78:00:00:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910267: ata_qc_issue:
ata_port=2 ata_dev=0 tag=16 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:80:40:00:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910320: ata_qc_issue:
ata_port=2 ata_dev=0 tag=17 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:88:80:00:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910378: ata_qc_issue:
ata_port=2 ata_dev=0 tag=18 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:90:c0:00:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910434: ata_qc_issue:
ata_port=2 ata_dev=0 tag=19 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:98:00:01:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910489: ata_qc_issue:
ata_port=2 ata_dev=0 tag=20 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:a0:40:01:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910546: ata_qc_issue:
ata_port=2 ata_dev=0 tag=21 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:a8:80:01:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910599: ata_qc_issue:
ata_port=2 ata_dev=0 tag=22 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:b0:c0:01:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910659: ata_qc_issue:
ata_port=2 ata_dev=0 tag=23 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:b8:00:02:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910711: ata_qc_issue:
ata_port=2 ata_dev=0 tag=24 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:c0:40:02:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910766: ata_qc_issue:
ata_port=2 ata_dev=0 tag=25 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:c8:80:02:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910818: ata_qc_issue:
ata_port=2 ata_dev=0 tag=26 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:d0:c0:02:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910879: ata_qc_issue:
ata_port=2 ata_dev=0 tag=27 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:d8:00:03:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910934: ata_qc_issue:
ata_port=2 ata_dev=0 tag=28 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:e0:40:03:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.910985: ata_qc_issue:
ata_port=2 ata_dev=0 tag=29 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:e8:80:03:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911041: ata_qc_issue:
ata_port=2 ata_dev=0 tag=30 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:f0:c0:03:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911097: ata_qc_issue:
ata_port=2 ata_dev=0 tag=0 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:00:00:04:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911152: ata_qc_issue:
ata_port=2 ata_dev=0 tag=1 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:08:40:04:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911203: ata_qc_issue:
ata_port=2 ata_dev=0 tag=2 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:10:80:04:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911263: ata_qc_issue:
ata_port=2 ata_dev=0 tag=3 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:18:c0:04:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911318: ata_qc_issue:
ata_port=2 ata_dev=0 tag=4 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:20:00:05:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911371: ata_qc_issue:
ata_port=2 ata_dev=0 tag=5 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:28:40:05:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911427: ata_qc_issue:
ata_port=2 ata_dev=0 tag=6 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:30:80:05:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911481: ata_qc_issue:
ata_port=2 ata_dev=0 tag=7 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:38:c0:05:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911538: ata_qc_issue:
ata_port=2 ata_dev=0 tag=8 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:40:00:06:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911592: ata_qc_issue:
ata_port=2 ata_dev=0 tag=9 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:48:40:06:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911649: ata_qc_issue:
ata_port=2 ata_dev=0 tag=10 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:50:80:06:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911710: ata_qc_issue:
ata_port=2 ata_dev=0 tag=11 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:58:c0:06:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911765: ata_qc_issue:
ata_port=2 ata_dev=0 tag=12 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:60:00:07:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911820: ata_qc_issue:
ata_port=2 ata_dev=0 tag=13 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:68:40:07:00/00:00:00:00:00/40)
             fio-4212  [001] d...  2426.911874: ata_qc_issue:
ata_port=2 ata_dev=0 tag=14 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:70:80:07:00/00:00:00:00:00/40)
          <idle>-0     [000] d.h.  2426.912187: ata_qc_complete_done:
ata_port=2 ata_dev=0 tag=16 flags=75048c{ IO RETRY FAILED EH_SCHEDULED
} status={ DRDY }  res=(40/00:00:00:00:00/00:00:00:00:00/00)
          <idle>-0     [000] dNs.  2426.912314: ata_qc_issue:
ata_port=2 ata_dev=0 tag=16 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:80:c0:07:00/00:00:00:00:00/40)
             fio-4212  [000] d.h.  2426.912396: ata_qc_complete_done:
ata_port=2 ata_dev=0 tag=17 flags=7991cc{ IO QUIET RETRY FAILED }
status={ DRDY }  res=(40/00:00:00:00:00/00:00:00:00:00/00)
             fio-4212  [000] d...  2426.912510: ata_qc_issue:
ata_port=2 ata_dev=0 tag=17 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:88:00:08:00/00:00:00:00:00/40)
          <idle>-0     [000] d.h.  2426.912633: ata_qc_complete_done:
ata_port=2 ata_dev=0 tag=18 flags=7b3f2c{ IO CLEAR_EXCL FAILED
SENSE_VALID } status={ DRDY }
res=(40/00:00:00:00:00/00:00:00:00:00/00)
          <idle>-0     [000] dNs.  2426.912666: ata_qc_issue:
ata_port=2 ata_dev=0 tag=18 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:90:40:08:00/00:00:00:00:00/40)
          <idle>-0     [000] d.h.  2426.912879: ata_qc_complete_done:
ata_port=2 ata_dev=0 tag=15 flags=77974c{ IO QUIET FAILED SENSE_VALID
EH_SCHEDULED } status={ DRDY }
res=(40/00:00:00:00:00/00:00:00:00:00/00)
          <idle>-0     [000] dNs.  2426.912939: ata_qc_issue:
ata_port=2 ata_dev=0 tag=15 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:78:80:08:00/00:00:00:00:00/40)
             fio-4212  [000] d.h.  2426.913109: ata_qc_complete_done:
ata_port=2 ata_dev=0 tag=19 flags=7862cc{ IO QUIET RETRY } status={
DRDY }  res=(40/00:00:00:00:00/00:00:00:00:00/00)
             fio-4212  [000] d.s.  2426.913125: ata_qc_issue:
ata_port=2 ata_dev=0 tag=19 proto=ATA_PROT_NCQ cmd=ATA_CMD_FPDMA_READ
tf=(60/40:98:c0:08:00/00:00:00:00:00/40)

(Entirety of the trace file is available from
https://sucs.org/~sits/test/20190109-libata-ftrace.txt )

Just to check - was the above how you are supposed to enable libata tracing?

-- 
Sitsofe | http://sucs.org/~sits/



[Index of Archives]     [Linux Filesystems]     [Linux SCSI]     [Linux RAID]     [Git]     [Kernel Newbies]     [Linux Newbie]     [Security]     [Netfilter]     [Bugtraq]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Samba]     [Device Mapper]

  Powered by Linux