linux-block.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Sitsofe Wheeler <sitsofe@gmail.com>
To: Hannes Reinecke <hare@suse.de>
Cc: Laurence Oberman <loberman@redhat.com>,
	linux-ide@vger.kernel.org, linux-block@vger.kernel.org
Subject: Re: failed command: WRITE FPDMA QUEUED with Samsung 860 EVO
Date: Wed, 9 Jan 2019 06:54:37 +0000	[thread overview]
Message-ID: <CALjAwxgt_r46a5dr0U4AnRTNh0AtjRyY-Nr8e0aofaJzr4SC_A@mail.gmail.com> (raw)
In-Reply-To: <CALjAwxjaffzBMSEC=R1ftW1upb2LZWuYinOxORGGUU9THm4vbA@mail.gmail.com>

On Tue, 8 Jan 2019 at 07:06, Sitsofe Wheeler <sitsofe@gmail.com> 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/

      reply	other threads:[~2019-01-09  6:54 UTC|newest]

Thread overview: 13+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2019-01-02 15:25 failed command: WRITE FPDMA QUEUED with Samsung 860 EVO Sitsofe Wheeler
2019-01-02 15:29 ` Sitsofe Wheeler
2019-01-02 16:10   ` Laurence Oberman
2019-01-03 18:28     ` Laurence Oberman
2019-01-03 20:47       ` Laurence Oberman
2019-01-03 22:24         ` Sitsofe Wheeler
2019-01-03 22:40           ` Laurence Oberman
2019-01-04  7:33             ` Sitsofe Wheeler
2019-01-07  7:17               ` Hannes Reinecke
2019-01-07  7:41                 ` Sitsofe Wheeler
2019-01-07  8:46                   ` Hannes Reinecke
2019-01-08  7:06                     ` Sitsofe Wheeler
2019-01-09  6:54                       ` Sitsofe Wheeler [this message]

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=CALjAwxgt_r46a5dr0U4AnRTNh0AtjRyY-Nr8e0aofaJzr4SC_A@mail.gmail.com \
    --to=sitsofe@gmail.com \
    --cc=hare@suse.de \
    --cc=linux-block@vger.kernel.org \
    --cc=linux-ide@vger.kernel.org \
    --cc=loberman@redhat.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).