Data Backup and Recovery

SnapDrive Windows & Exchange backup timeouts

jasonpugsley
2,428 Views

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
Public