Re: Snapdrive 6.31R1 takes very long time to enumerate disks

thierry · ‎2012-03-28

Hello ,

Windows 2008 R2 SP1

DSM 3.5

Snapdrive6.3.1R1

Ontap 8.0.2P3

We have 10 servers installed, dedicated to an exchange 2010 infrastructure.

Each server has 45 Luns.

8 of those servers takes around 15 minutes to enumerates their LUN (when you click on “disks” in the mmc) while 2 of them only takes between 30 to 45 seconds for the same number of LUNs.

Looking at the “snpdrvdbglog files of both a long enumerating server and a fast enumerating server I have noticed the following things.

On the slow server, we issue 4 times the NetShareEnum Call for every volume. Each call takes 10 seconds so 40 seconds per volume, for a total of 14 minutes due to the number of volumes.

On the “quick” servers, for the same process, it doesn’t take any time.

Any idea why we spend each time 10 seconds for this call on some servers and 0s on 2 others ?

See the output below :

Slow enumerating server :

03/28-12:59:07.666 PID:1496 TID:620 System.cpp@649 CSystem::enumerate_virtual_disks: volume_set.modify(33, 192.91.36.123+192.132.84.101, DRPMSAE207A0011

03/28-12:59:07.666 PID:1496 TID:620 volume_set.cpp@141 Start volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:59:07.666 PID:1496 TID:620 volume_set.cpp@14 Start volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:59:07.666 PID:1496 TID:620 VirtualDiskShare.cpp@2569 Start get_cifs_share_name(192.132.84.101, DRPMSAE207A0011)

03/28-12:59:07.666 PID:1496 TID:620 VirtualDiskShare.cpp@998 Start GetShareName(192.132.84.101, DRPMSAE207A0011)

03/28-12:59:07.666 PID:1496 TID:620 VirtualDiskShare.cpp@1006 GetShareName: calling NetShareEnum

03/28-12:59:17.697 PID:1496 TID:620 VirtualDiskShare.cpp@1058 GetShareName: did not find share the 1st time, try again...

03/28-12:59:17.697 PID:1496 TID:620 VirtualDiskShare.cpp@1070 GetShareName: calling NetShareEnum

03/28-12:59:27.712 PID:1496 TID:620 VirtualDiskShare.cpp@1129 Finish GetShareName: hr = 80070005

03/28-12:59:27.712 PID:1496 TID:620 VirtualDiskShare.cpp@2576 Finish get_cifs_share_name()

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@27 Finish volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@68 Start volume_t::update_volume_clone_status(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@100 Finish volume_t::update_volume_clone_status(filer_t& filer)-volume name:DRPMSAE207A0011, m_is_volume_clone:false

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@33 Start volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@63 Finish volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@106 Start volume_t::update_snapvault_status(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@136 Finish volume_t::update_snapvault_status(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@177 Finish volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:59:27.712 PID:1496 TID:620 System.cpp@649 CSystem::enumerate_virtual_disks: volume_set.modify(34, 192.91.36.123+192.132.84.101, DRPMSAE207A0011

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@141 Start volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:59:27.712 PID:1496 TID:620 volume_set.cpp@14 Start volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:59:27.712 PID:1496 TID:620 VirtualDiskShare.cpp@2569 Start get_cifs_share_name(192.132.84.101, DRPMSAE207A0011)

03/28-12:59:27.712 PID:1496 TID:620 VirtualDiskShare.cpp@998 Start GetShareName(192.132.84.101, DRPMSAE207A0011)

03/28-12:59:27.712 PID:1496 TID:620 VirtualDiskShare.cpp@1006 GetShareName: calling NetShareEnum

03/28-12:59:37.727 PID:1496 TID:620 VirtualDiskShare.cpp@1058 GetShareName: did not find share the 1st time, try again...

03/28-12:59:37.727 PID:1496 TID:620 VirtualDiskShare.cpp@1070 GetShareName: calling NetShareEnum

03/28-12:59:47.758 PID:1496 TID:620 VirtualDiskShare.cpp@1129 Finish GetShareName: hr = 80070005

03/28-12:59:47.758 PID:1496 TID:620 VirtualDiskShare.cpp@2576 Finish get_cifs_share_name()

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@27 Finish volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@68 Start volume_t::update_volume_clone_status(filer_t& filer)

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@100 Finish volume_t::update_volume_clone_status(filer_t& filer)-volume name:DRPMSAE207A0011, m_is_volume_clone:false

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@33 Start volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@63 Finish volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@106 Start volume_t::update_snapvault_status(filer_t& filer)

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@136 Finish volume_t::update_snapvault_status(filer_t& filer)

03/28-12:59:47.758 PID:1496 TID:620 volume_set.cpp@177 Finish volume_t::update_functor::operator()(volume_t* p_volume)

Fast Enumerating server

03/28-12:57:27.548 PID:2128 TID:10336 System.cpp@649 CSystem::enumerate_virtual_disks: volume_set.modify(32, 192.91.36.125+192.132.84.100, DRPMSAE207B0011

03/28-12:57:27.548 PID:2128 TID:10336 volume_set.cpp@141 Start volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:57:27.548 PID:2128 TID:10336 volume_set.cpp@14 Start volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:57:27.548 PID:2128 TID:10336 VirtualDiskShare.cpp@2569 Start get_cifs_share_name(192.132.84.100, DRPMSAE207B0011)

03/28-12:57:27.548 PID:2128 TID:10336 VirtualDiskShare.cpp@998 Start GetShareName(192.132.84.100, DRPMSAE207B0011)

03/28-12:57:27.548 PID:2128 TID:10336 VirtualDiskShare.cpp@1006 GetShareName: calling NetShareEnum

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@1058 GetShareName: did not find share the 1st time, try again...

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@1070 GetShareName: calling NetShareEnum

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@1129 Finish GetShareName: hr = 800706bf

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@2576 Finish get_cifs_share_name()

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@27 Finish volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@68 Start volume_t::update_volume_clone_status(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@100 Finish volume_t::update_volume_clone_status(filer_t& filer)-volume name:DRPMSAE207B0011, m_is_volume_clone:false

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@33 Start volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@63 Finish volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@106 Start volume_t::update_snapvault_status(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@136 Finish volume_t::update_snapvault_status(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@177 Finish volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:57:27.564 PID:2128 TID:10336 System.cpp@649 CSystem::enumerate_virtual_disks: volume_set.modify(33, 192.91.36.125+192.132.84.100, DRPMSAE207B0011

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@141 Start volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:57:27.564 PID:2128 TID:10336 volume_set.cpp@14 Start volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@2569 Start get_cifs_share_name(192.132.84.100, DRPMSAE207B0011)

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@998 Start GetShareName(192.132.84.100, DRPMSAE207B0011)

03/28-12:57:27.564 PID:2128 TID:10336 VirtualDiskShare.cpp@1006 GetShareName: calling NetShareEnum

03/28-12:57:27.580 PID:2128 TID:10336 VirtualDiskShare.cpp@1058 GetShareName: did not find share the 1st time, try again...

03/28-12:57:27.580 PID:2128 TID:10336 VirtualDiskShare.cpp@1070 GetShareName: calling NetShareEnum

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@1129 Finish GetShareName: hr = 800706bf

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@2576 Finish get_cifs_share_name()

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@27 Finish volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@68 Start volume_t::update_volume_clone_status(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@100 Finish volume_t::update_volume_clone_status(filer_t& filer)-volume name:DRPMSAE207B0011, m_is_volume_clone:false

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@33 Start volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@63 Finish volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@106 Start volume_t::update_snapvault_status(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@136 Finish volume_t::update_snapvault_status(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@177 Finish volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:57:27.595 PID:2128 TID:10336 System.cpp@649 CSystem::enumerate_virtual_disks: volume_set.modify(34, 192.91.36.125+192.132.84.100, DRPMSAE207B0011

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@141 Start volume_t::update_functor::operator()(volume_t* p_volume)

03/28-12:57:27.595 PID:2128 TID:10336 volume_set.cpp@14 Start volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@2569 Start get_cifs_share_name(192.132.84.100, DRPMSAE207B0011)

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@998 Start GetShareName(192.132.84.100, DRPMSAE207B0011)

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@1006 GetShareName: calling NetShareEnum

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@1058 GetShareName: did not find share the 1st time, try again...

03/28-12:57:27.595 PID:2128 TID:10336 VirtualDiskShare.cpp@1070 GetShareName: calling NetShareEnum

03/28-12:57:27.611 PID:2128 TID:10336 VirtualDiskShare.cpp@1129 Finish GetShareName: hr = 800706bf

03/28-12:57:27.611 PID:2128 TID:10336 VirtualDiskShare.cpp@2576 Finish get_cifs_share_name()

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@27 Finish volume_t::update_cifs_share_name(filer_t& filer)

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@68 Start volume_t::update_volume_clone_status(filer_t& filer)

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@100 Finish volume_t::update_volume_clone_status(filer_t& filer)-volume name:DRPMSAE207B0011, m_is_volume_clone:false

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@33 Start volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@63 Finish volume_t::update_snapmirror_status(filer_t& filer)

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@106 Start volume_t::update_snapvault_status(filer_t& filer)

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@136 Finish volume_t::update_snapvault_status(filer_t& filer)

03/28-12:57:27.611 PID:2128 TID:10336 volume_set.cpp@177 Finish volume_t::update_functor::operator()(volume_t* p_volume)

Any help would be very appreciated

aborzenkov · ‎2012-03-28

Did you configure SnapDrvie to use the same protocol (RPC, HTTP(S)) on all servers?

thierry · ‎2012-03-29

Yes,

All servers are configured to use HTTPS.

/T

tyrone_owen_1 · ‎2012-06-22

I seem to be having the same problem on multiple Windows 2008 R2 SP1 boxes

I'm alos using Snapdrive6.3.1R1 (RPC) with preferred IPs set

Did you make any progress?

brauntvr2swiss · ‎2012-06-22

Hi

I would recommend you to plan an update to snapdrive 6.4.. Its much faster, than the previous Version of snapdrive.

We have few Windows 2008 R2 Clusters and since SD 6.4 Lun Enumeration is very fast...

regards,

Thomas

thierry · ‎2012-06-22

Correct.

Upgrading to the Snapdrive 6.4 release fixed those too long disk enumerating time.

Please consider upgrading your current release.

Regards

tyrone_owen_1 · ‎2012-06-28

Thought I'd quickly post back as I've had a bit of a discovery.

I used SD 6.3.1R1 to mount a snapshot from one of my T2 storage boxes and it was really quick - this is the first time I've carried out this activity. I made an assumption that SD 6.3.1R1 was the issue, but it looks like that isn't the case. When I solve the issue I'll update the post.

Thanks

ashleycook · ‎2012-06-29

Any issues with DNS?

I've seen enumeration take an excessive amount of time in the past when the host has been unable to resolve the storage system name, even though SnapDrive is attempting to connect to the IP address.

Might be worth entering the addresses in the hosts file to test.

tyrone_owen_1 · ‎2012-06-29

Mr Cook, how are you?

I thought it may have been name resolution when I first started having the issues so tried the local hosts file with no joy.

Two out of six storage controllers are having issues. I've compared VIF configurations which look fine, so I've asked the comms guys to gte involved.

Cheers

brooksindc · ‎2014-01-27

once the disks finally enumerate. (right click disk) or go to disk properties in snapdrive. look for the preferred storage tab and fill in your preferred storage list and IP.

Next time you enumerate....the disk will come up very quickly.