Session Backup and Session Task info detail.

PowerShell script exchange

Session Backup and Session Task info detail.

Veeam Logoby lucaliga » Tue Jan 19, 2016 4:38 pm

Ciao,

I have some problems in backup duration/speed and I'm making some "data mining".
I need help to understand the data I get from Session Backup (Get-VBRBackupSession) and Session Task (Get-VBRTaskSession).
Starting from example "Generate Veeam Session Report (HTML) from Powershell" link powershell-f26/generate-veeam-session-report-html-from-powershell-t22525.html this morning I got the email report of the last night backup:

Code: Select all
Backup job: Backup Dati
3 of 3 VMs processed 
monday 18 january 2016 21:00:12
Success 3 Start time 21:00:12 Total size 1,3 TB Backup size 860,0 GB   
Warning 0 End time 21:41:13 Data read 70,9 GB Dedupe 1,2x
Error 0 Duration 0:41:01  Transferred 4,8 GB Compression 1,4x

Where these data come from ? I execute:

Code: Select all
$Job = Get-VBRJob -Name "Backup Dati"
$LastSession = $Job.FindLastSession()

Which give me these data:
$LastSession.Result                                     Success
$LastSession.CreationTime                          monday 18 january 2016 21:00:12     is the above "Start time"
$LastSession.EndTime                                 monday 18 january 2016 21:41:13     is the above "End time"
$LastSession.BackupStats.DataSize              1463526859388           / 1024 / 1024 / 1024 /1024 = 1,3 TB is the above "Total size"
$LastSession.BackupStats.BackupSize           923455310848                       / 1024 / 1024 /1024 = 860,0 GB  is the above "Backup size"
$LastSession.Info.Progress.ReadSize             76096208896                        / 1024 / 1024 /1024 = 70,9 GB is the above "Data read"
$LastSession.BackupStats.DedupRatio           86                                           math (100 / 86)    = 1,2 is the above "Dedupe"
$LastSession.Info.Progress.TransferedSize     5179694972                         / 1024 / 1024 /1024 =  4,8 GB is the above "Transferred"
$LastSession.BackupStats.CompressRatio      73                                           math (100 / 73)    = 1,4 is the above "Compression"


Until here all clear but there are many other session data that I wish to understand:
Code: Select all
$LastSession.Info.BackupTotalSize               959052981248                            / 1024 / 1024 /1024 = 893 GB
$LastSession.Info.BackedUpSize                   15355302912                              / 1024 / 1024 /1024 = 14,3 GB
$LastSession.Info.Progress.TotalSize            1463510106112                / 1024 / 1024 / 1024 /1024 = 1,3 TB
$LastSession.Info.Progress.Duration             00:41:01.1160000           this is clear: is the above "Duration" and in sec = 2461
$LastSession.Info.Progress.AvgSpeed            41632914                       /1024/1024 = 39 MB/s


These value are what ? Especially AvgSpeed is quite obscure to me because (reverse engineering):
duration 2461 sec x AvgSpeed 41632914 bytes/sec = 102458601354 bytes = 95,42 Gb and a similar value doesn't appear in any upper value.

Could you please explain. Thanks.
lucaliga
Influencer
 
Posts: 11
Liked: 5 times
Joined: Mon Jan 11, 2016 8:37 am

Re: Session Backup and Session Task info detail.

Veeam Logoby PTide » Wed Jan 20, 2016 12:33 pm 1 person likes this post

Hi,

$LastSession.Info.BackupTotalSize = total size of the whole backup chain
$LastSession.Info.BackedUpSize = this session backup size
$LastSession.Info.Progress.TotalSize = total size of all machines in job
$LastSession.Info.Progress.Duration = self explanatory
$LastSession.Info.Progress.AvgSpeed = processing rate (see job stats)

Please see the attachment.

Thank you.
Attachments
params.png
params.png (403.7 KiB) Viewed 1539 times
PTide
Veeam Software
 
Posts: 3021
Liked: 246 times
Joined: Tue May 19, 2015 1:46 pm

Re: Session Backup and Session Task info detail.

Veeam Logoby lucaliga » Thu Jan 21, 2016 9:08 am

Ciao Pavel,

thanks for reply.
You wrote Veeam Session Report (HTML) "Total size" is not $LastSession.BackupStats.DataSize (like stated in above forum topic link) but is $LastSession.Info.Progress.TotalSize , this is OK because anyway this match my job session report value 1,3 TB.

Instead my job session report "Backup size" is 860,0 GB and dont match $LastSession.Info.BackedUpSize but match $LastSession.BackupStats.BackupSize. What's wrong ?

Code: Select all
PS C:\Users\administrator> echo $LastSession.Info.BackedUpSize ($LastSession.Info.BackedUpSize / 1024 / 1024 /1024)
15355302912
14,3007402420044


Code: Select all
PS C:\Users\administrator> echo $LastSession.BackupStats.BackupSize ($LastSession.BackupStats.BackupSize  / 1024 / 1024 /1024)
923455310848
860,034777641296


About $LastSession.Info.Progress.AvgSpeed = processing rate how it is calculated ? referring which size and time ?

Thanks for help.
lucaliga
Influencer
 
Posts: 11
Liked: 5 times
Joined: Mon Jan 11, 2016 8:37 am

Re: Session Backup and Session Task info detail.

Veeam Logoby PTide » Thu Jan 21, 2016 4:20 pm

Instead my job session report "Backup size" is 860,0 GB and dont match $LastSession.Info.BackedUpSize but match $LastSession.BackupStats.BackupSize. What's wrong ?
The thread you've mentioned was started in 2014 and is related to v7. Which version do you use?

About $LastSession.Info.Progress.AvgSpeed = processing rate how it is calculated ? referring which size and time ?

Please check here.
PTide
Veeam Software
 
Posts: 3021
Liked: 246 times
Joined: Tue May 19, 2015 1:46 pm

Re: Session Backup and Session Task info detail.

Veeam Logoby lucaliga » Thu Jan 21, 2016 7:11 pm

My version is 8.0.0.2084 and I want to give you some more info otherwise you dont undertand why my in-depth research.
The Job session in my example is "3 of 3 VMs processed" and Tasksession reports:

Code: Select all
VMName  StartTime-------------     StopTime--------------      SizeGB         ReadSizeGB  TransferredSizeGB   Duration   AvgSpeedMB
server04  18/01/2016 21:16:07    18/01/2016 21:40:33      180,00         66,30-------  1,98------------------00:24:25   53
server06  18/01/2016 21:09:41    18/01/2016 21:15:52      230,00         0,54--------- 0,17-----------------  00:06:10   13
server01  18/01/2016 21:02:12    18/01/2016 21:15:02      953,00         4,03--------- 2,68-----------------  00:12:49   8

Load: Source 43% > Proxy 22% > Network 59% > Target 27%


As you may see there is a big difference in speed between the VM. But all of them are on same ESxi on the same datastore and is the same backup repository. Moreover I have onother Job backup of two VM scheduled in very different time starting 03:30 at night that takes ever 4/5 hours with tasksession AvgSpeedMB varying from 5 to 8 (very poor) ...same datatore ...same backup repository . It gives me Load: Source 6% > Proxy 12% > Network 13% > Target 88%

The link you give me AvgSpeed = processing rate help me to understand there is no way to calculate by myself because time in ratio in not job duration but the time for tranfer data (without data compression/dedupe time, without read time and other). Because is ratio " read data (so yes, zeroes don't count) and the time it took to transfer data" May I suppose the AvgSpeed is only related to backup repository network speed access and disk speed ? Thus Is not related to other components in the data flow working ? I need to identify which part of the data pipe backup process is the critical/faulting one.

Thanks
lucaliga
Influencer
 
Posts: 11
Liked: 5 times
Joined: Mon Jan 11, 2016 8:37 am

Re: Session Backup and Session Task info detail.

Veeam Logoby PTide » Fri Jan 22, 2016 2:37 pm

As you may see there is a big difference in speed between the VM
Can you confirm that I/O load for all three VMs stayed the same for all the duration of backup session? Also how about network?

May I suppose the AvgSpeed is only related to backup repository network speed access and disk speed ?
That depends on which transport mode you use. For example with Network Mode vmdk data is retrieved via mgmt interface thus "Source" in bottleneck might be either ESXi NIC or production datastore, or both. With Hot-Add mode data flows through proxy-vm vNIC and "Source" would mean that it's the production storage what makes things to slow down. Please describe your backup infrastructure.

Regarding $LastSession.BackupStats.BackupSize and $LastSession.Info.BackedUpSize difference - I'll check with devs and will get to you shortly.

Thank you.
PTide
Veeam Software
 
Posts: 3021
Liked: 246 times
Joined: Tue May 19, 2015 1:46 pm

Re: Session Backup and Session Task info detail.

Veeam Logoby PTide » Tue Jan 26, 2016 12:56 pm

Update from developers:

PS C:\Users\administrator> echo $LastSession.Info.BackedUpSize ($LastSession.Info.BackedUpSize / 1024 / 1024 /1024)
15355302912
14,3007402420044
This figure represents size of the last restore point.

PS C:\Users\administrator> echo $LastSession.BackupStats.BackupSize ($LastSession.BackupStats.BackupSize / 1024 / 1024 /1024)
923455310848
860,034777641296
This figure represents the whole backup size (sum of all RPs required to get to the last RP). Both values should be the same when running full backup.

As I already mentioned - the behaviour of those undocumented fileds and properties may change from version to version, so I suggest you to consider using this report module.

Thank you.
PTide
Veeam Software
 
Posts: 3021
Liked: 246 times
Joined: Tue May 19, 2015 1:46 pm

Re: Session Backup and Session Task info detail.

Veeam Logoby lucaliga » Thu Jan 28, 2016 3:47 pm 1 person likes this post

Ciao Pavel,

I have many updated info got after days of logs analysis.
big difference in speed between the VM

the slowest backup VM is server04 which is the Veeam B&R server itself and the only backup proxy with default setup: "transport mode=Automatic selection" and Max concurrent tasks=2.

The backup session named "Backup Dati" is made by 3 VM task sessions and this is timing:

Code: Select all
18/01/2016  tasks period
overalljob  21:00:12------------------------------------------------21:41:13
server01    ---21:02:12---------21:15:02
server04    --------------------------------21:16:07------------21:40:33
server06    ---------------21:09:41---21:15:52


The sessions are not quite concurrent but seems sequential, moreover server04 has unexpected size read and duration. These job historical statistics with my note/doubts:

Code: Select all
Backupjob "Backup Dati"
18/01/2016 21:00:14 :: Job started at 18/01/2016 21:00:12
18/01/2016 21:00:15 :: Building VM list
18/01/2016 21:00:55 :: VM size: 1,3 TB
18/01/2016 21:00:56 :: Changed block tracking is enabled
18/01/2016 21:02:07 :: Preparing next VM for processing-------------------------this is for server01
18/01/2016 21:02:12 :: Preparing next VM for processing-------------------------this is for server06
18/01/2016 21:02:12 :: Processing server01
18/01/2016 21:09:41 :: Processing server06--------------------------------------[color=#4040FF]Why wait since 21:02:12 till 21:09:41 (0:07:28) before start processing ?[/color]
18/01/2016 21:09:41 :: Waiting for the next task
18/01/2016 21:15:53 :: Preparing next VM for processing-------------------------this is for server04
18/01/2016 21:16:06 :: Processing server04--------------------------------------Takes much time 0:24:26, see related session statistics below.
18/01/2016 21:40:33 :: All VMs have been queued for processing
18/01/2016 21:41:09 :: Removing '\\192.168.23.239\Backup_VM\Backup Dati\Backup Dati2016-01-11T210057.vrb' per retention policy
18/01/2016 21:41:13 :: Load: Source 53% > Proxy 24% > Network 57% > Target 29%
18/01/2016 21:41:13 :: Primary bottleneck: Network
18/01/2016 21:41:13 :: Job finished at 18/01/2016 21:41:13


Note server04 delayed since 21:02:07 until 21:15:53 (0:13:46): this is expected behavior because is the Veeam B&R server itself and backup is done in a sequential order: "placed at the bottom of the queue and wait for the resources assignment until all other job tasks are completed." ref vmware-vsphere-f24/quick-couple-of-questions-t25692.html


Code: Select all
server04 task session
18/01/2016 21:02:07 :: Waiting for completion of other tasks (VM is backup server - not a parallel task)
18/01/2016 21:15:53 :: Queued for processing at 18/01/2016 21:15:53
18/01/2016 21:15:54 :: Required backup infrastructure resources have been assigned
18/01/2016 21:16:07 :: VM processing started at 18/01/2016 21:16:07
18/01/2016 21:16:07 :: VM size: 180,0 GB
18/01/2016 21:16:09 :: Getting VM info from vSphere
18/01/2016 21:16:50 :: Inventorying guest system
18/01/2016 21:17:04 :: Excluding own configuration database from VSS snapshot
18/01/2016 21:17:04 :: Preparing guest for hot backup
18/01/2016 21:17:18 :: Creating snapshot
18/01/2016 21:17:21 :: Releasing guest
18/01/2016 21:17:31 :: Indexing guest file system
18/01/2016 21:17:38 :: Saving [vmware00_Datastore_03] server04/server04.vmx
18/01/2016 21:17:38 :: Saving [vmware00_Datastore_03] server04/server04.vmxf
18/01/2016 21:17:39 :: Saving [vmware00_Datastore_03] server04/server04.nvram
18/01/2016 21:17:40 :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [nbd]----------Backup proxy cannot backup itself in hot add mode thus use nbd=network mode
18/01/2016 21:17:40 :: Using backup proxy VMware Backup Proxy for disk Hard disk 2 [nbd]----------Backup proxy cannot backup itself in hot add mode thus use nbd=network mode
18/01/2016 21:17:42 :: Hard disk 1 (80,0 GB) 54,9 GB read at 44 MB/s [CBT]
18/01/2016 21:17:42 :: Hard disk 2 (100,0 GB) 11,4 GB read at 27 MB/s [CBT]
18/01/2016 21:18:08 :: Getting list of guest file system local users
18/01/2016 21:39:42 :: Saving GuestIndexData.zip
18/01/2016 21:39:43 :: Saving GuestMembers.xml
18/01/2016 21:39:45 :: Removing VM snapshot
18/01/2016 21:40:21 :: Publishing guest file system index to catalog
18/01/2016 21:40:22 :: Finalizing
18/01/2016 21:40:23 :: Truncating transaction logs
18/01/2016 21:40:27 :: Truncating SQL server transaction logs
18/01/2016 21:40:31 :: Swap file blocks skipped: 4,0 GB
18/01/2016 21:40:33 :: Busy: Source 96% > Proxy 36% > Network 5% > Target 2%
18/01/2016 21:40:33 :: Primary bottleneck: Source
18/01/2016 21:40:33 :: Network traffic verification detected no corrupted blocks
18/01/2016 21:40:33 :: Processing finished at 18/01/2016 21:40:33


Now looking at the two Hard disks related statistic rows there are many considerations to do:
1) I'm sure the ""read at...speed" is NOT a "read only activity" instead is (read source, network transport to repository, write to disk) AvgSpeed = processing rate we talk about upper.
2) All used space on each disks (54,9 GB and 11,4 GB) is read. Why ? We expected only changed data to be read.
3) It says [CBT] ?! BURP ! Expect is CBT disabled automatically on any VM that acts as backup proxy moreover VM server04 has ExtensionData.Config.ChangeTrackingEnabled = $false Did you agree with me ?

About the other backup job ever taking 4/5 hours is the backup 2 VM both containing IBM Domino (non-VSS application) thus pre-freeze/post-thaw is used to stop/start service. This statistic of the bigger one:

Code: Select all
Domino task session
19/01/2016 03:31:40 :: Queued for processing at 19/01/2016 03:31:40
19/01/2016 03:31:40 :: Required backup infrastructure resources have been assigned
19/01/2016 03:31:45 :: VM processing started at 19/01/2016 03:31:45
19/01/2016 03:31:45 :: VM size: 680,0 GB
19/01/2016 03:31:48 :: Getting VM info from vSphere
19/01/2016 03:31:56 :: Inventorying guest system
19/01/2016 03:32:04 :: Running pre-freeze script in the guest OS
19/01/2016 03:33:06 :: Preparing guest for hot backup
19/01/2016 03:33:14 :: Creating snapshot
19/01/2016 03:33:18 :: Releasing guest
19/01/2016 03:33:27 :: Running post-thaw script in the guest OS
19/01/2016 03:34:29 :: Indexing guest file system
19/01/2016 03:34:36 :: Saving [vmware00_Datastore_03] domino/domino.vmx
19/01/2016 03:34:36 :: Saving [vmware00_Datastore_03] domino/domino.vmxf
19/01/2016 03:34:37 :: Saving [vmware00_Datastore_03] domino/domino.nvram
19/01/2016 03:34:38 :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [hotadd]
19/01/2016 03:34:38 :: Using backup proxy VMware Backup Proxy for disk Hard disk 2 [hotadd]
19/01/2016 03:34:40 :: Changed block tracking has been disabled for backup proxy VM.------------[color=#4040FF]??????? weird see note below.[/color]
19/01/2016 03:35:35 :: Hard disk 1 (80,0 GB) 3,5 GB read at 5 MB/s [CBT]
19/01/2016 03:35:36 :: Hard disk 2 (200,0 GB) 102,9 GB read at 7 MB/s [CBT]
19/01/2016 03:35:40 :: Getting list of guest file system local users
19/01/2016 03:50:52 :: Using backup proxy VMware Backup Proxy for disk Hard disk 3 [hotadd]
19/01/2016 03:53:06 :: Hard disk 3 (400,0 GB) 260,5 MB read at 9 MB/s [CBT]
19/01/2016 07:32:25 :: Saving GuestIndexData.zip
19/01/2016 07:32:25 :: Saving GuestMembers.xml
19/01/2016 07:32:28 :: Removing VM snapshot
19/01/2016 07:34:48 :: Publishing guest file system index to catalog
19/01/2016 07:34:50 :: Finalizing
19/01/2016 07:34:52 :: Truncating transaction logs
19/01/2016 07:35:00 :: Swap file blocks skipped: 2,8 GB
19/01/2016 07:35:02 :: Busy: Source 7% > Proxy 13% > Network 21% > Target 78%
19/01/2016 07:35:02 :: Primary bottleneck: Target
19/01/2016 07:35:02 :: Network traffic verification detected no corrupted blocks
19/01/2016 07:35:02 :: Processing finished at 19/01/2016 07:35:02


The only info I found is "You will see warning messages during your VM backup if the changed block tracking is enabled and the VM has an active snapshot"...Yes, true, there is "an active snapshot" Veeam B&R created at 03:33:14. What do you think about ?

The long duration 4/5 hours is due reverse incremental we use...not so smart for a disk size=200GB used space=119,00GB and daily changes=102,9GB.
That's a lot of random I/O on the NAS, and likely why the system is showing the "target" as the bottleneck. I changed it to Forever forward incremental and now starting from 2th backup it takes 25 minutes: "Hard disk 2 (200,0 GB)110,2 GB read at 85 MB/s [CBT]" but the warning "Changed block tracking has been disabled for backup proxy VM." still remains.

Great improvement but anyway we are checking why these high daily changes rates on that disk.

Thanks for help and for the patience to read me.
lucaliga
Influencer
 
Posts: 11
Liked: 5 times
Joined: Mon Jan 11, 2016 8:37 am

Re: Session Backup and Session Task info detail.

Veeam Logoby PTide » Thu Jan 28, 2016 5:16 pm

Why wait since 21:02:12 till 21:09:41 (0:07:28) before start processing
I suspect that it was adding disks in hot-add mode. Please check session log for details regarding which transport mode was used.

All used space on each disks (54,9 GB and 11,4 GB) is read. Why ? We expected only changed data to be read.
CBT is reset every time proxy is used in hot-add mode. I'd check that in session info.

It says [CBT] ?! BURP ! Expect is CBT disabled automatically on any VM that acts as backup proxy moreover VM server04 has ExtensionData.Config.ChangeTrackingEnabled = $false Did you agree with me ?
CBT is only disabled for backup proxies servers using hot add processing mode. From your logs I can see that proxy backs up itself in network mode. However I'm curios why the paremeter ExtensionData.Config.ChangeTrackingEnabled is set to $false.

The only info I found is "You will see warning messages during your VM backup if the changed block tracking is enabled and the VM has an active snapshot"...Yes, true, there is "an active snapshot" Veeam B&R created at 03:33:14. What do you think about ?
Not sure that I follow you. It's OK to create a snapshot. What is your concern? Please clarify.

That's a lot of random I/O on the NAS, and likely why the system is showing the "target" as the bottleneck.
Correct.

"Changed block tracking has been disabled for backup proxy VM." still remains.
I got a little bit lost in your configuration. You have servers 01 04 and 06, how many of them have proxy role installed?
PTide
Veeam Software
 
Posts: 3021
Liked: 246 times
Joined: Tue May 19, 2015 1:46 pm

Re: Session Backup and Session Task info detail.

Veeam Logoby lucaliga » Thu Jan 28, 2016 7:21 pm 1 person likes this post

lucaliga Why wait since 21:02:12 till 21:09:41 (0:07:28) before start processing

PTide I suspect that it was adding disks in hot-add mode. Please check session log for details regarding which transport mode was used.


did you mean there is a limitation in quantity of disks could be added in hot-add mode in same job session ? one job two tasks/VM same datastore containing hard disk for both: contention issues ?

Server01
Code: Select all
........
18/01/2016 21:03:04 :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [hotadd]
18/01/2016 21:03:04 :: Using backup proxy VMware Backup Proxy for disk Hard disk 2 [hotadd]
18/01/2016 21:03:35 :: Hard disk 1 (80,0 GB) 2,2 GB read at 7 MB/s [CBT]----------------------------in vmware00_Datastore_03
18/01/2016 21:03:36 :: Hard disk 2 (273,0 GB) 198,0 MB read at 13 MB/s [CBT]------------------------in vmware00_Datastore_03
18/01/2016 21:04:28 :: Getting list of guest file system local users
18/01/2016 21:06:40 :: Using backup proxy VMware Backup Proxy for disk Hard disk 3 [hotadd]
18/01/2016 21:08:47 :: Hard disk 3 (600,0 GB) 1,6 GB read at 9 MB/s [CBT]---------------------------in vmware00_Datastore_02
18/01/2016 21:13:26 :: Saving GuestIndexData.zip
.....


Server06 full detail
Code: Select all
18/01/2016 21:02:07 :: Queued for processing at 18/01/2016 21:02:07
18/01/2016 21:02:07 :: Required backup infrastructure resources have been assigned -----------------this is done/hold since 21:02:12 till 21:09:41
18/01/2016 21:09:41 :: VM processing started at 18/01/2016 21:09:41
18/01/2016 21:09:41 :: VM size: 230,0 GB
18/01/2016 21:09:43 :: Getting VM info from vSphere
18/01/2016 21:09:48 :: Inventorying guest system
18/01/2016 21:09:51 :: Preparing guest for hot backup
18/01/2016 21:09:56 :: Creating snapshot
18/01/2016 21:09:59 :: Releasing guest
18/01/2016 21:10:07 :: Indexing guest file system
18/01/2016 21:10:28 :: Getting list of guest file system local users
18/01/2016 21:13:11 :: Saving [vmware00_Datastore_03] server06/server06.vmx
18/01/2016 21:13:12 :: Saving [vmware00_Datastore_03] server06/server06.vmxf
18/01/2016 21:13:13 :: Saving [vmware00_Datastore_03] server06/server06.nvram
18/01/2016 21:13:13 :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [hotadd]
18/01/2016 21:13:28 :: Using backup proxy VMware Backup Proxy for disk Hard disk 2 [hotadd]
18/01/2016 21:13:44 :: Hard disk 1 (80,0 GB) 237,5 MB read at 28 MB/s [CBT]----------------------------in vmware00_Datastore_03
18/01/2016 21:13:49 :: Hard disk 2 (150,0 GB) 319,0 MB read at 8 MB/s [CBT]----------------------------in vmware00_Datastore_02
18/01/2016 21:15:09 :: Saving GuestIndexData.zip
18/01/2016 21:15:10 :: Saving GuestMembers.xml
18/01/2016 21:15:12 :: Removing VM snapshot
18/01/2016 21:15:42 :: Publishing guest file system index to catalog
18/01/2016 21:15:42 :: Finalizing
18/01/2016 21:15:43 :: Truncating transaction logs
18/01/2016 21:15:46 :: Truncating SQL server transaction logs
18/01/2016 21:15:52 :: Busy: Source 26% > Proxy 18% > Network 63% > Target 51%
18/01/2016 21:15:52 :: Primary bottleneck: Network
18/01/2016 21:15:52 :: Network traffic verification detected no corrupted blocks
18/01/2016 21:15:52 :: Processing finished at 18/01/2016 21:15:52


CBT is reset every time proxy is used in hot-add mode. I'd check that in session info.

I agree
CBT is only disabled for backup proxies servers using hot add processing mode.

I agree
From your logs I can see that proxy backs up itself in network mode.

By design: Backup proxy cannot backup itself in hot add mode thus "transport mode=Automatic selection" failback to nbd=network mode

I totally agree with you. There is a detailed explaination in
http://forums.veeam.com/vmware-vsphere-f24/cktenabled-gets-set-to-false-after-backup-t15622.html
which also explain that ExtensionData.Config.ChangeTrackingEnabled is set to $false by Veeam B&R.
My BURP is about log says [CBT] even is cant use it, isn't using it.

It's OK to create a snapshot. What is your concern? Please clarify.

I dont understand the warning "Changed block tracking has been disabled for backup proxy VM." during a session backup of a VM not acting as proxy.

I got a little bit lost in your configuration. You have servers 01 04 and 06, how many of them have proxy role installed?

server04 is the only Veeam B&R and the only backup proxy.

Thanks.
lucaliga
Influencer
 
Posts: 11
Liked: 5 times
Joined: Mon Jan 11, 2016 8:37 am

Re: Session Backup and Session Task info detail.

Veeam Logoby PTide » Fri Jan 29, 2016 9:57 am

did you mean there is a limitation in quantity of disks could be added in hot-add mode
I mean that usually it takes some time to add disks in hot-add mode, depending on size of the disk. Even free proxy slots are available hot-add mode does not backup disks immediately.

server04 is the only Veeam B&R and the only backup proxy.
Ok, got it.

I dont understand the warning "Changed block tracking has been disabled for backup proxy VM." during a session backup of a VM not acting as proxy.
If you're 100% percent sure that you Domino machine does not and never did contain any proxy related components then please open a case with our support team since that is an unexpected behaviour and should be investigated. You can also mention that "log says [CBT] even is cant use it, isn't using it."

Don't forget to post your case ID in this thread.

P.S. Interesting research, your keen attention to details is highly appreciated.

Thank you.
PTide
Veeam Software
 
Posts: 3021
Liked: 246 times
Joined: Tue May 19, 2015 1:46 pm

Re: Session Backup and Session Task info detail.

Veeam Logoby lucaliga » Wed Feb 03, 2016 5:22 pm 1 person likes this post

Support case ID 01683957.

Now my longer backup take 15 min instead of 5 hours.

I took 17 days to collect all the following knowledge thus I want to share with others forum guys hope to save at least someone to waste a lot of time in googling tech docs ;-) .

Following the explanations of the Backup job statistics lines:

31/01/2016 03:31:23 :: Queued for processing at 31/01/2016 03:31:23
31/01/2016 03:31:23 :: Required backup infrastructure resources have been assigned
31/01/2016 04:45:13 :: VM processing started at 31/01/2016 04:45:12
31/01/2016 04:50:17 :: Using backup proxy VMware Backup Proxy for disk Hard disk 1 [hotadd]
31/01/2016 04:50:20 :: Changed block tracking has been disabled for backup proxy VM.
31/01/2016 04:51:13 :: Hard disk 1 (80,0 GB) 56,7 GB read at 125 MB/s [CBT]

1) the delay since 03:31:23 to 04:45:13 is because the only existing Backup Proxy has Max concurrent tasks = 2. Here "tasks" mean VM hard disks. At that time 2 Hard Disk are already in backup by other job's tasks so it has to wait. Online help dont focus about this and my misunderstanding was consider "tasks" as job/session instead "Max concurrent tasks" means " Max concurrent Hard disk".

2) " Changed block tracking has been disabled for backup proxy VM." means during backup runtime of one VM the Backup Proxy assigned to the task is the one named "VMware Backup Proxy" (mentioned in previous log line) and IS A VM and USE HOTADD MODE thus in this moment Veeam B&R change the VM attribute ChangeTrackingEnabled to $false for the VM acting as Backup Proxy. In other words if you have (like me) only one Backup Proxy you could never backup himself in CBT because CBT is disabled for the VM. All disk data tracks will ever be saved. Trick: leave the backup proxy VM the more light possible in space used.

3) "Hard disk 1 (80,0 GB) 56,7 GB read at 125 MB/s [CBT]" the hard disk has size 80,0 GB and INSIDE GUEST OS used space=35,00GB why 56,7 GB read ?
Provisioned size of VM's disk got from hypervisor is 80,0 GB. The DATA BLOCKS used inside guest is 56,7 GB maybe/often are deleted files thus to reduce it to the real used space of 35,00GB (and make faster backup) execute inside guest OS defrag and sdelete /Z UNLESS your disks are thin provisioned see https://forums.veeam.com/veeam-backup-replication-f2/backups-slowed-way-down-after-sdelete-on-drives-t22934.html#p117338

4) 125 MB/s is AvgSpeed = processing rate NOT a "read at" only activity as you may suppose by the preceding "read at ". It is more or less read source+network transport to repository+repository write to disk. No way you could calculate by yourself because is ratio using read data (and yes, zeroes data don't count) and the time (NOT job duration but) it took to transfer data (without data compression/dedupe time, without read time and other). My suggest is dont trust in AvgSpeed as the real focus for backup duration issue (Like I do for the first 4 days of throubleshooting).

5) [CBT] means Veeam B&R asks to Esxi “give me the changed block only” and Esxi send back only changed blocks since last backup...if this is possible....otherwise if the VM or the scsi disk are ChangeTrackingEnabled = $false then Esxi returns ALL data blocks. Veeam B&R logs [CBT] meaning “I request CBT”. It doesn't mean “I got CBT”. This is mine 3rd misunderstand.

6) This is only for IBM (former Lotus) Domino. We got why VM with Domino inside has high daily changes rates disks. Database Maintenance Tool (DBMT) the new V9.0 tools is used to replace command compact: by design DBMT when compacting use ONLY copy-style this means example one mail db 9GB is copied in temp file, filtering unneeded data (trash, softly deleted etc.), at last renamed to original. This has three side effect.
a) the original file is logical deleted -> disk data blocks remain "occupied" until reused or reclaimed-> next backup still will backup these 9GB data blocks
b) the file is newly created so next time you will have full backup of its 9GB. (plus 9GB of point a)
c) OS disk need at least 9GB continuos free space to have the new file copied in contiguous blocks otherwise the new file will has defrag issue.

reference
http://ab1osborne.blogspot.it/2014/07/busting-dbmt-pre-allocation-myth.html
http://blog.nashcom.de/nashcomblog.nsf/dx/domino-9.0.1-dbmt-compact-file-pre-alloc.htm
http://www-01.ibm.com/support/docview.wss?rs=203&uid=swg21084388

Regards/ciao
lucaliga
Influencer
 
Posts: 11
Liked: 5 times
Joined: Mon Jan 11, 2016 8:37 am


Return to PowerShell



Who is online

Users browsing this forum: No registered users and 4 guests