Netbackup Client DeDup & Accelerator savings report

[Volker_Spies1]

Hi Forum,

we are testing Client Side DeDup + Accelerator + DeDup Pool for our branch offices right now.

and we see results that we can't explain.

We have a client backup that states this:

3/31/2014 10:05:28 PM - Info bpbkar32(pid=5604) not using change journal data for <D:\>: unable to validate change journal usage <reason=filter checksum validation failed>
3/31/2014 10:05:28 PM - Info bpbkar32(pid=5604) not using change journal data for enumeration for <D:\> but will use it for change detection
4/1/2014 4:57:26 AM - Info bpbkar32(pid=5604) accelerator sent 6169297920 bytes out of 74969240576 bytes to server, optimization 91.8% 
4/1/2014 4:57:26 AM - Info bpbkar32(pid=5604) bpbkar waited 22862 times for empty buffer, delayed 736141 times.   
4/1/2014 4:57:29 AM - Info sv42080oel0197(pid=8976) StorageServer=PureDisk:sv42080oel0197; Report=PDDO Stats for (sv42080oel0197): scanned: 73212159 KB, CR sent: 3296883 KB, CR sent over FC: 0 KB, dedup: 95.5%, cache disabled
4/1/2014 4:57:30 AM - Info sv42080oel0197(pid=8976) Using the media server to write NBU data for backup sv43080bry0015_1396296089 to sv42080oel0197
4/1/2014 4:57:31 AM - Info bptm(pid=8976) EXITING with status 0 <----------        
4/1/2014 4:57:31 AM - Info sv42080oel0197(pid=8976) StorageServer=PureDisk:sv42080oel0197; Report=PDDO Stats for (sv42080oel0197): scanned: 1 KB, CR sent: 0 KB, CR sent over FC: 0 KB, dedup: 100.0%, cache disabled

I see a lot of information, but what I miss is what KB was actually send throug the connection to the DeDup pool?

The Backup took 6 hours for ~73GB, that would add up the ~3MB/s, wich is way to slow, but I assume that figures are calculated by the activity monitor?

Is there a log or something where we can see, how many was send to the dedup server in the datacenter? Why is the backup taking 6 hours? Scanning the local filesystem should be fast, we are using client dedup, the accelertator should take care only unique chunks were send over the line, and dedup at the target pool should be high as well.

So I need numbers about was was actually send to the DeDup pool and how long took the local filesystem scan with local dedup?

Thanks.

Volker

[ehudb36]

You can see from those 2 lines:

4/1/2014 4:57:26 AM - Info bpbkar32(pid=5604) accelerator sent 6169297920 bytes out of 74969240576 bytes to server, optimization 91.8% 

4/1/2014 4:57:29 AM - Info sv42080oel0197(pid=8976) StorageServer=PureDisk:sv42080oel0197; Report=PDDO Stats for (sv42080oel0197): scanned: 73212159 KB, CR sent: 3296883 KB, CR sent over FC: 0 KB, dedup: 95.5%, cache disabled

Accelerator sent 6169297920  bytes = 5.74 GB

MSDP wrote 3296883 KB = 3.144 GB

So if you don't use client-side deduplication, you actually sent 5.74 GB in 6 hours, which means 280 kb/s
Because you used accelerator you actually backed up at 3 MB/s which is almost 11 faster!

[Nicolai]

You need to take a look for the CR sendt - in this case "CR sent: 3296883 KB"

There is also a tech note with much more details:

Monitoring the deduplication rate

http://www.symantec.com/docs/HOWTO36313

[Volker_Spies1]

Thanks for the info, the howto helped a bit, but a don't get it completly, so I have to ask again. :)

Let take antother example:

Everything in KB, the source disk has ~31,457,000KB

4/2/2014 10:05:15 PM - Info bpbkar32(pid=4512) not using change journal data for <C:\>: hard link or reparse point change detected

4/2/2014 10:05:15 PM - Info bpbkar32(pid=4512) not using change journal data for enumeration for <C:\> but will use it for change detection

4/2/2014 10:30:35 PM - Info bpbkar32(pid=4512) accelerator sent 433504768 bytes out of 1071560704 bytes to server, optimization 59.5%

4/2/2014 10:30:35 PM - Info bpbkar32(pid=4512) bpbkar waited 1372 times for empty buffer, delayed 37356 times.

So the accelerator says that 423,344KB out of 1,046,446KB are unique and have to be backed up. Thats 40.5%.

4/2/2014 10:31:33 PM - Info sv42080oel0197(pid=7896) StorageServer=PureDisk:sv42080oel0197; Report=PDDO Stats for (sv42080oel0197): scanned: 1046466 KB, CR sent: 69031 KB, CR sent over FC: 0 KB, dedup: 93.4%, cache disabled

4/2/2014 10:31:42 PM - Info sv42080oel0197(pid=7896) Using the media server to write NBU data for backup sv43080bry0015_1396468898 to sv42080oel0197

4/2/2014 10:31:44 PM - Info bptm(pid=7896) EXITING with status 0 <----------       

Accoring ti HOWTO36313 this is client dedup. So the client dedup says that 69,031KB out of 1,046,466KB have to be backed up. Thats 6.6%

4/2/2014 10:31:44 PM - Info sv42080oel0197(pid=7896) StorageServer=PureDisk:sv42080oel0197; Report=PDDO Stats for (sv42080oel0197): scanned: 1 KB, CR sent: 0 KB, CR sent over FC: 0 KB, dedup: 100.0%, cache disabled

4/2/2014 10:31:45 PM - Info bpbrm(pid=6164) validating image for client sv43080bry0015       

4/2/2014 10:32:13 PM - Info bpbkar32(pid=4512) done. status: 0: the requested operation was successfully completed   

4/2/2014 10:32:13 PM - end writing; write time: 0:27:04

the requested operation was successfully completed(0)

Accoring to the HOWTO this is for TIR and Image Headers, dedup should be low? but is 100% for us?

So how do these numbers get together, especially Accelerator and Client DeDup? What was actually send over the line. Why are both functions do say they scan 1,046,446KB? Where do I find the ~31GB that are on the server?

I have many informations but I can't get the whole picture. Help! ;)

Best regards

Volker

[RLeon · Accepted solution]

4/2/2014 10:30:35 PM - Info bpbkar32(pid=4512) accelerator sent 433504768 bytes out of 1071560704 bytes to server, optimization 59.5%

While on the client, Accelerator sent 433,504,768 bytes (423,344KB) out of 1,071,560,704 bytes (1,046,446KB) to the Client-Side-Dedup plug-in (we're still on the client here). In other words, 423,344KB is the figure before any deduplication.

As for the reason why Accelerator reported to have found 1,046,446KB instead of 31,457,000KB, this is due to the way Accelerator 'tracks' changes in the file system. Apparently it has a quick and proprietary way of tracking directories/folders that contain changed data. A glimpse of this info could be found on this post by AbdulRasheed.

The list of directories Accelerator retrieved has a total size of 1,046,446KB. But not every file and its blocks have changed, so only the changed ones are sent. That gives us the figure 423,344KB, which is 40.5%, or, to put it in another way, "optimization 59.5%".

4/2/2014 10:30:35 PM - Info bpbkar32(pid=4512) bpbkar waited 1372 times for empty buffer, delayed 37356 times.

A bpbkar delay in NetBackup is 10ms. So 37356 delays cost around 6 minutes of not being able to send any data.
In your original post there were 736141 delays. That means at least 2 hours of the 6 hour backup were due to factors outside of NetBackup. You may want to start off by checking the network connection to the branch office. 73GB in 4 hours is around 5.2MB/s, much better than 3MB/s.

4/2/2014 10:31:33 PM - Info sv42080oel0197(pid=7896) StorageServer=PureDisk:sv42080oel0197; Report=PDDO Stats for (sv42080oel0197): scanned: 1046466 KB, CR sent: 69031 KB, CR sent over FC: 0 KB, dedup: 93.4%, cache disabled

Although it is true that Accelerator did initially report 1,046,446KB as we have established previously, but it ended up only having sent 423,344KB to the Client-Side-Dedup plug-in. So the part that says "scanned: 1046466 KB" from the above, could have been 'clearer' by saying something to the effect of: "423344KB of 1046466KB received from Accelerator". But hey.

So anyway, out of 1,046,466KB, the Client-Side-Dedup plug-in (yep, still on the client here) ended up sending only 69,031KB to the MSDP Media Server. This answers your question of how much data does the Client actually send out.
69,031KB of 1,046,466KB is around 6.6%, or to spin it another way: "dedup: 93.4%".
I would have preferred it to say 69,031KB of 423,344KB, which would have made it: "dedup: 83.7%".
But hey.

As for the TIR header at dedup: 100%, one of the NetBackup training videos on education.symantec.com explains it, verbatim:
".. The second number here, it used to just say zero, arh, because the Media Server wasn't doing anything, and then people kinda freaked out: 'Oh no! I'm getting zero percent Dedup!' So they changed it to be a hundred. But either way whether it's a zero or a hundred, it's a meaningless number. You know, the number I wanna look at is the number on the client."

The name of the video is "Managing NetBackup Deduplication in 5230 Appliances", fyi.

I'm guessing they changed it from 0% to 100% starting NetBackup 7.5, but didn't really update the documents, release notes or the online technotes to reflect this.

[Volker_Spies1]

Thanks a lot RLeon, that clarified almost everything!

Volker