Numerous log errors when copying large amounts of data (Freenas 8.2, LSI SAS9211-8i)

[jafin]

Hardware:
Intel 1200BT Motherboard
LSI SAS9211-8i P14 bios
Intel (RES2SV240) expander
Hard disks mixture of WD RED 3TB WD30EFRX and Samsung HD204UI 2TB Drives

When I copy from the shell I seem to populate the log with a large amount of errors.
Noticeably a timeout appears to occur, or something drops out/resets and then resumes after about 10 seconds.
Any clues as to what might be wrong?

Heres a extract of the log.

Code:

Aug 24 00:30:47 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 417
Aug 24 00:30:47 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 417 complete
Aug 24 00:30:47 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 798
Aug 24 00:30:47 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 798 complete
Aug 24 00:30:47 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 638
Aug 24 00:30:47 freenas kernel: mps0: (0:6:0) terminated ioc 804b scsi 0 state c xfer 0
Aug 24 00:30:47 freenas last message repeated 17 times
Aug 24 00:30:47 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 638 complete
Aug 24 00:30:47 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 881
Aug 24 00:30:47 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 881 complete
Aug 24 00:30:47 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 440
Aug 24 00:30:47 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 440 complete
Aug 24 00:30:47 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 874
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 874 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 546
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 546 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 209
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 209 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 114
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 114 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 299
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 299 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 190
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 190 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 305
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 305 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 662
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 662 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 919
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 919 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 399
Aug 24 00:30:48 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 399 complete
Aug 24 00:30:48 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 334
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 334 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 213
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 213 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 297
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 297 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 689
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 689 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 387
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 387 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 558
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 558 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 81
Aug 24 00:30:49 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 81 complete
Aug 24 00:30:49 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 890
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 890 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 364
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 364 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 319
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 319 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 743
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 743 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 1004
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 1004 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 557
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 557 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 487
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 487 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0c SMID 993
Aug 24 00:30:50 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0c SMID 993 complete
Aug 24 00:30:50 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 838
Aug 24 00:30:51 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 838 complete
Aug 24 00:30:51 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 606
Aug 24 00:30:51 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 606 complete
Aug 24 00:30:51 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 749
Aug 24 00:30:51 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 749 complete
Aug 24 00:30:51 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0e SMID 178
Aug 24 00:30:51 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0e SMID 178 complete
Aug 24 00:30:51 freenas kernel: (da2:mps0:0:6:0): READ(10). CDB: 28 0 b1 b6 ff 28 0 0 68 0 
Aug 24 00:30:51 freenas kernel: (da2:mps0:0:6:0): CAM status: SCSI Status Error
Aug 24 00:30:51 freenas kernel: (da2:mps0:0:6:0): SCSI status: Check Condition
Aug 24 00:30:51 freenas kernel: (da2:mps0:0:6:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)
Aug 24 00:30:51 freenas kernel: (da4:mps0:0:8:0): READ(10). CDB: 28 0 b1 b6 f6 60 0 0 68 0 
Aug 24 00:30:51 freenas kernel: (da4:mps0:0:8:0): CAM status: SCSI Status Error
Aug 24 00:30:51 freenas kernel: (da4:mps0:0:8:0): SCSI status: Check Condition
Aug 24 00:30:51 freenas kernel: (da4:mps0:0:8:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 84
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 827
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 820
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 101
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 315
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 154
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 287
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 798
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 138
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 400
Aug 24 00:32:09 freenas kernel: (da3:mps0:0:7:0): SCSI command timeout on device handle 0x000d SMID 9
Aug 24 00:32:10 freenas kernel: mps0: (0:7:0) terminated ioc 804b scsi 0 state c xfer 0
Aug 24 00:32:10 freenas last message repeated 9 times
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 84 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 827
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 827 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 820
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 820 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 101
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 101 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 315
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 315 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 154
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 154 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 287
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 287 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 798
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 798 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 138
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 138 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 400
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 400 complete
Aug 24 00:32:10 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x0d SMID 9
Aug 24 00:32:10 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x0d SMID 9 complete
Aug 24 00:32:11 freenas kernel: (da3:mps0:0:7:0): READ(10). CDB: 28 0 b1 bb 8b 58 0 0 80 0 
Aug 24 00:32:11 freenas kernel: (da3:mps0:0:7:0): CAM status: SCSI Status Error
Aug 24 00:32:11 freenas kernel: (da3:mps0:0:7:0): SCSI status: Check Condition
Aug 24 00:32:11 freenas kernel: (da3:mps0:0:7:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)


Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 827 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 7
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 7 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 457
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 457 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 439
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 439 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 170
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 170 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 861
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 861 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 782
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 782 complete
Aug 24 00:37:14 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x13 SMID 1006
Aug 24 00:37:14 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x13 SMID 1006 complete
Aug 24 00:37:14 freenas kernel: (da9:mps0:0:13:0): READ(10). CDB: 28 0 c4 63 6c e0 0 0 80 0 
Aug 24 00:37:14 freenas kernel: (da9:mps0:0:13:0): CAM status: SCSI Status Error
Aug 24 00:37:14 freenas kernel: (da9:mps0:0:13:0): SCSI status: Check Condition
Aug 24 00:37:14 freenas kernel: (da9:mps0:0:13:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)
Aug 24 00:45:37 freenas kernel: (da7:mps0:0:11:0): SCSI command timeout on device handle 0x0011 SMID 114
Aug 24 00:45:37 freenas kernel: (da7:mps0:0:11:0): SCSI command timeout on device handle 0x0011 SMID 515
Aug 24 00:45:37 freenas kernel: mps0: (0:11:0) terminated ioc 804b scsi 0 state c xfer 0
Aug 24 00:45:37 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x11 SMID 114 complete
Aug 24 00:45:37 freenas kernel: mps0: mpssas_complete_tm_request: sending deferred task management request for handle 0x11 SMID 515
Aug 24 00:45:37 freenas kernel: mps0: mpssas_abort_complete: abort request on handle 0x11 SMID 515 complete
Aug 24 00:45:38 freenas kernel: (da7:mps0:0:11:0): READ(10). CDB: 28 0 b1 b3 5c e0 0 0 20 0 
Aug 24 00:45:38 freenas kernel: (da7:mps0:0:11:0): CAM status: SCSI Status Error
Aug 24 00:45:38 freenas kernel: (da7:mps0:0:11:0): SCSI status: Check Condition
Aug 24 00:45:38 freenas kernel: (da7:mps0:0:11:0): SCSI sense: UNIT ATTENTION asc:29,0 (Power on, reset, or bus device reset occurred)

and camcontrol devlist

Code:

<ATA SAMSUNG HD204UI 0001>         at scbus0 target 4 lun 0 (pass0,da0)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 5 lun 0 (pass1,da1)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 6 lun 0 (pass2,da2)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 7 lun 0 (pass3,da3)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 8 lun 0 (pass4,da4)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 9 lun 0 (pass5,da5)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 10 lun 0 (pass6,da6)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 11 lun 0 (pass7,da7)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 12 lun 0 (pass8,da8)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 13 lun 0 (pass9,da9)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 14 lun 0 (pass10,da10)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 15 lun 0 (pass11,da11)
<ATA WDC WD30EFRX-68A 0A80>        at scbus0 target 16 lun 0 (pass12,da12)
<ATA WDC WD30EFRX-68A 0A80>        at scbus0 target 17 lun 0 (pass13,da13)
<ATA WDC WD30EFRX-68A 0A80>        at scbus0 target 18 lun 0 (pass14,da14)
<ATA WDC WD30EFRX-68A 0A80>        at scbus0 target 19 lun 0 (pass15,da15)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 20 lun 0 (pass16,da16)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 21 lun 0 (pass17,da17)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 22 lun 0 (pass18,da18)
<ATA SAMSUNG HD204UI 0001>         at scbus0 target 23 lun 0 (pass19,da19)
<Intel RES2SV240 0b00>             at scbus0 target 24 lun 0 (pass20,ses0)
<WDC WD30EFRX-68AX9N0 80.00A80>    at scbus5 target 0 lun 0 (pass21,ada0)
<WDC WD30EFRX-68AX9N0 80.00A80>    at scbus6 target 0 lun 0 (pass22,ada1)
<Imation ImationFlashDriv PMAP>    at scbus7 target 0 lun 0 (pass23,da20)

I found another article suggesting adding the following tunables may help (http://forums.freebsd.org/showthread.php?t=27128):

Code:

vfs.zfs.vdev.min_pending="1"
vfs.zfs.vdev.max_pending="1"

It did not seem to make any change in my instance.


EDIT
Fingers Crossed, Applying firmware V13 to the Intel RES2SV240 Expander has stopped the errors at this point being logged. Copied over 3TB of data sofar without error.

 

[mattymuc]

hi jafin,

thank you very much for the tip with the firmware v13 update for the Intel RES2SV240. I had so many timeouts/resets that my system was unusable. It worked for max. 10 seconds and then the next drive had a timeout... After the firmware update everything runs perfect!