SATA errors on iMX8QM with Linux 6.12

[Olivaw]

Hello, community!

We have a custom board based on i.mx8 QuadMax, and we use a Yocto BSP based on layers meta-imx and meta-freescale. On this board we have an SSD attached to one of the SATA/PCIe lanes, operating with 6.0 Gbps.

Recently we made a big jump of the NXP BSP version from 5.10.72_2.2.0 to 6.12.20_2.0.0, and with the new Kernel we started seeing SATA errors on some devices:

Spoiler

[    4.037121] ahci-imx 5f020000.sata: AHCI vers 0001.0301, 32 command slots, 6 Gbps, platform mode
[    4.047739] ahci-imx 5f020000.sata: 1/1 ports implemented (port mask 0x1)
[    4.054550] ahci-imx 5f020000.sata: flags: 64bit ncq sntf pm clo only pmp fbs pio slum part ccc sadm sds apst
[    4.082145] scsi host0: ahci-imx
[    4.085601] ata1: SATA max UDMA/133 mmio [mem 0x5f020000-0x5f02ffff] port 0x100 irq 510 lpm-pol 0
[    4.568137] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
...
[    4.592889] ata1.00: 234441648 sectors, multi 16: LBA48 NCQ (depth 32)
[    4.593161] ata1.00: configured for UDMA/133
...
[  588.609141] ata1.00: exception Emask 0x52 SAct 0x3000 SErr 0x200c00 action 0x6 frozen
[  588.620665] ata1.00: irq_stat 0x08000000, interface fatal error
[  588.626672] ata1: SError: { Proto HostInt BadCRC }
[  588.631561] ata1.00: failed command: READ FPDMA QUEUED
[  588.640406] ata1.00: cmd 60/08:60:d8:47:f9/00:00:0d:00:00/40 tag 12 ncq dma 4096 in
[  588.640406]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x52 (ATA bus error)
[  588.658886] ata1.00: status: { DRDY }
[  588.662599] ata1.00: failed command: READ FPDMA QUEUED
[  588.671398] ata1.00: cmd 60/10:68:e8:47:f9/00:00:0d:00:00/40 tag 13 ncq dma 8192 in
[  588.671398]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x52 (ATA bus error)
[  588.687117] ata1.00: status: { DRDY }
[  588.690805] ata1: hard resetting link
[  589.161130] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  589.167972] ata1.00: configured for UDMA/133
[  589.172904] sd 0:0:0:0: [sda] tag#12 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[  589.182636] sd 0:0:0:0: [sda] tag#12 Sense Key : 0x5 [current]
[  589.188577] sd 0:0:0:0: [sda] tag#12 ASC=0x21 ASCQ=0x4
[  589.193853] sd 0:0:0:0: [sda] tag#12 CDB: opcode=0x28 28 00 0d f9 47 d8 00 00 08 00
[  589.201552] I/O error, dev sda, sector 234440664 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[  589.214422] sd 0:0:0:0: [sda] tag#13 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[  589.224127] sd 0:0:0:0: [sda] tag#13 Sense Key : 0x5 [current]
[  589.233725] sd 0:0:0:0: [sda] tag#13 ASC=0x21 ASCQ=0x4
[  589.238996] sd 0:0:0:0: [sda] tag#13 CDB: opcode=0x28 28 00 0d f9 47 e8 00 00 10 00
[  589.246675] I/O error, dev sda, sector 234440680 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[  589.255890] ata1: EH complete​

The SATA errors are logged when the SSD is accessed, in about 10% of boot sessions. Also, not every access leads to the error, and on most devices the errors don't appear at all.

The issue persists when we further upgrade the BSP to release 6.12.34-2.1.0. The Kernel 6.6.52-2.2.0 also shows the symptom.

Did anyone see a similar symptom on their system, and maybe even found a solution for this?

We are thankful for any suggestions.

[Olivaw]

Hello Aldo! Thanks for your response

We did try "noncq" earlier without success, now I also added "nodma". The problem persists, unfortunately:

Spoiler

[ 4.110570] ahci-imx 5f020000.sata: flags: 64bit ncq sntf pm clo only pmp fbs pio slum part ccc sadm sds apst 
[ 4.121464] scsi host0: ahci-imx
[ 4.124941] ata1: SATA max UDMA/133 mmio [mem 0x5f020000-0x5f02ffff] port 0x100 irq 510 lpm-pol 0
...
[ 4.599797] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 4.606509] ata1.00: FORCE: modified (noncq)
[ 4.606516] ata1.00: FORCE: modified (nodma)
[ 4.606527] ata1.00: ATA-9: M.2 (S42) 3TE7, S22921, max UDMA/133
[ 4.612123] pci_bus 0000:01: resource 1 [mem 0x72000000-0x721fffff]
[ 4.618386] ata1.00: 234441648 sectors, multi 16: LBA48 NCQ (not used)
[ 4.618405] ata1.00: device does not support DMA, disabling DMA
[ 4.628979] ata1.00: configured for PIO4
...
[ 100.111610] ata1.00: exception Emask 0x52 SAct 0x0 SErr 0x400d00 action 0x6 frozen
[ 100.122993] ata1.00: irq_stat 0x08000000, interface fatal error
[ 100.128961] ata1: SError: { UnrecovData Proto HostInt Handshk }
[ 100.134944] ata1.00: failed command: WRITE MULTIPLE
[ 100.139853] ata1.00: cmd c5/00:08:58:08:00/00:00:00:00:00/e0 tag 12 pio 4096 out
[ 100.139853] res 50/00:08:08:09:81/00:00:00:00:00/ea Emask 0x52 (ATA bus error)
[ 100.155321] ata1.00: status: { DRDY }
[ 100.159056] ata1: hard resetting link
[ 100.635608] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 100.645314] ata1.00: device does not support DMA, disabling DMA
[ 100.651637] ata1.00: configured for PIO4
[ 100.655695] ata1: EH complete
[ 100.715250] ata1.00: exception Emask 0x52 SAct 0x0 SErr 0x400d00 action 0x6 frozen
[ 100.722875] ata1.00: irq_stat 0x08000000, interface fatal error
[ 100.728839] ata1: SError: { UnrecovData Proto HostInt Handshk }
[ 100.735646] ata1.00: failed command: WRITE MULTIPLE
[ 100.740906] ata1.00: cmd c5/00:08:78:29:00/00:00:00:00:00/e0 tag 11 pio 4096 out
[ 100.740906] res 50/00:0c:00:00:00/00:00:00:00:00/a0 Emask 0x52 (ATA bus error)
[ 100.756959] ata1.00: status: { DRDY }
[ 100.760758] ata1: hard resetting link
[ 101.231617] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[ 101.239116] ata1.00: device does not support DMA, disabling DMA
[ 101.245398] ata1.00: configured for PIO4
[ 101.249637] ata1: EH complete
...
# dd if=/dev/sda1 of=/dev/null bs=1M count=500 status=progres

[  149.324058] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  149.330650] ata1.00: device does not support DMA, disabling DMA
[  149.338353] ata1.00: configured for PIO4

57671680 bytes (58 MB, 55 MiB) copied, 1 s, 57.5 MB/s
179306496 bytes (179 MB, 171 MiB) copied, 2 s, 89.5 MB/s

[  151.505052] ata1: limiting SATA link speed to 3.0 Gbps
[  151.975579] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[  151.983099] ata1.00: device does not support DMA, disabling DMA
[  151.991499] ata1.00: configured for PIO4

263192576 bytes (263 MB, 251 MiB) copied, 3 s, 82.6 MB/s
342884352 bytes (343 MB, 327 MiB) copied, 4 s, 85.5 MB/s
443547648 bytes (444 MB, 423 MiB) copied, 5 s, 88.5 MB/s
500+0 records in
500+0 records out

With setting noncq and nodma, the read speed has dropped from about 250MB/s to 85 MB/s but the errors on ata1 still occur.

[AldoG]

Hello,

Thank you for trying, I see a differnet error on the last test so I will investigate, during so could you try with a different cable/connector?
Also, regarding the drop in speed it is spected since without DMA it would be slower, I wanted to see if this was the actual issue.

Best regards/Saludos,
Aldo.

[Olivaw]

Thanks for sticking to this thread, @AldoG! 

I cannot test a different cable because the SSD is attached via an M.2 connector that carries the SATA signals.

There is a hardware dependency though: we know that not every board is equally affected. Some show the symptom less frequently, some don't at all, but all boards that do show the symptom work fine with Kernel from the 5.10.72_2.2.0 BSP release.

We tried replacing the SSD on affected boards, and the issue persists there.

[AldoG]

Hello,

I understand thank you for sharing, then could you please try by checking the Power rails?
Try to Scope the SSD supply during sustained reads
Also, please re enable DMA and try reducing the link speed for a test, this by sending the kernel parameter:

libata.force=3.0G

Please try it and let me know of your results<
Best regards/Saludos,
Aldo.

[Olivaw]

Thanks for the suggestion, @AldoG!

Unfortunately, setting "libata.force=3.0G" does not eliminate the symptom:

[    4.145416] scsi host0: ahci-imx
[    4.148867] ata1: FORCE: PHY spd limit set to 3.0Gbps
[    4.153930] ata1: SATA max UDMA/133 mmio [mem 0x5f020000-0x5f02ffff] port 0x100 irq 510 lpm-pol 0
// ...
[    4.628203] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
// ...
[   89.900251] ata1.00: exception Emask 0x12 SAct 0x100 SErr 0x400500 action 0x6 frozen
[   89.908965] ata1.00: irq_stat 0x08000000, interface fatal error
[   89.915563] ata1: SError: { UnrecovData Proto Handshk }
[   89.921264] ata1.00: failed command: WRITE FPDMA QUEUED
[   89.926649] ata1.00: cmd 61/50:40:00:48:c5/00:00:06:00:00/40 tag 8 ncq dma 40960 out
[   89.926649]          res 40/00:01:01:4f:c2/00:00:00:00:00/00 Emask 0x12 (ATA bus error)
[   89.942665] ata1.00: status: { DRDY }
[   89.946535] ata1: hard resetting link
[   90.416176] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[   90.423350] ata1.00: configured for UDMA/133
[   90.427751] ata1: EH complete

 Sometimes we also see automatic reduction of speed, which does not help though:

[   90.476233] ata1: limiting SATA link speed to 1.5 Gbps
[   90.481466] ata1.00: exception Emask 0x12 SAct 0x1000 SErr 0x400500 action 0x6 frozen
[   90.489382] ata1.00: irq_stat 0x08000000, interface fatal error
[   90.495367] ata1: SError: { UnrecovData Proto Handshk }
[   90.500708] ata1.00: failed command: WRITE FPDMA QUEUED
[   90.505977] ata1.00: cmd 61/50:60:00:48:c5/00:00:06:00:00/40 tag 12 ncq dma 40960 out
[   90.505977]          res 41/84:01:06:4f:c2/00:00:00:00:00/00 Emask 0x12 (ATA bus error)
[   90.521892] ata1.00: status: { DRDY ERR }
[   90.525954] ata1.00: error: { ICRC ABRT }
[   90.530002] ata1: hard resetting link
[   91.000176] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[   91.007078] ata1.00: configured for UDMA/133
[   91.011575] ata1: EH complete

Best regards

Olivaw

[Olivaw]

Hello again!

Unfortunately it was not possible for me to do the power rail measurements.

However, our board manufacturer did some quick eye pattern measurements on the TX signal line (CPU to SSD) of an affected board. I have attached the images to this post.

We see that the vertical eye opening reduces visibly when transitioning from 5.4 to 6.12 (these are the two versions that they had at hand). 

 

When looking at the Kernel source code (linux-imx), we see that in a relatively recent driver architecture rework, some SATA PHY settings were removed in one place (ahci_imx) [1] but not added in the other (imx8qm-hsio) [2].

Can this be the reason?

Best regards

Olivaw

[1] https://github.com/nxp-imx/linux-imx/commit/4147e9d2408aab6df9315900f18f4142ca6e7c3f

[2] https://github.com/nxp-imx/linux-imx/commit/82c56b6dd24fcdf811f2b47b72e5585c8a79b685

[Olivaw]

Hello, community!

In the meantime I got contacted by an NXP FAE, a colleague of @AldoG but we did not receive much support so far, unfortunately.

We see that the same hardware shows errors with Kernel 6.x, and _not_ with Kernel 5.10. Therefore we are sure that the issue can be solved in software.

We started reverse-engineering the driver, hoping to find a workaround.
So far, we did not have success, but we saw that the errors disappear if we disable the PCIe lane that is usually active in addition to the SATA lane (we have fsl,hsio-cfg = "pciea-pcieb-sata", and use the pcieb lane along with SATA).

Our conclusion is that there seems to be an interference:

• either from the PCIe driver pci-imx6.c accessing one of the three PHYs, and thus corrupting the SATA line calibration
• or from the PCIe traffic somehow influencing the SATA signal integrity

We initially guessed that there might be a race condition between the two drivers simultaneously accessing the PHY registers (`phy-fsl-imx8qm-hsio.c`). This was not confirmed because the errors persisted also after configuring the PCIe driver as `late_initcall()`, thus starting it after SATA calibration is completed.

Would be great to hear an opinion from NXP who have authored the drivers and should have a better idea about the reason for the errors.

Best regards

Olivaw

[AldoG]

Hello,

Could you try with the following kernel parameter:
libata.force=noncq, nodma

This would disable NCQ and DMA, lets see if this does help.

Best regards/Saludos,
Aldo.