NVP vProxy: VM backup is backing up unallocated disk space as changed data
Summary: NetWorker VMware Protection (NVP) Virtual Machine (VM) backups are being performed. During backups, unallocated disk space is being calculated as changed data and is written to Data Domain, resulting in slower than expected backup performance. ...
Symptoms
As an example, A VM has the following disk configuration and usage:
| Disk Number | Provisioned | Free Space |
| 1 | 149 GB | 94 GB |
| 2 | 14 TB | 12.3 TB |
| 3 | 899 GB | 595 GB |
| 4 | 249 GB | 241 GB |
| 5 | 74 GB | 10 GB |
During VM backups, the following is logged in the VM backup session log:
YYYY-MM-DDT22:00:26Z INFO: [94] Queried CBT data relative to '52 68 e2 45 c1 72 2a 28-60 2b 7c d3 20 2f b1 7c/45', for 'Hard disk 1'. YYYY-MM-DDT22:00:27Z NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDT22:00:27Z NOTICE: [94] Used bytes = 160410107904, changed bytes = 113753849856, change rate = 070.91%. YYYY-MM-DDT22:00:27Z INFO: [94] File block exclusion: No objects to exclude from the backup YYYY-MM-DDT22:00:29Z NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDT22:00:29Z INFO: [94] Queried CBT data relative to '52 c5 cb 19 01 05 07 a7-33 ad 3c 83 ed ae 88 f3/45', for 'Hard disk 2'. YYYY-MM-DDT22:00:29Z NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDT22:00:29Z NOTICE: [94] Used bytes = 15393120845824, changed bytes = 14654092869632, change rate = 095.20%. YYYY-MM-DDT22:00:29Z INFO: [94] File block exclusion: No objects to exclude from the backup YYYY-MM-DDT22:00:29Z NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDT22:00:29Z INFO: [94] Queried CBT data relative to '52 cd 0c c4 5d e0 d4 23-7a c3 98 f3 cc 1f 45 63/45', for 'Hard disk 3'. YYYY-MM-DDT22:00:29Z NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDT22:00:29Z NOTICE: [94] Used bytes = 966305775616, changed bytes = 965150244864, change rate = 099.88%. YYYY-MM-DDT22:00:29Z INFO: [94] File block exclusion: No objects to exclude from the backup YYYY-MM-DDT22:00:30Z NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDT22:00:30Z INFO: [94] Queried CBT data relative to '52 eb e8 e1 8c 3d ea 1d-ff 5d 73 da 9e 91 d0 39/48', for 'Hard disk 4'. YYYY-MM-DDTHH:MM:SSZ NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDTHH:MM:SSZ NOTICE: [94] Used bytes = 268405047296, changed bytes = 263489847296, change rate = 098.17%. YYYY-MM-DDTHH:MM:SSZ INFO: [94] File block exclusion: No objects to exclude from the backup YYYY-MM-DDTHH:MM:SSZ NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDTHH:MM:SSZ INFO: [94] Queried CBT data relative to '52 f7 ec 4d 6b 8e fb bb-93 5b 29 53 9a 78 6e e0/45', for 'Hard disk 5'. YYYY-MM-DDTHH:MM:SSZ NOTICE: [94] Blocks were realigned to 0 KB boundary. YYYY-MM-DDTHH:MM:SSZ NOTICE: [94] Used bytes = 78411005952, changed bytes = 32001884160, change rate = 040.81%. … YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Disk Label | Mode | Bytes Moved | Read Rate | Write Rate | Overhead | VDDK Wait | Total Time | VM MORef | VM Name YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: ------------- | ------ | ----------- | ------------ | ------------ | ------------- | ------------- | ------------- | --------- | ------------------------------ YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Hard disk 3 | hotadd | 899 GiB | 491 MiB/s | 179 MiB/s | 0:00:17 | 4.4 us | 1:27:52 | vm-11883 | VM_NAME YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Hard disk 4 | hotadd | 246 GiB | 559 MiB/s | 238 MiB/s | 0:00:18 | 4.1 us | 0:21:06 | vm-11883 | VM_NAME YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Hard disk 1 | hotadd | 106 GiB | 776 MiB/s | 222 MiB/s | 0:00:19 | 4.5 us | 0:10:29 | vm-11883 | VM_NAME YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Hard disk 5 | hotadd | 30 GiB | 662 MiB/s | 147 MiB/s | 0:00:19 | 4.5 us | 0:04:12 | vm-11883 | VM_NAME YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Hard disk 2 | hotadd | 14 TiB | 604 MiB/s | 252 MiB/s | 0:00:20 | 5.1 us | 16:01:26 | vm-11883 | VM_NAME YYYY-MM-DDTHH:MM:SSZ INFO: [94] DiskStats: Total | | 15 TiB | 596 MiB/s | 245 MiB/s | 0:01:36 | 22.7 us | 18:05:08 | vm-11883 | VM_NAME
The VM backup session logs can be found on the vProxy under:
/opt/emc/vproxy/runtime/logs/recycle/vbackupd/date
VM backup session logs can also be found on the NetWorker server; however, the NetWorker server logs are subject to the jobsdb retention (72 hours, default). This means that 72 hours after completion the session logs are removed from the server. The vProxy logs are not impacted by the jobsdb retention.
Linux: /nsr/logs/policy/PolicyName/WorkflowName/
Windows: ..\Program Files\EMC NetWorker\nsr\logs\policy\PolicyName\WorkflowName
Cause
Resolution
Reset Change Block Tracking (CBT) for the VMs observing this issue.
See VMware documentation: Resetting Changed Block Tracking for VMware vSphere virtual machines (2139574)
It is recommended to engage VMware support if assistance with this procedure is required and to investigate any issues observed with CBT.
Additional Information
NVP vProxy: Understanding VMware VM backup levels shown in NetWorker