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/
