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