Slow backups since ESXi 5.1 update 2

[briguyiu]

Is anyone experiencing issues with extremely slow processing and backups after updating your hosts and vCenter ESXi 5.1 to update 2? I will probably open a support case soon, but just wanted to see if anybody else was seeing the same thing. My jobs went from 55-65 mb/s on some down to around 10 mb/s consistently. I am using hotadd, and a job that used to take around 25 minutes, is taking almost and hour and a half. It's almost like parallel processing isn't running correctly.

[Vitaliy S.]

Hi Brian,

What are your full bottleneck stats for the jobs that have degraded performance?

Thank you!

[veremin]

Also, if I were you I would double check that CBT was used, as well as, Hot Add backup mode. Anyway, the backup session statistics will clarify the situation. Thanks.

[Gostev]

This definitely has nothing to deal with the ESXi update.

[briguyiu]

CBT was used in all.

Here is what it looked like when things were great:

2/9/2014 8:29:40 PM :: Load: Source 21% > Proxy 16% > Network 36% > Target 75%



Here is what it looks like now:

2/19/2014 1:10:06 PM :: Load: Source 21% > Proxy 44% > Network 24% > Target 75%

[briguyiu]

Here's an example of one of the servers in the 2/19 job today.

Code: Select all

2/19/2014 12:03:19 PM :: Queued for processing at 2/19/2014 12:03:19 PM
2/19/2014 12:05:10 PM :: Required backup infrastructure resources have been assigned
2/19/2014 12:06:33 PM :: VM processing started at 2/19/2014 12:06:32 PM
2/19/2014 12:06:33 PM :: VM size: 220.0 GB (98.7 GB used)
2/19/2014 12:08:01 PM :: VMware Tools are not up to date, some functionality may be affected
2/19/2014 12:08:27 PM :: Indexing guest file system
2/19/2014 12:09:39 PM :: Inventoring guest system
2/19/2014 12:10:32 PM :: Preparing guest for hot backup
2/19/2014 12:11:54 PM :: Creating snapshot
2/19/2014 12:12:03 PM :: Releasing guest
2/19/2014 12:23:04 PM :: Saving [Prod-VMFS02] CORP-SP-01/TESTMAXSP2010WB.vmx
2/19/2014 12:23:25 PM :: Saving [Prod-VMFS02] CORP-SP-01/TESTMAXSP2010WB.vmxf
2/19/2014 12:23:57 PM :: Saving [Prod-VMFS02] CORP-SP-01/TESTMAXSP2010WB.nvram
2/19/2014 12:26:52 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [hotadd]
2/19/2014 12:28:51 PM :: Hard disk 1 (80.0 GB)
2/19/2014 12:48:43 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 2 [hotadd]
2/19/2014 12:49:04 PM :: Hard disk 2 (80.0 GB)
2/19/2014 12:52:21 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 3 [hotadd]
2/19/2014 12:52:38 PM :: Hard disk 3 (30.0 GB)
2/19/2014 12:56:19 PM :: Using backup proxy VMware Backup Proxy for disk Hard disk 4 [hotadd]
2/19/2014 12:56:41 PM :: Hard disk 4 (30.0 GB)
2/19/2014 12:59:41 PM :: Saving GuestIndexData.zip
2/19/2014 12:59:54 PM :: Publishing guest file system index to catalog
2/19/2014 1:00:02 PM :: Finalizing
2/19/2014 1:04:28 PM :: Truncating transaction logs
2/19/2014 1:04:37 PM :: Removing VM snapshot
2/19/2014 1:08:13 PM :: Swap file blocks skipped: 325.0 MB
2/19/2014 1:08:14 PM :: Busy: Source 54% > Proxy 32% > Network 14% > Target 88%
2/19/2014 1:08:14 PM :: Primary bottleneck: Target
2/19/2014 1:08:15 PM :: Network traffic verification detected no corrupted blocks
2/19/2014 1:08:15 PM :: Processing finished at 2/19/2014 1:08:15 PM

[foggy]

Brian, I do not see the [CBT] tag next to the hard disks processing lines, so seems that the entire image is being read, causing the job to run longer. Have you tried to reset CBT manually? Do you see the same behavior for all the jobs/VMs?

[tsightler]

I do not see the [CBT] tag next to the hard disks processing lines

That's because the "Copy to Clipboard" function in the GUI doesn't copy the performance or [CBT] tag information (looks like a bug to me). For example, here's a small snippet from one of my VM logs last night using the "Copy to Clipboad" feature:

Code: Select all

2/20/2014 1:02:31 AM :: Hard disk 1 (40.0 GB)

But here's what it actually shows in the GUI:

Code: Select all

2/20/2014 1:02:31 AM :: Hard disk 1 (40.0 GB) 656.0MB read at 19MB/s [CBT]

Based on his screenshot I think it's pretty obvious that CBT is being used. The second "slower" screenshot shows much less data read even than the first, although there is also somewhat more processed data on the second screenshot. I'm not sure if there are multiple jobs running at the same time or if this is the only job so it's a little difficult to make a judgement but there seems to be some delays in the log snippet posted where there's nothing really going on. Some of that time is easily explained by the fact that the second job processed about 50% more change data, however I'd still say it looks like there are delays.

[foggy]

That's because the "Copy to Clipboard" function in the GUI doesn't copy the performance or [CBT] tag information (looks like a bug to me).

That made me also wonder - why disk processing rate was not there as well. Ok, I've passed this to R&D.

Based on his screenshot I think it's pretty obvious that CBT is being used. The second "slower" screenshot shows much less data read even than the first, although there is also somewhat more processed data on the second screenshot.

Right, I've missed the "Read" counter.

[tsightler]

Thanks for submitting the "Copy to Clipboard" issue to R&D, it's bugged me for a while now, but I guess not enough to bring it up.

So back to the OP's problem, to me the smoking gun is this small section of the log:

Code: Select all

2/19/2014 12:12:03 PM :: Releasing guest
2/19/2014 12:23:04 PM :: Saving [Prod-VMFS02] CORP-SP-01/TESTMAXSP2010WB.vmx

There's 11 minutes between releasing guest and when the backup actually starts doing anything. Backup resources are already assigned at this point so there's no reason for this delay, I'd expect it to be no more than 20-30 seconds. I don't think it was mentioned what version of B&R this is, does it happen to still be a 6.x version? I'm thinking this may be the well know snapshot tracker issue, although I thought that delay happened at an earlier point. A support case is probably the correct path for investigation of this issue as this likely needs some log diving.

[briguyiu]

You guys are correct about the Copy to Clipboard. It was indeed using CBT, as Tom suggested. The version is 7 patched to R2. There are some other things at play here that I just discovered, so before I open a case with Veeam, I'm going to head down that path. We had a couple of situations pointed out here http://kb.vmware.com/selfservice/micros ... Id=2049103, and so now I'm a little concerned that there may be some corruption issues. I have a case open with Dell and VMware to find out if we are indeed suffering from this issue, which could potentially be the root cause of the slowdown we are experiencing in Veeam. Thanks again guys, and I'll keep this post updated with any findings.

[briguyiu]

Just a quick update. In working with VMware and Dell, we haven't found anything that leads us to believe we are still facing any of the issues with corruption or locking as of yet, but both cases are still open. I did end up opening a case with Veeam, and it is case ID# 00522822. After looking at one set of logs we haven't really gotten very far in figuring out what is going on. Hopefully next week we can drill down a little further.

[briguyiu]

Another update. Seemingly, disabling System Center Endpoint Protection has stopped the slowness. The processing rate isn't great all the time, but that's just b/c of the amount of reading it's doing with CBT enabled...I think. The timeframe has returned to normal though. I have a couple of questions on this though...

1. When hotadd is used, are the drives supposed to come online ever and show up in my computer? This is happening some of the time, and I'm wondering if this isn't why the jobs slowed way down if the real-time scanning started scanning those drives. Other times, I'm pretty sure they JUST show up in disk manager.
2. Are there any processes, folders or anything else that should be excluded other than the vrb, vbk, vib, and vbm files?

[foggy]

1. When hotadd is used, are the drives supposed to come online ever and show up in my computer? This is happening some of the time, and I'm wondering if this isn't why the jobs slowed way down if the real-time scanning started scanning those drives. Other times, I'm pretty sure they JUST show up in disk manager.

Well, not sure this is expected, however you're not the first one to report similar behavior. Though, the question should be addressed to VMware itself.

2. Are there any processes, folders or anything else that should be excluded other than the vrb, vbk, vib, and vbm files?

You can also exclude Veeam database files and logs folder. Please see the following topics on different antivirus issues for some details:

Slowness at Beginning of VM Processing
TrendMicro AV exlusions for Veeam Backup & Replication