Data Backup and Recovery
Data Backup and Recovery
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:
Regards,
Jason