Options
- Subscribe to RSS Feed
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Bookmark
- Subscribe
- Mute
- Printer Friendly Page
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
This is probably directed at the engineering team responsible for SnapDrive and SME but it might be interesting to others.
We've had an issue for a while with Exchange backups failing. An Exchange backup must occur within a 10 second window after the mailbox databases have had their I/O frozen.
When we check the windows application event log you can see that the backup failed because it took longer than 10 seconds, for example:
"Data ONTAP VSS hardware provider has completed CommitSnapshots for SnapshotSetId {699697d1-b950-47d8-9dfe-075b3fab74f6} in 10172 milliseconds. Since it takes more than 10 seconds, this can fail the current shadow copy."
I think I've tracked down the problem and it's not the duration of the actual snapshot but of a set of LUN attribute settings that get applied to the LUNs after the snapshot.
In another example below you can see the snapshot runs from 23:30:54.924 to 23:30:58.924, and then from 23:30:58.924 'lun-set-attribute' is called several times for each LUN through to 23:31:08.737
07/12-23:30:54.924 PID:2696 TID:23216 SnapCreateHelper.cpp@351 CreateMultivolSnapShotThreadProc - Begin 07/12-23:30:54.924 PID:2696 TID:23216 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:30:54.924 PID:2696 TID:23216 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:30:54.924 PID:2696 TID:23216 filer.cpp@16339 The 'snapshot-multicreate' ZAPI is being called. 07/12-23:30:54.924 PID:2696 TID:23216 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:30:58.924 PID:2696 TID:23216 filer.cpp@16416 CFilerRollingRock::zapi_snapshot_multicreate finished. 07/12-23:30:58.924 PID:2696 TID:23216 SnapCreateHelper.cpp@436 CreateMultivolSnapShotThreadProc End 07/12-23:30:58.924 PID:2696 TID:7920 EventLog.cpp@344 Start NeedMuteEvent(): dwEventID 190 dwNumStrings 3 enumEvtMuteGrp -1 07/12-23:30:58.924 PID:2696 TID:7920 EventLog.cpp@438 End NeedMuteEvent(): dwEventID 190 dwNumStrings 3 enumEvtMuteGrp -1 bRet=00 07/12-23:30:58.924 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:30:58.924 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:30:58.924 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:30:58.924 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:30:59.236 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:30:59.236 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:30:59.236 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:30:59.236 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:30:59.549 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:30:59.549 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:30:59.549 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:30:59.549 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:30:59.861 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:30:59.861 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:30:59.861 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:30:59.861 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:00.158 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:00.158 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:00.158 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:00.158 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:00.502 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:00.502 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:00.502 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:00.502 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:00.861 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:00.861 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:00.861 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:00.861 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:01.158 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:01.158 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:01.158 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:01.158 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:01.486 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:01.486 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:01.486 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:01.486 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:01.783 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:01.783 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:01.783 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:01.783 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:02.080 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:02.080 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:02.080 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:02.080 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:02.377 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:02.377 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:02.377 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:02.377 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:02.674 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:02.674 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:02.674 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:02.674 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:03.018 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:03.018 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:03.018 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:03.018 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:03.315 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:03.315 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:03.315 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:03.315 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:03.627 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:03.627 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:03.627 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:03.627 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:03.924 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:03.924 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:03.924 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:03.924 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:04.221 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:04.221 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:04.221 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:04.221 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:04.533 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:04.533 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:04.533 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:04.533 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:04.830 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:04.830 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:04.830 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:04.830 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:05.143 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:05.143 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:05.143 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:05.143 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:05.455 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:05.455 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:05.455 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:05.455 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:05.768 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:05.768 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:05.768 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:05.768 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:06.065 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:06.065 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:06.065 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:06.065 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:06.361 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:06.361 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:06.361 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:06.361 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:06.643 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:06.643 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:06.643 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:06.643 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:06.955 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:06.955 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:06.955 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:06.955 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:07.252 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:07.252 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:07.252 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:07.252 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:07.549 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:07.549 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:07.549 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:07.549 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:07.846 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:07.846 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:07.846 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:07.846 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:08.127 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:08.127 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:08.127 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:08.127 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:08.440 PID:2696 TID:12496 filer.cpp@1143 CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start. 07/12-23:31:08.440 PID:2696 TID:12496 filer.cpp@1168 CFiler::static_setup_zapi_connection: end. 07/12-23:31:08.440 PID:2696 TID:12496 filer.cpp@6184 The 'lun-set-attribute' ZAPI is being called. 07/12-23:31:08.440 PID:2696 TID:12496 filer.cpp@11326 CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start 07/12-23:31:08.737 PID:2696 TID:12496 SnapShot.cpp@8279 Finish CSnapShot::CreateSnapShotInternal_PerFiler 07/12-23:31:08.737 PID:2696 TID:12496 SnapShot.cpp@8526 CSnapShot::CreateSnapShot1 - End 07/12-23:31:08.737 PID:2696 TID:12496 Sychronize.h@108 Mutex::Release called 07/12-23:31:08.737 PID:2696 TID:12496 Sychronize.h@118 Mutex::Release finished execution 07/12-23:31:08.737 PID:2696 TID:12496 SWSvc.cpp@2431 CServiceModule::ReleaseVolumeCache 07/12-23:31:08.737 PID:2696 TID:12496 host_volume_info.cpp@1170 exit_volume_list_vector: Clear m_volume_list_vector. 07/12-23:31:08.737 PID:2696 TID:12496 SWSvc.cpp@2336 CServiceModule::ReleaseZapiCache 07/12-23:31:08.737 PID:2696 TID:12496 filer.h@3222 exit_volume_list_map: Clear m_volume_list_map.
Each round-trip ZAPI call takes about a quarter of a second. With 32 ZAPI calls (4 per LUN, 8 LUNs) that's around 8-10 seconds just to set LUN attributes.
The time varies with each backup and depends on things such as how busy the cluster is.
I don't have a 'quiet' time that I can schedule backups for - our clusters are pretty busy at most parts of the day. I also don't want to split our backup sets into ever smaller groups of mailbox databases but this is the only option I have right now.
In the meantime, can I suggest the SME and SnapDrive team look at adding a feature request to change the way this works?
Here are some of my ideas:
- Move the 'lun-set-attribute' out of the critical path for the backup so it doesn't hold up sending Exchange a success result for the snapshot.
- Modify ZAPI and SnapDrive to add a 'lun-set-attributes' call so multiple attributes can be set with just one call.
- Update SnapDrive so it reuses HTTP sessions - I know the filer web server used to close the session after each request-response pair but in newer versions sessions can be long lived. Don't close a session until it has been idle for at least 1 second (maybe longer). This would avoid the time wasted in setting up new HTTPS sessions for every single ZAPI call that gets made.
Regards,
Jason
0 REPLIES 0
