Dear Linux folks,
On 01.05.19 11:34, Paul Menzel wrote:
> On an MSI B350M MORTAR (MS-7A37) with all firmwares, and the AHCI SSD
> Crucial MX500, *sometimes* boot and resume are delayed by four to five
> seconds, and the log contains the message *failed to set xfermode*.
>
>> [ 0.474150] ata9: SATA link up 6.0 Gbps (SStatus 133 SControl 0)
>> [ 0.474267] microcode: Microcode Update Driver: v2.2.
>> [ 0.474294] AVX2 version of gcm_enc/dec engaged.
>> [ 0.474295] AES CTR mode by8 optimization enabled
>> [ 0.474304] ata9.00: supports DRM functions and may not be fully accessible
>> [ 0.474368] ata9.00: ATA-10: CT1000MX500SSD4, M3CR020, max UDMA/133
>> [ 0.474370] ata9.00: 1953525168 sectors, multi 1: LBA48 NCQ (depth 32), AA
>> [ 0.474569] ata9.00: READ LOG DMA EXT failed, trying PIO
>> [ 0.474571] ata9.00: failed to get Identify Device Data, Emask 0x40
>> [ 0.474572] ata9.00: ATA Identify Device Log not supported
>> [ 0.474573] ata9.00: Security Log not supported
>> [ 0.474576] ata9.00: failed to set xfermode (err_mask=0x40)
>> [ 0.493193] sched_clock: Marking stable (504159603, -10991650)->(615393192, -122225239)
>> [ 0.493768] registered taskstats version 1
>> [ 0.493770] Loading compiled-in X.509 certificates
>> [ 0.497894] Loaded X.509 cert 'Build time autogenerated kernel key: 4682756457c0b7b167f0b726943cf53ade93bd78'
>> [ 0.497984] zswap: loaded using pool lzo/zbud
>> [ 0.498237] kmemleak: Kernel memory leak detector initialized
>> [ 0.498243] kmemleak: Automatic memory scanning thread started
>> [ 0.506469] Key type big_key registered
>> [ 0.508864] Magic number: 11:580:189
>> [ 0.508914] acpi device:48: hash matches
>> [ 0.508922] acpi device:1b: hash matches
>> [ 0.509017] rtc_cmos 00:02: setting system clock to 2019-03-29T17:09:41 UTC (1553879381)
>> [ 0.509485] After kernel_init_freeable
>> [ 1.364358] tsc: Refined TSC clocksource calibration: 3499.982 MHz
>> [ 1.364370] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x32734013f67, max_idle_ns: 440795323134 ns
>> [ 1.364419] clocksource: Switched to clocksource tsc
>> [ 5.593141] ata9: SATA link up 6.0 Gbps (SStatus 133 SControl 0)
>> [ 5.593270] ata9.00: supports DRM functions and may not be fully accessible
>> [ 5.594006] ata9.00: supports DRM functions and may not be fully accessible
>> [ 5.594600] ata9.00: configured for UDMA/133
>> [ 5.595893] scsi 8:0:0:0: Direct-Access ATA CT1000MX500SSD4 020 PQ: 0 ANSI: 5
>> [ 5.596611] sd 8:0:0:0: [sda] 1953525168 512-byte logical blocks: (1.00 TB/932 GiB)
>> [ 5.596613] sd 8:0:0:0: [sda] 4096-byte physical blocks
>> [ 5.596626] sd 8:0:0:0: [sda] Write Protect is off
>> [ 5.596629] sd 8:0:0:0: [sda] Mode Sense: 00 3a 00 00
>> [ 5.596650] sd 8:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
>> [ 5.596837] sd 8:0:0:0: Attached scsi generic sg0 type 0
>> [ 5.597329] sda: sda1 sda2 sda3
>> [ 5.599079] sd 8:0:0:0: [sda] Attached SCSI disk
>
> This happens with all Linux kernel versions – tested since 4.14.
> Searching for this error on the Web, several people seem to be affected
> with different boards and drives [1].
>
> In a lot of those reports, I also see the message *Security Log not
> supported*.
>
> Do you have an idea, why this is only happening sometimes? Is it likely
> a drive firmware issue? As it affects several vendors, can Linux work
> around this problem (if it can be pinpointed)?
The first error seems to be `READ LOG DMA EXT failed, trying PIO`. The
code looks like below [2].
> retry:
> ata_tf_init(dev, &tf);
> if (dev->dma_mode && ata_id_has_read_log_dma_ext(dev->id) &&
> !(dev->horkage & ATA_HORKAGE_NO_DMA_LOG)) {
> tf.command = ATA_CMD_READ_LOG_DMA_EXT;
> tf.protocol = ATA_PROT_DMA;
> dma = true;
> } else {
> tf.command = ATA_CMD_READ_LOG_EXT;
> tf.protocol = ATA_PROT_PIO;
> dma = false;
> }
> tf.lbal = log;
> tf.lbam = page;
> tf.nsect = sectors;
> tf.hob_nsect = sectors >> 8;
> tf.flags |= ATA_TFLAG_ISADDR | ATA_TFLAG_LBA48 | ATA_TFLAG_DEVICE;
>
> err_mask = ata_exec_internal(dev, &tf, NULL, DMA_FROM_DEVICE,
> buf, sectors * ATA_SECT_SIZE, 0);
>
> if (err_mask && dma) {
> dev->horkage |= ATA_HORKAGE_NO_DMA_LOG;
> ata_dev_warn(dev, "READ LOG DMA EXT failed, trying PIO\n");
> goto retry;
> }
>
> DPRINTK("EXIT, err_mask=%x\n", err_mask);
> return err_mask;
So when trying PIO, that also seems to fail, and the error mask 0x40 is
propagated up.
> enum ata_completion_errors {
> AC_ERR_DEV = (1 << 0), /* device reported error */
> AC_ERR_HSM = (1 << 1), /* host state machine violation */
> AC_ERR_TIMEOUT = (1 << 2), /* timeout */
> AC_ERR_MEDIA = (1 << 3), /* media error */
> AC_ERR_ATA_BUS = (1 << 4), /* ATA bus error */
> AC_ERR_HOST_BUS = (1 << 5), /* host bus error */
> AC_ERR_SYSTEM = (1 << 6), /* system error */
> AC_ERR_INVALID = (1 << 7), /* invalid argument */
> AC_ERR_OTHER = (1 << 8), /* unknown */
> AC_ERR_NODEV_HINT = (1 << 9), /* polling device detection hint */
> AC_ERR_NCQ = (1 << 10), /* marker for offending NCQ qc */
> };
So 0x40 is AC_ERR_HOST_BUS, right? Any idea, what might cause this?
Would it be helpful to enable the debug messages?
#undef ATA_DEBUG /* debugging output */
Kind regards,
Paul
> [1]: https://bugzilla.kernel.org/show_bug.cgi?id=195895[2]:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/ata/libata-core.c?id=1daa0449d287a109b93c4516914eddeff4baff65#n2075
[3]:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/include/linux/libata.h?id=1daa0449d287a109b93c4516914eddeff4baff65#n508