Unsolved
This post is more than 5 years old
6 Posts
0
1510
December 22nd, 2016 08:00
Long Delay of Actual Data Backup after Scheduled Backup Begins
Hello,
I have a backup job that is scheduled to run at 7pm, however the VSS snapshot appears to be created about 3 to 4 hours later, and then the backup process actually begins. I've included a snip-it of the Avamar Activity Session Log. There are a number of avtar <8688> Status messages with 0 Bytes of data during this time that I have highlighted below. Our backup Dataset is setup to only backup the E: volume, excluding C:. I have a support ticket open on this and initially was told that certain Avamar files needed to be added to our AntiVirus exclusions list, and that this would resolve the issue. However these files had already been excluded. Can anyone help in explaining what may be going on during this time, and is there anything that can be done to resolve this?
Thanks!
Pat
2016-12-21 19:00:37 avtar Info <6426>: Done loading cache files
2016-12-21 19:00:37 avtar Info <19072>: Doing full FS backup -- adding ALL Mount Points to freeze volumes list
2016-12-21 19:00:37 avtar Info <19831>: Performing Reparse Points processing on backup target(s) to locate any nested reparse points, which may 'point' to remote volumes that also need freezing.
2016-12-21 19:00:37 avtar Info <7324>: Volume Type for "C:\" is "NTFS", Supports Compression=1, Encryption=1, ACLS=1, DataStreams=1, Reparse=1, Sparse=1, Hardlinks=1
2016-12-21 19:15:38 avtar Info <8688>: Status 2016-12-21 19:15:38, 0 bytes (0 bytes, 0.00% new) 1097MB 8% CPU
2016-12-21 19:30:46 avtar Info <8688>: Status 2016-12-21 19:30:46, 0 bytes (0 bytes, 0.00% new) 1097MB 9% CPU
2016-12-21 19:45:53 avtar Info <8688>: Status 2016-12-21 19:45:53, 0 bytes (0 bytes, 0.00% new) 1098MB 10% CPU
2016-12-21 20:01:01 avtar Info <8688>: Status 2016-12-21 20:01:01, 0 bytes (0 bytes, 0.00% new) 1098MB 11% CPU
2016-12-21 20:16:09 avtar Info <8688>: Status 2016-12-21 20:16:09, 0 bytes (0 bytes, 0.00% new) 1098MB 12% CPU
2016-12-21 20:31:16 avtar Info <8688>: Status 2016-12-21 20:31:16, 0 bytes (0 bytes, 0.00% new) 1098MB 13% CPU
2016-12-21 20:46:24 avtar Info <8688>: Status 2016-12-21 20:46:24, 0 bytes (0 bytes, 0.00% new) 1098MB 13% CPU
2016-12-21 21:01:31 avtar Info <8688>: Status 2016-12-21 21:01:31, 0 bytes (0 bytes, 0.00% new) 1098MB 12% CPU
2016-12-21 21:16:39 avtar Info <8688>: Status 2016-12-21 21:16:39, 0 bytes (0 bytes, 0.00% new) 1098MB 7% CPU
2016-12-21 21:31:47 avtar Info <8688>: Status 2016-12-21 21:31:47, 0 bytes (0 bytes, 0.00% new) 1098MB 10% CPU
2016-12-21 21:46:55 avtar Info <8688>: Status 2016-12-21 21:46:55, 0 bytes (0 bytes, 0.00% new) 1098MB 13% CPU
2016-12-21 22:02:02 avtar Info <8688>: Status 2016-12-21 22:02:02, 0 bytes (0 bytes, 0.00% new) 1098MB 14% CPU
2016-12-21 22:17:10 avtar Info <8688>: Status 2016-12-21 22:17:10, 0 bytes (0 bytes, 0.00% new) 1098MB 10% CPU
2016-12-21 22:32:18 avtar Info <8688>: Status 2016-12-21 22:32:18, 0 bytes (0 bytes, 0.00% new) 1098MB 12% CPU
2016-12-21 22:47:26 avtar Info <8688>: Status 2016-12-21 22:47:26, 0 bytes (0 bytes, 0.00% new) 1098MB 11% CPU
2016-12-21 22:50:14 avtar Info <7324>: Volume Type for "E:\" is "NTFS", Supports Compression=1, Encryption=1, ACLS=1, DataStreams=1, Reparse=1, Sparse=1, Hardlinks=1
2016-12-21 22:50:14 avtar Info <19066>: Frozen Volume Path:
2016-12-21 22:50:14 avtar Info <19067>: Cmd-related (directly or via reparse points) Mount Paths
2016-12-21 22:50:14 avtar Info <19068>: C:\ (directly)
2016-12-21 22:50:14 avtar Info <19066>: Frozen Volume Path:
2016-12-21 22:50:14 avtar Info <19067>: Cmd-related (directly or via reparse points) Mount Paths
2016-12-21 22:50:14 avtar Info <19068>: E:\ (directly)
2016-12-21 22:50:14 avtar Info <16479>: VSS: Running on Windows 8 or newer OS, setting correct impersonation level
2016-12-21 22:50:14 avtar Info <19008>: Obtaining available VSS providers
2016-12-21 22:50:14 avtar Info <19014>: Determining best VSS provider for volume '\\?\Volume{228f91d4-69bd-11e4-80bf-806e6f6e6963}\'
2016-12-21 22:50:15 avtar Info <19013>: Volume \\?\Volume{228f91d4-69bd-11e4-80bf-806e6f6e6963}\ will be frozen by 'Microsoft Software Shadow Copy provider 1.0' in Snaphot {ca154e55-1967-4ad8-93f6-1e21ef49e6aa}
2016-12-21 22:50:15 avtar Info <19014>: Determining best VSS provider for volume '\\?\Volume{39806ff0-69be-11e4-80c2-0050568f3937}\'
2016-12-21 22:50:15 avtar Info <19013>: Volume \\?\Volume{39806ff0-69be-11e4-80c2-0050568f3937}\ will be frozen by 'Microsoft Software Shadow Copy provider 1.0' in Snaphot {1389f3a2-6986-4bce-8702-edb37293f0b8}
2016-12-21 22:50:15 avtar Info <8776>: Freezing volumes now...
2016-12-21 22:50:15 avtar Info <8780>: Creating the shadow copy set (DoSnapshotSet) ...
2016-12-21 22:50:31 avtar Info <8781>: Shadow copy set successfully created.
2016-12-21 22:50:31 avtar Info <8803>: Querying all shadow copies with the SnapshotSetID {12be93fa-42a6-4cbc-bf23-4acc8b349a06} ...
2016-12-21 22:50:32 avtar Info <8808>: * SNAPSHOT ID = {1389f3a2-6986-4bce-8702-edb37293f0b8}
2016-12-21 22:50:32 avtar Info <8809>: - Member of Snapshot Set: {12be93fa-42a6-4cbc-bf23-4acc8b349a06}
2016-12-21 22:50:32 avtar Info <8810>: - Original count of shadow copies = 2
2016-12-21 22:50:32 avtar Info <8811>: - Original Volume name: \\?\Volume{39806ff0-69be-11e4-80c2-0050568f3937}\
2016-12-21 22:50:32 avtar Info <8812>: - Creation Time: 12/21/2016 10:50:27 PM
2016-12-21 22:50:32 avtar Info <8813>: - Shadow copy device name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy11
2016-12-21 22:50:32 avtar Info <8814>: - Originating machine: 01FS6.honigman.local
2016-12-21 22:50:32 avtar Info <8815>: - Service machine: 01FS6.honigman.local
2016-12-21 22:50:32 avtar Info <8819>: - Not Exposed
2016-12-21 22:50:32 avtar Info <8820>: - Provider : Microsoft Software Shadow Copy provider 1.0
2016-12-21 22:50:32 avtar Info <8821>: - Attributes: Auto_Release No_Writers Differential
2016-12-21 22:50:32 avtar Info <0000>:
2016-12-21 22:50:32 avtar Info <8808>: * SNAPSHOT ID = {ca154e55-1967-4ad8-93f6-1e21ef49e6aa}
2016-12-21 22:50:32 avtar Info <8809>: - Member of Snapshot Set: {12be93fa-42a6-4cbc-bf23-4acc8b349a06}
2016-12-21 22:50:32 avtar Info <8810>: - Original count of shadow copies = 2
2016-12-21 22:50:32 avtar Info <8811>: - Original Volume name: \\?\Volume{228f91d4-69bd-11e4-80bf-806e6f6e6963}\
2016-12-21 22:50:32 avtar Info <8812>: - Creation Time: 12/21/2016 10:50:27 PM
2016-12-21 22:50:32 avtar Info <8813>: - Shadow copy device name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy10
2016-12-21 22:50:32 avtar Info <8814>: - Originating machine: 01FS6.honigman.local
2016-12-21 22:50:32 avtar Info <8815>: - Service machine: 01FS6.honigman.local
2016-12-21 22:50:32 avtar Info <8819>: - Not Exposed
2016-12-21 22:50:32 avtar Info <8820>: - Provider : Microsoft Software Shadow Copy provider 1.0
2016-12-21 22:50:32 avtar Info <8821>: - Attributes: Auto_Release No_Writers Differential
2016-12-21 22:50:32 avtar Info <0000>:
2016-12-21 22:50:32 avtar Info <8785>: Retrieving volume mappings...
2016-12-21 22:50:32 avtar Info <6074>: VSS snapshot set creation successful
2016-12-21 22:50:32 avtar Info <7324>: Volume Type for "D:\" is "", Supports Compression=0, Encryption=0, ACLS=0, DataStreams=0, Reparse=0, Sparse=0, Hardlinks=0
2016-12-21 22:50:32 avtar Info <5811>: - Traversing drive 'C:' kind 'Local Fixed Disk'
2016-12-21 22:50:32 avtar Info <7324>: Volume Type for "C:\" is "NTFS", Supports Compression=1, Encryption=1, ACLS=1, DataStreams=1, Reparse=1, Sparse=1, Hardlinks=1
2016-12-21 22:50:33 avtar Info <5810>: - Not traversing drive 'D:' kind 'CDROM' and not performing a target backup
2016-12-21 22:50:33 avtar Info <5811>: - Traversing drive 'E:' kind 'Local Fixed Disk'
2016-12-21 22:50:33 avtar Info <7324>: Volume Type for "E:\" is "NTFS", Supports Compression=1, Encryption=1, ACLS=1, DataStreams=1, Reparse=1, Sparse=1, Hardlinks=1
2016-12-21 22:50:56 avtar Info <5548>: 2016-12-21 22:50:56 Eastern Standard Time: Automatic cache flush of 'C:\Program Files\avs\var\f_cache.dat'
2016-12-21 22:50:56 avtar Info <5069>: - Writing cache file "C:\Program Files\avs\var\f_cache.dat"
2016-12-21 22:50:59 avtar Info <5546>: Cache update complete C:\Program Files\avs\var\f_cache.dat (704.0 MiB of 1500 MiB max)
2016-12-21 23:02:34 avtar Info <8688>: Status 2016-12-21 23:02:34, 83,662 files, 15,139 folders, 34.15 GB (0 bytes, 0.00% new) 1107MB 11% CPU E:\WorkSiteDocs\ACTIVE\AJB\6735\1\
nat1231
1 Message
0
January 23rd, 2017 05:00
Hi pmittle11, did you ever get a response from EMC about this? I'm getting the exact same issue in the exact same situation. After enabling the --debug flag, it appears that the blue highlighted text your getting, the below is happening (G drive in my case), it "looks" like it's stuck on C drive though, just like mine. It will sit there for about 3 hours doing this before finally going ahead and doing the backup. Avamar 7.1 didn't do this, it's only until I upgraded to 7.2 did it start doing this. the Windows file system plugin appears to want to enumerate the volumes that it's backing up using VSS even if it's only select files/folders and unfortunately deduplication can have a lot of reparse points.
2017/01/20-02:26:38.18899 [avtar] Enumerating reparse points on 'G:\'
2017/01/20-02:26:41.31399 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.31399 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.31399 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.31399 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.34500 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.34500 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.36100 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.36100 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.36100 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.36100 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.36100 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.37700 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.37700 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005 2017/01/20-02:26:41.37700 [avtar] ZwQueryInformationFile() failed to obtain reparse point filename on volume 'G:\', status=0X80000005
I haven't figured much else out and unfortunately EMC aren't telling me much at the moment. I have other 2012 R2 servers with dedupe turned on and working but don't display the same delay. Having said that, this server is housing 6TB with a windows dedupe ratio of about 50%. with Avamar 7.1 the message was:
[avtar] Info <16130>: Windows Deduplicated files and being backed-up as full-size ("reinflated") files. Files will remain deduplicated on source machine.
I was happy with this, but something has changed, most notably the reparse enumeration or the way it's done.
milb65
10 Posts
0
January 23rd, 2017 07:00
Out of curiosity, what does the OS event viewer App and Sys logs look like at the time of backups?