AHCI Timeouts in Kernel Log

[Franiac]

Hello everyone,

I have built myself two identical FreeNAS machines with the following hardware (I think the Delock 89384 is the issue here):

Board: ASRock J4015M
RAM: G.Skill Value 2400Mhz
SATA-Controller: Delock 89384 with ASM1061 Chip
HDDs: 6x 3000GB WD Red WD30EFRX Intellipower

The machines run without issues. One clones to the other via periodic snapshots and replication tasks.

But every night at 3 AM I get an email from both machines containing the following kernel log messages:

Code:

> ahcich2: Timeout on slot 24 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 01000000 tfd 50 serr 00000000 cmd 0004cc17
> ahcich2: Timeout on slot 22 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00400000 tfd 50 serr 00000000 cmd 0004cd17
> ahcich6: Timeout on slot 13 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00002000 tfd 50 serr 00000000 cmd 0004c617
> ahcich6: Timeout on slot 19 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00080000 tfd 50 serr 00000000 cmd 0004d317
> ahcich2: Timeout on slot 23 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00800000 tfd 50 serr 00000000 cmd 0004cb17
> ahcich2: Timeout on slot 25 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 02000000 tfd 50 serr 00000000 cmd 0004d317
> ahcich2: Timeout on slot 13 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00002000 tfd 50 serr 00000000 cmd 0004ce17
> ahcich2: Timeout on slot 10 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000400 tfd 50 serr 00000000 cmd 0004d117
> ahcich6: Timeout on slot 27 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 08000000 tfd 50 serr 00000000 cmd 0004d817
> ahcich2: Timeout on slot 23 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00800000 tfd 50 serr 00000000 cmd 0004d917
> ahcich2: Timeout on slot 18 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00040000 tfd 50 serr 00000000 cmd 0004cf17
> ahcich2: Timeout on slot 18 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00040000 tfd 50 serr 00000000 cmd 0004d517
> ahcich2: Timeout on slot 27 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 08000000 tfd 50 serr 00000000 cmd 0004c517
> ahcich6: Timeout on slot 14 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00004000 tfd 50 serr 00000000 cmd 0004d317
> ahcich6: Timeout on slot 11 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00000800 tfd 50 serr 00000000 cmd 0004c417
> ahcich2: Timeout on slot 0 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000001 tfd 50 serr 00000000 cmd 0004d417
> ahcich7: Timeout on slot 21 port 0
> ahcich7: is 00000000 cs 00000000 ss 00000000 rs 00200000 tfd 50 serr 00000000 cmd 0004cd17
> ahcich2: Timeout on slot 23 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00800000 tfd 50 serr 00000000 cmd 0004cd17
> ahcich2: AHCI reset: device not ready after 31000ms (tfd = 0000ff80)
> ahcich2: Timeout on slot 7 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000080 tfd 50 serr 00000000 cmd 0004c817
> ahcich7: Timeout on slot 31 port 0
> ahcich7: is 00000000 cs 00000000 ss 00000000 rs 80000000 tfd 50 serr 00000000 cmd 0004d117
> ahcich2: Timeout on slot 22 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00400000 tfd 50 serr 00000000 cmd 0004d417
> ahcich2: Timeout on slot 9 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000200 tfd 50 serr 00000000 cmd 0004dc17
> ahcich2: Timeout on slot 27 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 08000000 tfd 50 serr 00000000 cmd 0004da17
> ahcich2: Timeout on slot 12 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00001000 tfd 50 serr 00000000 cmd 0004cc17
> ahcich6: Timeout on slot 5 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00000020 tfd 50 serr 00000000 cmd 0004d917
> ahcich6: Timeout on slot 28 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 10000000 tfd 50 serr 00000000 cmd 0004ca17
> ahcich2: Timeout on slot 25 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 02000000 tfd 50 serr 00000000 cmd 0004da17
> ahcich6: Timeout on slot 16 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00010000 tfd 50 serr 00000000 cmd 0004c817
> ahcich2: Timeout on slot 12 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00001000 tfd 50 serr 00000000 cmd 0004dc17
> ahcich2: Timeout on slot 28 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 10000000 tfd 50 serr 00000000 cmd 0004cb17
> ahcich6: Timeout on slot 20 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00100000 tfd 50 serr 00000000 cmd 0004d417
> ahcich2: Timeout on slot 11 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000800 tfd 50 serr 00000000 cmd 0004c317
> ahcich2: Timeout on slot 4 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000010 tfd 50 serr 00000000 cmd 0004c517
> ahcich6: Timeout on slot 16 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00010000 tfd 50 serr 00000000 cmd 0004c717
> ahcich2: Timeout on slot 17 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00020000 tfd 50 serr 00000000 cmd 0004c817
> ahcich2: Timeout on slot 9 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000200 tfd 50 serr 00000000 cmd 0004d717
> ahcich2: Timeout on slot 25 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 02000000 tfd 50 serr 00000000 cmd 0004d517
> ahcich6: Timeout on slot 14 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00004000 tfd 50 serr 00000000 cmd 0004c617
> ahcich2: Timeout on slot 9 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000200 tfd 50 serr 00000000 cmd 0004d817
> ahcich2: Timeout on slot 26 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 04000000 tfd 50 serr 00000000 cmd 0004c417
> ahcich2: Timeout on slot 20 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00100000 tfd 50 serr 00000000 cmd 0004c117
> ahcich2: Timeout on slot 4 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000010 tfd 50 serr 00000000 cmd 0004df17
> ahcich2: Timeout on slot 27 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 08000000 tfd 50 serr 00000000 cmd 0004c817
> ahcich6: Timeout on slot 15 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00008000 tfd 50 serr 00000000 cmd 0004c717
> ahcich6: Timeout on slot 24 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 01000000 tfd 50 serr 00000000 cmd 0004c817
> ahcich7: Timeout on slot 14 port 0
> ahcich7: is 00000000 cs 00000000 ss 00000000 rs 00004000 tfd 50 serr 00000000 cmd 0004c817
> ahcich2: Timeout on slot 18 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00040000 tfd 50 serr 00000000 cmd 0004d017
> ahcich2: Timeout on slot 27 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 08000000 tfd 50 serr 00000000 cmd 0004de17
> ahcich2: Timeout on slot 1 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000002 tfd 50 serr 00000000 cmd 0004ca17
> ahcich2: Timeout on slot 26 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 04000000 tfd 50 serr 00000000 cmd 0004dd17
> ahcich2: Timeout on slot 14 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00004000 tfd 50 serr 00000000 cmd 0004cd17
> ahcich6: Timeout on slot 23 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00800000 tfd 50 serr 00000000 cmd 0004d217
> ahcich2: Timeout on slot 27 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 08000000 tfd 50 serr 00000000 cmd 0004ca17
> ahcich2: Timeout on slot 5 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000020 tfd 50 serr 00000000 cmd 0004d117
> ahcich2: Timeout on slot 20 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00100000 tfd 50 serr 00000000 cmd 0004cf17
> ahcich2: Timeout on slot 21 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00200000 tfd 50 serr 00000000 cmd 0004c517
> ahcich2: Timeout on slot 7 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000080 tfd 50 serr 00000000 cmd 0004ca17
> ahcich6: Timeout on slot 8 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00000100 tfd 50 serr 00000000 cmd 0004ca17
> ahcich2: Timeout on slot 1 port 0
> ahcich2: is 00000000 cs 00000000 ss 00000000 rs 00000002 tfd 50 serr 00000000 cmd 0004dd17
> ahcich6: Timeout on slot 23 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00800000 tfd 50 serr 00000000 cmd 0004c617
> ahcich6: Timeout on slot 7 port 0
> ahcich6: is 00000000 cs 00000000 ss 00000000 rs 00000080 tfd 50 serr 00000000 cmd 0004d417

I tried to research a little bit and stumbled upon the following thread:

https://forums.freenas.org/index.ph...s-problem-with-asm1062-sata-controller.49406/

The messages look different though but I suppose I am not the only one working with the Delock controller and in addition to that the above issue has been fixed.

I really don't have any issues with the machines, everything just works and the speed is awesome, but the log messages worry me a little bit.

Does anyone know what the log messages mean or even how to get rid of them?

Any help is greatly appreciated!

~ Franiac

 

[dlavigne]

Did you find the underlying cause?

 

[Franiac]

No, still getting the messages daily.

What I encoutered is when I access the mapped network drive (SMB share) in Explorer on Windows 10, maybe once in two days the Explorer hangs for 10s and then continues to work. Could be something caused by the above log messages. But I definitely have no consistency or corrupt file issues.

 

[dlavigne]

/var/log/messages will have timestamps for those errors so you can determine how often the messages occur and if the system is under load during that time.

 

[Franiac]

Thx for the hint.

I get the logs once or twice per hour. It is definitely not dependent on load since even at 4 AM (where nothing accesses the NAS) the messages are still there. And also I cannot see any connection to the periodic snapshots (every 2 hours).

I did 3 things now:

1. Disabled S.M.A.R.T. for all drives
2. Set the "Advanced Power Management" to "DISABLED" for every disk (was set to 128... maybe that's the issue)
3. Set the periodic snapshots to every 6 hours instead of 2

This way I can see if the messages maybe get less or disappear completely.

Do you know of any PCIe HBA with 6+ SATA connectors other than the Delock one? I cannot find one.

 

[Franiac]

I can confirm that the messages disappered completely after my recent changes.

I am going to set the periodic snapshot time to 2 hours again and enable S.M.A.R.T.

The issue probably was the Advanced Power Management setting on the disks.

 

[Franiac]

I finally got it. S.M.A.R.T. is the issue!

I disabled SMART on all 6 drives on both machines and there are no more ahci timeout messages in the log.

I didn't have SMART tasks enabled. Even the SMART service was not running. I don't get it, but SMART is questionable anyway, so....

 

[Ghwomb]

Thanks a lot for writing this. I am thinking about buying a DeLock 89384 and it seems to work fine as long as SMART is not enabled. If I read these posts correct.