Slow full backups using deduplication

Last post 01-21-2020, 4:26 AM by Liberje. 8 replies.
Sort Posts: Previous Next
  • Slow full backups using deduplication
    Posted: 01-09-2020, 5:26 AM

    Hello,

    We're experiencing some issues and I'm unable to find a decent explanation.  We're running full backups with deduplication and are seeing really long duration times.


    Example:

    Client with file system agent

    100GB application size

    Client side dedup enabled

     

    When running a full backup, it will take almost 1.5 hours for this job to complete, although it only writes about 2gb to disk . We throttled the connection between client and MA to 7.5Mbyte/s which we can see is always flatlining around this speed. In theory, this means about 50GB going over the line. Why is so much data going over the line if dedup is happening on the client and only about 2GB is being written to disk? Is it normal to have so much excessive amount of network traffic?

    Thank you.

  • Re: Slow full backups using deduplication
    Posted: 01-09-2020, 6:40 AM

    Hi Liberje

    Could you please share the CVPerfMgr.log from the MediaAgent after a completion of a Full Backup Job. This will be useful to identify which component could be taking the most time. 

    Regards

    Winston 

  • Re: Slow full backups using deduplication
    Posted: 01-09-2020, 8:06 AM

    Hello Winston,

     

    Thank you for your answer. I have never used CVPerfMgr, it looks very helpful.

     

    See below:

     

    8104  d78   12/22 23:35:47 1827452 *CVPERFLOG*|43|2255857|16|1577048783|1577045183|1577054147|1577050547|1577048783|1577045183|1577054147|1577050547|50|1|*CVCOUNTER*|502|1|1577050547|284|0|0|0|0|*|437067555037|0|*CVCOUNTER*|501|1|1577050547|2628|0|0|0|0|*|110994402244|0|*CVCOUNTER*|503|1|1577050547|1350|0|0|0|0|*|112113406325|0|*CVCOUNTER*|520|1|1577050547|689|0|0|0|0|*|0|0|*CVCOUNTER*|509|1|1577050547|0|0|0|0|0|*|0|0|*CVCOUNTER*|549|1|1577050547|111|0|0|0|0|*|0|0|*CVCOUNTER*|544|1|1577050547|49|0|0|0|0|*|0|0|*CVCOUNTER*|545|1|1577050547|240|0|0|0|0|*|0|0|*CVCOUNTER*|1004|505|1577050547|4017|0|0|0|0|*|0|0|*CVCOUNTER*|1001|505|1577050547|1232|0|0|0|0|*|0|0|*CVCOUNTER*|5001|2057|1577050547|4940|0|0|0|0|*|0|0|*CVCOUNTER*|5002|2057|1577050547|0|0|0|0|0|*|0|0|*CVCOUNTER*|5003|2057|1577050547|129|0|0|0|0|*|0|0|*CVCOUNTER*|5804|2057|1577050547|0|0|0|0|0|*|0|0|*CVCOUNTER*|5005|2057|1577050547|202|0|0|0|0|*|1837099830|0|*CVCOUNTER*|6014|5005|1577050547|139|0|0|0|0|*|1822744259|0|
    8104  d78   12/22 23:35:47 1827452
    |*2255857*|*Perf*|1827452| =======================================================================================
    |*2255857*|*Perf*|1827452| Job-ID: 1827452            [Pipe-ID: 2255857]            [App-Type: 43]            [Data-Type: 1]
    |*2255857*|*Perf*|1827452| Stream Source:   "CLIENT"
    |*2255857*|*Perf*|1827452| Simpana Network medium:   Pipeline
    |*2255857*|*Perf*|1827452| Head duration (Local):  [22,December,19 22:06:23  ~  22,December,19 23:35:47] 01:29:24 (5364)
    |*2255857*|*Perf*|1827452| Tail duration (Local):  [22,December,19 22:06:23  ~  22,December,19 23:35:47] 01:29:24 (5364)
    |*2255857*|*Perf*|1827452| -----------------------------------------------------------------------------------------------------
    |*2255857*|*Perf*|1827452|     Perf-Counter                                  Time(seconds)              Size
    |*2255857*|*Perf*|1827452| -----------------------------------------------------------------------------------------------------
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| Windows File System Agent
    |*2255857*|*Perf*|1827452|  |_Buffer allocation............................       284              437067555037  [407.05 GB] [5159.80 GBPH]
    |*2255857*|*Perf*|1827452|  |_Read.........................................      2628              110994402244  [103.37 GB] [141.60 GBPH]
    |*2255857*|*Perf*|1827452|  |_Pipeline write...............................      1350              112113406325  [104.41 GB] [278.44 GBPH]
    |*2255857*|*Perf*|1827452|  |_Open File....................................       689                          
    |*2255857*|*Perf*|1827452|  |_FSDM Load Library............................         -                          
    |*2255857*|*Perf*|1827452|  |_FindFirstFile Open...........................       111                          
    |*2255857*|*Perf*|1827452|  |_Index V2 Id calculation......................        49                          
    |*2255857*|*Perf*|1827452|  |_Index V2 Id Send.............................       240                          
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| Reader Pipeline Modules
    |*2255857*|*Perf*|1827452|  |_CVA Wait to received data from reader........      4017                          
    |*2255857*|*Perf*|1827452|  |_CVA Buffer allocation........................      1232                          
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| SDT-Tail: Writer Tasks
    |*2255857*|*Perf*|1827452|  |_DSBackup: BufferRecieve......................      4940                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Update Restart Info................         -                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Update Index.......................       129                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Update Restart Info Index..........         -                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Media Write........................       202                1837099830  [1.71 GB] [30.49 GBPH]
    |*2255857*|*Perf*|1827452|    |_Writer: DM: Physical Write.................       139                1822744259  [1.70 GB] [43.97 GBPH]
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| ----------------------------------------------------------------------------------------------------
    8104  e10   12/22 23:35:59 1827452 *CVPERFLOG*|1|2255857|7|1577054156|1577050556|1577054159|1577050559|1577054156|1577050556|1577054159|1577050559|50|7|*CVCOUNTER*|1004|505|1577050559|3|0|0|0|0|*|0|0|*CVCOUNTER*|1001|505|1577050559|0|0|0|0|0|*|0|0|*CVCOUNTER*|5001|2057|1577050559|1|0|0|0|0|*|0|0|*CVCOUNTER*|5002|2057|1577050559|0|0|0|0|0|*|0|0|*CVCOUNTER*|5804|2057|1577050559|0|0|0|0|0|*|0|0|*CVCOUNTER*|5005|2057|1577050559|0|0|0|0|0|*|3168|0|*CVCOUNTER*|6014|5005|1577050559|0|0|0|0|0|*|2100320|0|
    8104  e10   12/22 23:35:59 1827452
    |*2255857*|*Perf*|1827452| =======================================================================================
    |*2255857*|*Perf*|1827452| Job-ID: 1827452            [Pipe-ID: 2255857]            [App-Type: 1]            [Data-Type: 7]
    |*2255857*|*Perf*|1827452| Stream Source:   "MEDIA AGENT"
    |*2255857*|*Perf*|1827452| Simpana Network medium:   Pipeline
    |*2255857*|*Perf*|1827452| Head duration (Local):  [22,December,19 23:35:56  ~  22,December,19 23:35:59] 00:00:03 (3)
    |*2255857*|*Perf*|1827452| Tail duration (Local):  [22,December,19 23:35:56  ~  22,December,19 23:35:59] 00:00:03 (3)
    |*2255857*|*Perf*|1827452| -----------------------------------------------------------------------------------------------------
    |*2255857*|*Perf*|1827452|     Perf-Counter                                  Time(seconds)              Size
    |*2255857*|*Perf*|1827452| -----------------------------------------------------------------------------------------------------
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| Reader Pipeline Modules
    |*2255857*|*Perf*|1827452|  |_CVA Wait to received data from reader........         3                          
    |*2255857*|*Perf*|1827452|  |_CVA Buffer allocation........................         -                          
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| SDT-Tail: Writer Tasks
    |*2255857*|*Perf*|1827452|  |_DSBackup: BufferRecieve......................         1                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Update Restart Info................         -                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Update Restart Info Index..........         -                          
    |*2255857*|*Perf*|1827452|  |_DSBackup: Media Write........................         -                      3168  [3.09 KB]
    |*2255857*|*Perf*|1827452|    |_Writer: DM: Physical Write.................         -                   2100320  [2.00 MB]
    |*2255857*|*Perf*|1827452|
    |*2255857*|*Perf*|1827452| ----------------------------------------------------------------------------------------------------

     

    Many thanks. 

     

    Jeremy

  • Re: Slow full backups using deduplication
    Posted: 01-13-2020, 6:30 AM

    Hi Jeremy 


    Thank you very much for sharing the logs. 

    From the review of the CVPerfMgr.log the bottleneck seems to be the transfer time between the Client and the MediaAgent:

    • |*2255857*|*Perf*|1827452|  |_CVA Buffer allocation........................      1232
    •                          
    • |*2255857*|*Perf*|1827452|
    • |*2255857*|*Perf*|1827452| SDT-Tail: Writer Tasks
    • |*2255857*|*Perf*|1827452|  |_DSBackup: BufferRecieve......................      4940  
     
    As you can see in the logs (in seconds) the majority of the time is between the Reader (client) and the time it takes to buffer the reqest on the Writer (MediaAgent) 
    Although we are leveraging Source-side Deduplication, it will still need to reach out to the Destination MediaAgent to do signature comparison before it increments the references in the DDB.
     
    If you would like to minimize the traffic between the Client and the MediaAgent (as you have mentioned you are currently using network throttling), you can consider doing Synthetic Fulls. 
     
    The purpose of Synthetic Fulls is to use the last full and all the incrementals to create the next Synthetic Full (meaning the MediaAgent will read from Disk and update the reference of the DDB when doing the Synthetic Full Process) - https://documentation.commvault.com/commvault/v11/article?p=11694.htm
     
    Regards
     
    Winston 
  • Re: Slow full backups using deduplication
    Posted: 01-13-2020, 8:45 AM

    Hello Winston,

     

    Thank you for your answer! Appreciate it.

     

    We however have found an issue with the disk library, which is rather slow.

     

    However, the issue is more complicated.

     

    When we're doing deduped full backups with source side dedup, it should only transfer the new signatures right? So let's say I run a new full backup, right after the first one. There should barely be any new signatures. What we see is, let's says for 100GB application data, about 50GB of data going over the line, although there aren't no new signatures to be added.

     

    Do you have any idea why the network overhead is so large?

     

    Thanks

     

    Jeremy

  • Re: Slow full backups using deduplication
    Posted: 01-19-2020, 4:44 AM

    Hi Jeremy 

    Do you have any Source Side Cache configured on the Client?

    By design when leveraging Source Side Deduplication it will result in two behavior (The signature is first compared in the local cache):

    • If the signature exists the block is discarded.
    • If the signature does not exists in the local cache, it is sent to the MediaAgent.
    The default cache configuration is 4096MB, so if the block doesn't exist in the cache this could be why additional signature are being sent over the wire. 
     
    Regards
     
    Winston
  • Re: Slow full backups using deduplication
    Posted: 01-20-2020, 3:58 AM

    Hello Winston,

     

    Source Side Cache is configured yes.

    We did some additional tests with a subclient of 13 files (12GB is size)

    First full we see Commvault writing about 9-10GB to disk. The next full (right after it) Commvault reports only writing a couple of megabytes to disk. However, we did a wireshark trace and see more than 1.5GB going over the wire. That's way too much traffic for 13 unmodified files and not at all useful on the remote location with limited bandwidth.

     

    Regards,

    Jeremy

  • Re: Slow full backups using deduplication
    Posted: 01-21-2020, 4:00 AM

    Hi Jeremy 

    From the current findings I believe the additional writes over the network could be due to signature update and metadata references that needs to be cross-verified with the DDB, but the actual writes to Disk is only in megabytes. 

    At this point it might it would be good to engage Commvault support and share the findings. 

    Support will provide further findings and details on signature update and transfer when using Source Side Dedupe and provide recommendation to further reduce network utilization. 

    Regards

    Winston 

  • Re: Slow full backups using deduplication
    Posted: 01-21-2020, 4:26 AM

    Hello Winston,

    I think you might be right.

    I have engaged Commvault Support and will await their further feedback.

    Thanks for your help.

    Regards,

    Jeremy

The content of the forums, threads and posts reflects the thoughts and opinions of each author, and does not represent the thoughts, opinions, plans or strategies of Commvault Systems, Inc. ("Commvault") and Commvault undertakes no obligation to update, correct or modify any statements made in this forum. Any and all third party links, statements, comments, or feedback posted to, or otherwise provided by this forum, thread or post are not affiliated with, nor endorsed by, Commvault.
Commvault, Commvault and logo, the “CV” logo, Commvault Systems, Solving Forward, SIM, Singular Information Management, Simpana, Commvault Galaxy, Unified Data Management, QiNetix, Quick Recovery, QR, CommNet, GridStor, Vault Tracker, InnerVault, QuickSnap, QSnap, Recovery Director, CommServe, CommCell, SnapProtect, ROMS, and CommValue, are trademarks or registered trademarks of Commvault Systems, Inc. All other third party brands, products, service names, trademarks, or registered service marks are the property of and used to identify the products or services of their respective owners. All specifications are subject to change without notice.
Close
Copyright © 2020 Commvault | All Rights Reserved. | Legal | Privacy Policy