SATA SSD Read Performance under TrueNAS vs CentOS | Windows

[Alex_K]

Hail all the Guru!

Building system with core specs as follows:

Supermicro X11DPi-N 8xIntel_1TB_Intel_S4510_SATA-SSD SAS3008 IT 16.00.12 5220R 512GB SATA-DOM 64GB
ESXi 7.03f
VM has 128GB , 8 Cores and SAS3008 is in passthrough mode

I'm in a confusing situation and ask for your advice

It all boils down to this:
[root@centostest ~]# dd if=/dev/sdb of=/dev/null bs=1M
181911158784 bytes (182 GB) copied, 322.139 s, 565 MB/s

root@freenas[~]# dd if=/dev/da1 of=/dev/null bs=1M
9805234176 bytes transferred in 26.474249 secs (370368737 bytes/sec)

I did a LOT of testing, some of them attached
FreeNAS 11.2, TrueNAS 12.0U8.1, TrueNAS 13.1 FreeBSD 14 - all the same ~350MB/sec
CentOS, Windows - 500+ MB/s each disk
hw.pci.honor_msi_blacklist=0/1 - no effect (but most tests made with it set to 0 so to make SR-IOV Intel X550-2 work)
pciPassthru1.msiEnabled="FALSE" - not used
/etc/vmware/passthru.map - not used
autotune enable vs virgin system - no effect on dd read speed


Secondary question - 2 of 8 SSD same model Same FW (updated - with old FW were no different) performs better (~430 MB/s). But that's really secondary and I have some idea as to why (2 SSD almost brand new (100%) other got lil wear (2%)).

But Why it reads slower under FreeBSD/TrueNAS? How to make it faster (as fast as in CentOS) and what it would take? Working at 2/3 of speed is very bad.

I will give more detail later. I got a LOT of detail.

 

[Alex_K]

And test results now it changed.
ESXi or hardware configuration did not change from earlier today

I reloaded TrueNAS 12.0U8.1 VM I started testing with (In-TrueNAS-Wide_short_tn12_orig-fw.txt)
VM's configuration did not change (only zpool was offline because other systems changed data on disks), however results are as follows:

root@TrueNAS-Wide[~]# dd if=/dev/da1 of=/dev/null bs=1M
15216934912 bytes transferred in 33.545648 secs (453618744 bytes/sec)

root@TrueNAS-Wide[~]# dd if=/dev/da5 of=/dev/null bs=1M
15879634944 bytes transferred in 33.056925 secs (480372420 bytes/sec)

No FreeBSD -based VMs shown this level of performance on this system yet
This level of performance persist after restart and zpool recreation

Its still slower then in CentOS but not as drastically.

For clarity, during the all the tests host had no other VMs running

 

[Alex_K]

Ok I haven't found out why the performance differ from Centos/Windows so much yet, but getting closer to 500MB/s were best I could get from FreeBSD and considered it satisfactory for now. Then this happen
Then during one more test (under TrueNAS 12.0U8.1)

Code:

root@TrueNAS-Wide[~]# ./solnet-array-test-v2.sh
...
Selected disks: da1 da6
<ATA INTEL SSDSC2KB96 0140>        at scbus3 target 0 lun 0 (pass2,da1)
<ATA INTEL SSDSC2KB96 0140>        at scbus3 target 5 lun 0 (pass7,da6)
                   Serial Parall % of
Disk    Disk Size  MB/sec MB/sec Serial
------- ---------- ------ ------ ------
da1       915715MB    442    491    111
da6       915715MB    448    496    111

I got this in /var/log/messages
Is this as bad as it looks? What is bad and what are the ways to fix that?

Code:

Aug 27 13:43:04 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 f6 b0 00 00 08 00 00 length 1048576 SMID 292 Command timeout on target 5(0x0010), 60000 set,
60.21080711 elapsed
Aug 27 13:43:04 TrueNAS-Wide mpr0: At enclosure level 0, slot 5, connector name (    )
Aug 27 13:43:04 TrueNAS-Wide mpr0: Sending abort to target 5 for SMID 292
Aug 27 13:43:04 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 f6 b0 00 00 08 00 00 length 1048576 SMID 292 Aborting command 0xfffffe0149c9fce0
Aug 27 13:43:04 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 c1 a8 00 00 08 00 00 length 1048576 SMID 208 Command timeout on target 5(0x0010), 60000 set,
60.21793731 elapsed
Aug 27 13:43:04 TrueNAS-Wide mpr0: At enclosure level 0, slot 5, connector name (    )
Aug 27 13:43:04 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 208 loginfo 31130000
Aug 27 13:43:04 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 2015 loginfo 31140000
Aug 27 13:43:04 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 2123 loginfo 31140000
Aug 27 13:43:04 TrueNAS-Wide mpr0: Finished abort recovery for target 5
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 f6 b0 00 00 08 00 00
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: Command timeout
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 c1 a8 00 00 08 00 00
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 ef 40 00 00 08 00 00
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 08 10 80 00 00 08 00 00
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 08 10 80 00 00 08 00 00
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: SCSI Status Error
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): SCSI status: Check Condition
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)
Aug 27 13:43:04 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command (per sense data)
Aug 27 13:44:06 TrueNAS-Wide    (da1:mpr0:0:0:0): READ(10). CDB: 28 00 03 6a e8 00 00 08 00 00 length 1048576 SMID 1270 Command timeout on target 0(0x000b), 60000 set, 60.12173521 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 0, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide mpr0: Sending abort to target 0 for SMID 1270
Aug 27 13:44:06 TrueNAS-Wide    (da1:mpr0:0:0:0): READ(10). CDB: 28 00 03 6a e8 00 00 08 00 00 length 1048576 SMID 1270 Aborting command 0xfffffe0149cf9950
Aug 27 13:44:06 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 f9 a8 00 00 08 00 00 length 1048576 SMID 1643 Command timeout on target 5(0x0010), 60000 set, 60.19629176 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 5, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide mpr0: Sending abort to target 5 for SMID 1643
Aug 27 13:44:06 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 f9 a8 00 00 08 00 00 length 1048576 SMID 1643 Aborting command 0xfffffe0149d1bd28
Aug 27 13:44:06 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 c4 a0 00 00 08 00 00 length 1048576 SMID 1612 Command timeout on target 5(0x0010), 60000 set, 60.19937840 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 5, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide    (da1:mpr0:0:0:0): READ(10). CDB: 28 00 08 43 10 00 00 08 00 00 length 1048576 SMID 1582 Command timeout on target 0(0x000b), 60000 set, 60.37233581 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 0, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide    (da1:mpr0:0:0:0): READ(10). CDB: 28 00 02 10 48 00 00 08 00 00 length 1048576 SMID 1563 Command timeout on target 0(0x000b), 60000 set, 60.37570143 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 0, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide    (da6:mpr0:0:5:0): SYNCHRONIZE CACHE(10). CDB: 35 00 00 00 00 00 00 00 00 00 length 0 SMID 1678 Command timeout on target 5(0x0010), 60000 set, 60.43302193 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 5, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide    (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 1f 48 00 00 08 00 00 length 1048576 SMID 1669 Command timeout on target 5(0x0010), 60000 set, 60.58231501 elapsed
Aug 27 13:44:06 TrueNAS-Wide mpr0: At enclosure level 0, slot 5, connector name (    )
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 0 SMID 1582 loginfo 31130000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 0 SMID 1563 loginfo 31130000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 0 SMID 1548 loginfo 31140000
Aug 27 13:44:06 TrueNAS-Wide mpr0: (da1:mpr0:0:0:0): READ(10). CDB: 28 00 03 6a e8 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide Finished abort recovery for target 0
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): CAM status: Command timeout
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): READ(10). CDB: 28 00 08 43 10 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): READ(10). CDB: 28 00 02 10 48 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): READ(10). CDB: 28 00 03 16 58 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 1669 loginfo 31130000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 1612 loginfo 31130000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 1678 loginfo 31130000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 1811 loginfo 31140000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 1738 loginfo 31140000
Aug 27 13:44:06 TrueNAS-Wide mpr0: Controller reported scsi ioc terminated tgt 5 SMID 1836 loginfo 31140000
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 1f 48 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide mpr0: (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 03 f9 a8 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide Finished abort recovery for target 5
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: Command timeout
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 c4 a0 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): SYNCHRONIZE CACHE(10). CDB: 35 00 00 00 00 00 00 00 00 00
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 0 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 09 6c 38 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 ee 38 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 02 49 28 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: CCB request completed with an error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command, 3 more tries remain
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): READ(10). CDB: 28 00 03 16 58 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): READ(10). CDB: 28 00 00 ee 38 00 00 08 00 00
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): CAM status: SCSI Status Error
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): SCSI status: Check Condition
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)
Aug 27 13:44:06 TrueNAS-Wide (da1:mpr0:0:0:0): Retrying command (per sense data)
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): CAM status: SCSI Status Error
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): SCSI status: Check Condition
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)
Aug 27 13:44:06 TrueNAS-Wide (da6:mpr0:0:5:0): Retrying command (per sense data)

I did not notice that log until I checked log files later.
Did another test today, with 3 disks, errors repeated for each of them.

Errors began ~5minutes into 2nd solnet's "initial parallel seek-stress array read"

~an hour into stress-test my SSH connection to this TrueNAS dropped. May not be related but ssh did not drop to ESXi and to another TrueNAS on another ESXi sitting next to this one. SSH did not drop during previous tests too.

Full 1st test log and corresponding part of /var/log/messages attached.

Appreciating any help/insight