Storagespaces: CRC Errors on initiator

qwertz · Tue May 06, 2014 1:11 am

Hi there,
I'm currently trying Starwind8 iSCSI RC2(Version 8.0.6694 it says) on a Windows Server 2012 R2.
I've previously used a Starwind8 RC1 (i guess) and I've recently upgraded to the new RC2.
The Targets / Devices which I created with the old version seem to work.(Though I didn't test much, just had a look inside the folder structure)

But when I tried to add a new target and connect to it, I'm getting CRC-Errors on the Initiator side.
The issue is similar to the issue described by barrysmoke in his thread:
http://www.starwindsoftware.com/forums/ ... t3530.html

I've created a Harddisk Device , created a virtualdisk, set the size to 512 GB and the sector size to 512 b and it's thick provisioned.
The file is stored on a tiered StorageSpace, hope this is not a problem?(The "old" and working Devices and Targets are not on a StorageSpace.)
Device Info looks like this:

: Imagefile; Device_info.png (5.96 KiB) Viewed 36925 times

On the initiator side(also win2k12 r2) I can connect to the target, and it shows up in disk manager but as soon as i try to initialize the "drive" with either mbr or gpt it fails with crc error.
Looks like this:

: Initialization_Fails; Disk_Manager.png (8.32 KiB) Viewed 36926 times

Here is what is in the logs on the starwind server:

Code: Select all

5/6 1:22:15.441 b60 Srv: Accepted iSCSI connection from 172.17.100.100:49170 to 172.17.100.99:3260. (Id = 0xc)
5/6 1:22:15.441 b60 C[c], FREE: Event - CONNECTED.
5/6 1:22:15.441 b60 C[c], XPT_UP: T3.
5/6 1:22:15.441 67c C[c], XPT_UP: Login request: ISID 0x400001370000, TSIH 0x0000.
5/6 1:22:15.441 67c C[c], XPT_UP: Event - LOGIN.
5/6 1:22:15.441 67c C[c], IN_LOGIN: T4.
5/6 1:22:15.441 67c Params: <<< String param 'InitiatorName': received 'iqn.1991-05.com.microsoft:myhost.mydomain', accepted 'iqn.1991-05.com.microsoft:myhost.mydomain'
5/6 1:22:15.441 67c Params: <<< Enum param 'SessionType': received 'Discovery', accepted 'Discovery'
5/6 1:22:15.441 67c Params: <<< Enum param 'AuthMethod': received 'None', accepted 'None'
5/6 1:22:15.441 67c Params: <<< Enum param 'AuthMethod': received 'None', accepted 'None'
5/6 1:22:15.441 67c Params: >>> AuthMethod=None.
5/6 1:22:15.441 e2c T[c,1]: session 0xc, connection 0xc : end of stage 0, next stage 1.
5/6 1:22:15.441 67c Params: <<< Enum param 'HeaderDigest': received 'None,CRC32C', accepted 'None'
5/6 1:22:15.441 67c Params: <<< Enum param 'DataDigest': received 'None,CRC32C', accepted 'None'
5/6 1:22:15.441 67c Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 65536, accepted 65536
5/6 1:22:15.441 67c Params: <<< Numeric param 'DefaultTime2Wait': received 0, accepted 2
5/6 1:22:15.441 67c Params: <<< Numeric param 'DefaultTime2Retain': received 60, accepted 20
5/6 1:22:15.441 67c Params: >>> HeaderDigest=None.
5/6 1:22:15.441 67c Params: >>> DataDigest=None.
5/6 1:22:15.441 67c Params: >>> MaxRecvDataSegmentLength=8192.
5/6 1:22:15.441 67c Params: >>> DefaultTime2Wait=2.
5/6 1:22:15.441 67c Params: >>> DefaultTime2Retain=20.
5/6 1:22:15.441 e2c T[c,1]: session 0xc, connection 0xc : end of stage 1, next stage 3.
5/6 1:22:15.441 e2c C[c], IN_LOGIN: Event - LOGIN_ACCEPT.
5/6 1:22:15.441 e2c C[c], LIN: T5.
5/6 1:22:15.441 67c Params: <<< String param 'SendTargets': received 'All', accepted 'All'
5/6 1:22:15.441 67c Srv: <no target>: 'SendTargets=All' for a Discovery session...
5/6 1:22:15.441 e2c C[c], LIN: Event - LOGOUT.
5/6 1:22:15.441 e2c C[c], IN_LOGOUT: T9/10.
5/6 1:22:15.441 f54 C[c], IN_LOGOUT: Event - LOGOUT_ACCEPT.
5/6 1:22:15.441 f54 C[c], FREE: T13.
5/6 1:22:15.441 67c C[c], FREE: recvData returned 10058
5/6 1:22:35.389 b60 Srv: Accepted iSCSI connection from 172.17.100.100:49171 to 172.17.100.99:3260. (Id = 0xd)
5/6 1:22:35.389 b60 C[d], FREE: Event - CONNECTED.
5/6 1:22:35.389 b60 C[d], XPT_UP: T3.
5/6 1:22:35.389 e20 C[d], XPT_UP: Login request: ISID 0x400001370000, TSIH 0x0000.
5/6 1:22:35.389 e20 C[d], XPT_UP: Event - LOGIN.
5/6 1:22:35.389 e20 C[d], IN_LOGIN: T4.
5/6 1:22:35.389 e20 Params: <<< String param 'InitiatorName': received 'iqn.1991-05.com.microsoft:myhost.mydomain', accepted 'iqn.1991-05.com.microsoft:myhost.mydomain'
5/6 1:22:35.389 e20 Params: <<< Enum param 'SessionType': received 'Normal', accepted 'Normal'
5/6 1:22:35.389 e20 Params: <<< String param 'TargetName': received 'iqn.2008-08.com.starwindsoftware:mystorage.mydomain.local-virtual-machines', accepted 'iqn.2008-08.com.starwindsoftware:mystorage.mydomain.local-virtual-machines'
5/6 1:22:35.389 e20 Params: <<< Enum param 'AuthMethod': received 'CHAP', accepted 'CHAP'
5/6 1:22:35.389 e20 PR: Set Unit attention 0x3f/0xe (0x0) for session 0xd from iqn.1991-05.com.microsoft:myhost.mydomain,400001370000.
5/6 1:22:35.389 e20 Tgt: open 'iqn.2008-08.com.starwindsoftware:mystorage.mydomain.local-virtual-machines': 1 session(s) opened, 65535 more allowed.
5/6 1:22:35.389 e20 Params: <<< Enum param 'AuthMethod': received 'CHAP', accepted 'CHAP'
5/6 1:22:35.389 e20 Params: >>> AuthMethod=CHAP.
5/6 1:22:35.389 e20 Params: >>> TargetAlias=virtual_machines.
5/6 1:22:35.389 e20 Params: >>> TargetPortalGroupTag=1.
5/6 1:22:35.389 e20 Params: <<< Enum param 'CHAP_A': received '5', accepted '5'
5/6 1:22:35.389 e20 Params: >>> CHAP_A=5.
5/6 1:22:35.389 e20 Params: >>> CHAP_I=2.
5/6 1:22:35.389 e20 Params: >>> CHAP_C=SOMETHING
5/6 1:22:35.389 e20 Params: <<< String param 'CHAP_N': received 'iqn.1991-05.com.microsoft:myhost.mydomain', accepted 'iqn.1991-05.com.microsoft:myhost.mydomain'
5/6 1:22:35.389 e20 Params: <<< String param 'CHAP_R': received 'SOMETHING', accepted 'SOMETHING'
5/6 1:22:35.389 ea0 T[d,1]: session 0xd, connection 0xd : end of stage 0, next stage 1.
5/6 1:22:35.389 e20 Params: <<< Enum param 'HeaderDigest': received 'None,CRC32C', accepted 'None'
5/6 1:22:35.389 e20 Params: <<< Enum param 'DataDigest': received 'None,CRC32C', accepted 'None'
5/6 1:22:35.389 e20 Params: <<< Numeric param 'ErrorRecoveryLevel': received 2, accepted 0
5/6 1:22:35.389 e20 Params: <<< Boolean param 'InitialR2T': received No, accepted 0
5/6 1:22:35.389 e20 Params: <<< Boolean param 'ImmediateData': received Yes, accepted 1
5/6 1:22:35.389 e20 Params: <<< Numeric param 'MaxRecvDataSegmentLength': received 65536, accepted 65536
5/6 1:22:35.389 e20 Params: <<< Numeric param 'MaxBurstLength': received 262144, accepted 262144
5/6 1:22:35.389 e20 Params: <<< Numeric param 'FirstBurstLength': received 65536, accepted 65536
5/6 1:22:35.389 e20 Params: <<< Numeric param 'MaxConnections': received 32, accepted 1
5/6 1:22:35.389 e20 Params: <<< Boolean param 'DataPDUInOrder': received Yes, accepted 1
5/6 1:22:35.389 e20 Params: <<< Boolean param 'DataSequenceInOrder': received Yes, accepted 1
5/6 1:22:35.389 e20 Params: <<< Numeric param 'DefaultTime2Wait': received 0, accepted 0
5/6 1:22:35.389 e20 Params: <<< Numeric param 'DefaultTime2Retain': received 60, accepted 20
5/6 1:22:35.389 e20 Params: <<< Numeric param 'MaxOutstandingR2T': received 16, accepted 1
5/6 1:22:35.389 e20 Params: >>> ErrorRecoveryLevel=0.
5/6 1:22:35.389 e20 Params: >>> MaxConnections=1.
5/6 1:22:35.389 e20 Params: >>> HeaderDigest=None.
5/6 1:22:35.389 e20 Params: >>> DataDigest=None.
5/6 1:22:35.389 e20 Params: >>> InitialR2T=No.
5/6 1:22:35.389 e20 Params: >>> ImmediateData=Yes.
5/6 1:22:35.389 e20 Params: >>> MaxRecvDataSegmentLength=262144.
5/6 1:22:35.389 e20 Params: >>> MaxBurstLength=262144.
5/6 1:22:35.389 e20 Params: >>> FirstBurstLength=65536.
5/6 1:22:35.389 e20 Params: >>> DefaultTime2Wait=0.
5/6 1:22:35.389 e20 Params: >>> DefaultTime2Retain=20.
5/6 1:22:35.389 e20 Params: >>> MaxOutstandingR2T=1.
5/6 1:22:35.389 e20 Params: >>> DataPDUInOrder=Yes.
5/6 1:22:35.389 e20 Params: >>> DataSequenceInOrder=Yes.
5/6 1:22:35.389 ea0 T[d,1]: session 0xd, connection 0xd : end of stage 1, next stage 3.
5/6 1:22:35.389 ea0 C[d], IN_LOGIN: Event - LOGIN_ACCEPT.
5/6 1:22:35.389 ea0 C[d], LIN: T5.
5/6 1:22:35.404 ea0 PR: Cleared an existing unit attention 0x3f/0xe for session 0xd from iqn.1991-05.com.microsoft:myhost.mydomain,400001370000.
5/6 1:22:35.404 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.404 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.404 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.404 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.404 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.404 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.420 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.420 638 Ssc: *** SscScsi_InquiryHandler: INQUIRY VPD page 0xb1 is not supported!
5/6 1:22:35.420 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.420 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.420 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:35.420 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:22:51.295 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x000000000ADC6000, 512, 0x0) failed (87).
5/6 1:22:51.295 638 IMG: *** ImageFile_ReadWriteSectors: WriteFileEx(0x000000000ADC6000, 512, 0x0) failed (87).
5/6 1:22:51.295 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x000000000ADC6000, 512, 0x0) failed (87).
5/6 1:26:13.250 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:26:13.250 638 IMG: *** ImageFile_ReadWriteSectors: WriteFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:26:13.250 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:26:18.934 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:26:18.934 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x0000000000D51000, 512, 0x0) failed (87).
5/6 1:36:34.971 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x000000000A931000, 512, 0x0) failed (87).
5/6 1:36:34.971 638 IMG: *** ImageFile_ReadWriteSectors: WriteFileEx(0x000000000A931000, 512, 0x0) failed (87).
5/6 1:36:34.971 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x000000000A931000, 512, 0x0) failed (87).

Would be nice if we could get this running

Atto Benchmarks on the tiered StorageSpace look really great!
Please let me know if i missed some important point of information.

Kind regards

qwertz · Tue May 06, 2014 1:39 am

I've tried to add a file not residing on the storagespaces to the same target... works as usual.
Looks like there is a "problem" / I found a "unsupported configuration"

Tue May 06, 2014 8:13 am

Launch cmd.exe
then type
fsutil fsinfo ntfsinfo d:
replacing the d: with the drive letter of your storage spaces volume.
Post the info here.
Thank you.

qwertz · Tue May 06, 2014 9:18 am

Hi there!
Thanks for your reply. I've run the command you recommended, here are the results:

: additional data; ntfsinfo.png (10.21 KiB) Viewed 36896 times

Thanks for your help!
Kind regards from germany

Tue May 06, 2014 10:01 am

Storage spaces report 4k logical block size when reside on disks with 4k physical block size, even when underlaying disk reports 512 bytes logical block size.
In your case, you can see that both logical and physical sector size are 4096.
This is 4Kn
http://msdn.microsoft.com/en-us/library ... s.85).aspx

You have created img with 512 sector size over the 4k sector size storage space. That's why the problem appeared.
StarWind log shows that it tries to perform read and write operations with the sector size 512 bytes, but fails.

Code: Select all

5/6 1:22:51.295 638 IMG: *** ImageFile_ReadWriteSectors: ReadFileEx(0x000000000ADC6000, 512, 0x0) failed (87).
5/6 1:22:51.295 638 IMG: *** ImageFile_ReadWriteSectors: WriteFileEx(0x000000000ADC6000, 512, 0x0) failed (87).

Please, try to create starwind image file with 4k sector size on that storage space.
FYI, connecting such devices to ESX is not a good idea because AFAIK ESX does not work with 4k native disks.

qwertz · Tue May 06, 2014 10:39 am

Hi there!
Thanks for your reply. I was just digging into this, and I've already verified that I can successfully create a 4096b sector size disc.
(Performance is horrible though)

I'm currently trying to get this "right"
Here is what I found out so far:

: further_digging; storage_spaces_options.png (19.1 KiB) Viewed 36891 times

Looks like this should work better with a logicalsectorsize of 512. But how to change this...

Tue May 06, 2014 10:50 am

I have found it ))
http://technet.microsoft.com/en-us/libr ... 48689.aspx

qwertz · Tue May 06, 2014 10:52 am

u mean i need to delete the existing storagespace? absolutely no problem

Tue May 06, 2014 12:55 pm

Make sure you've also upgraded to RC2 as it's the first version we completely support Storage Spaces with.

qwertz · Tue May 06, 2014 9:39 pm

Hi there!
Thanks, again, for your help! I've got things running in the meantime, and it's "fast"

Here is what I get with atto if i perform a benchmark on the storage-space locally:

: performance_on_local_host; storage_spaces_localhost.png (20.06 KiB) Viewed 36814 times

I've compared performance accessing targets with 4k and 512b sector size and this are my results:

: 4k_vs_512; 4kvs512.png (34.73 KiB) Viewed 36812 times

I deleted the storagespace, and recreated using the following command:

Code: Select all

New-StoragePool -FriendlyName Hybrid_Pool -LogicalSectorSizeDefault 512 -ResiliencySettingNameDefault Mirror -Verbose -StorageSubSystemFriendlyName "Storage Spaces*" -PhysicalDisks $physicaldisks

Now the Pool looks like this:

Code: Select all

get-storagepool | ft FriendlyName,*Sector*,Size -AutoSize

FriendlyName LogicalSectorSize PhysicalSectorSize           Size
------------ ----------------- ------------------           ----
Hybrid_Pool                512               4096  8497055924224

When I copied Files from one iSCSI Target to another Target(from Backup to NewTarget) throughput was like this:

: throughput; throughput_cut.png (14.08 KiB) Viewed 36811 times

Fast enough for my home lab

Thanks again for your help, and the great Software !
Kind regards

Btw:

anton (staff) wrote:Make sure you've also upgraded to RC2 as it's the first version we completely support Storage Spaces with.

I did that

Have a nice Day!

Tue May 06, 2014 10:33 pm

Numbers seems to be swapped

4KB native blocks with StarWind should be faster. Are you sure you've posted (undersigned) pictures in the right way?

qwertz · Tue May 06, 2014 10:36 pm

yes. I'm sure. but maybe this is because of the "main performance" comes from the ssd's and they are 512b?
(you can also verify this in the image: the 4k bench doesn't include 512b test values)

Tue May 06, 2014 10:57 pm

I've asked engineers to take a look @ that. StarWind with native 4KB blocks should be faster on top of any storage then StarWind with 512B blocks.

qwertz wrote:yes. I'm sure. but maybe this is because of the "main performance" comes from the ssd's and they are 512b?
(you can also verify this in the image: the 4k bench doesn't include 512b test values)

qwertz · Tue May 06, 2014 11:17 pm

OK. Let me know if additional data is needed

Mon May 19, 2014 6:35 pm

We're done with a release and do fully suppert both layering on top of a 4KB block devices and also exporting either 512e or full-block 4096 bytes sectors to user. Please update and let us know what you think. Thanks!