Start a Conversation

Unsolved

This post is more than 5 years old

1189

November 3rd, 2017 06:00

Slow replication on some client backups (low network utilization, low cpu utilization)

There are some particular client backups of ours that are very slow to replicate. At first, I thought it may be a CPU limitation (our replication bandwidth usage goes from 100% when replicating our Exchange backups to 5%-10% on these particular client backups), but the job log shows 0% CPU:

2017-11-02 18:58:07 avtar Info <19841>: Backup #972 timestamp 2017-10-28 23:35:52 EDT created
2017-11-02 18:58:07 avtar Info <41359>: Backup #973 had been created by avtar version 7.4.101-58 as plugin 3016-VMWare Image
2017-11-02 18:58:07 avtar Info <6654>: Replicating backup 973, Label "[jobname]", 115.0 GB
2017-11-02 18:58:07 avtar Info <10632>: Using Client-ID='e1e925ca849d9ae6cf2d4b1e70e6defd7252a084'
2017-11-02 18:58:07 avtar Info <40062>: GSAN connected via: IPv4, retrieved Data Domain IPv4 hostname = [primaryDD]
2017-11-02 18:58:07 avtar Info <10538>: Connecting to Data Domain Server using cached handle #1 for DDR [primaryDD], LSU: avamar-1424809102
2017-11-02 18:58:07 avtar Info <41440>: Data Domain handle:1 capabilities:0x0020023B
2017-11-02 18:58:07 avtar Info <10543>: Data Domain login to [primaryDD] successful
2017-11-02 18:58:07 avtar Info <18845>: Restore mode - No Data Domain read compression.
2017-11-02 18:58:07 avtar Info <40062>: GSAN connected via: IPv4, retrieved Data Domain IPv4 hostname = [replicationDD]
2017-11-02 18:58:07 avtar Info <10606>: Connecting to Data Domain Destination Server "replicationDD[]" (LSU: avamar-1424881284, User: "********")
2017-11-02 18:58:07 avtar Info <10540>: - Resolved Data Domain Server name "[replicationDD]" to the IP address "[ip address]"
2017-11-02 18:58:07 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2017-11-02 18:58:07 avtar Info <0000>: - Connected to:
Data Domain System: [replicationDD]
Model:              DD2500
DDOS:               Data Domain OS 5.7.5.0-569395
Serial Number:      [serial number]
Capacity
Total:         25,680,578,347,008 (23.356 TB)
Available:      8,744,919,367,680 (7.9535 TB)
Used:          16,935,658,979,328 (15.403 TB)
Used logical: 786,769,741,721,921 (715.56 TB)
2017-11-02 18:58:07 avtar Info <41435>: - Data Domain configured in Stand-Alone mode.
2017-11-02 18:58:07 avtar Info <40206>: Setting default storage unit to 'avamar-1424881284' for handle 3
2017-11-02 18:58:07 avtar Info <41440>: Data Domain handle:3 capabilities:0x0020021B
2017-11-02 18:58:07 avtar Info <10609>: Data Domain Destination login to [replicationDD] complete
2017-11-02 18:58:07 avtar Info <42383>: id:14 VSR selected because file size is too small for NCR/Range-Replication (5BBDE79258A7BA79C2175E63E67A96DEC4FFC2D2)
2017-11-02 18:58:07 avtar Info <42383>: id:15 VSR selected because file size is too small for NCR/Range-Replication (BC654D0E0E59AF8568579BEF5C8C7FECD0B925FB)
2017-11-02 18:58:07 avtar Info <42383>: id:16 VSR selected because file size is too small for NCR/Range-Replication (A2F7AB22157140B7AC60482237210D2031EEA418)
2017-11-02 18:58:07 avtar Info <42383>: id:17 VSR selected because file size is too small for NCR/Range-Replication (C513FBC497E1218790D6B254764C3135EBE288A6)
2017-11-02 18:58:07 avtar Info <42383>: id:18 VSR selected because file size is too small for NCR/Range-Replication (8EA81C682F0550793878648A414C841DCCA73980)
2017-11-02 18:58:07 avtar Info <42383>: id:19 VSR selected because file size is too small for NCR/Range-Replication (CC7F68D095EFD99499A99FCA94D2FD8AF5EB5CE7)
2017-11-02 18:58:07 avtar Info <42383>: id:20 VSR selected because file size is too small for NCR/Range-Replication (4C388A06E8D41941973075002924894A8D3D25BC)
2017-11-02 18:58:07 avtar Info <42383>: id:21 VSR selected because file size is too small for NCR/Range-Replication (D7CFFB4639DAC7433A959A2BD91C68408B39CFA9)
2017-11-02 18:58:07 avtar Info <42383>: id:22 VSR selected because file size is too small for NCR/Range-Replication (2242EDC19E5015745818B73844860F16A94EF208)
2017-11-02 18:58:07 avtar Info <42384>: id:23 VSR selected because all base files are available (8918B0C27325D1FBBE2F004EBC8539D3ACCFFF2D)
2017-11-02 18:58:07 avtar Info <42383>: id:24 VSR selected because file size is too small for NCR/Range-Replication (6BB9834BAF86191A190A419C1FEC543995BAC93E)
2017-11-02 18:58:07 avtar Info <42383>: id:25 VSR selected because file size is too small for NCR/Range-Replication (3752E98BA868AE24A66A60391B8E2CFF05B520E9)
2017-11-02 18:58:07 avtar Info <42384>: id:26 VSR selected because all base files are available (CD69FC6495020D3E3C65415EED02E518BF85634E)
2017-11-02 18:58:07 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2017-11-02 18:58:07 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2017-11-02 19:02:37 avtar Info <8688>: Status 2017-11-02 19:02:37, 16 files, 115.0 GB (16 files, 17.70 GB, 15.39% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:07:37 avtar Info <8688>: Status 2017-11-02 19:07:37, 16 files, 115.0 GB (16 files, 17.70 GB, 15.39% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:07:37 avtar Info <8688>: Status 2017-11-02 19:07:37, 16 files, 115.0 GB (16 files, 17.70 GB, 15.39% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 19:12:38 avtar Info <8688>: Status 2017-11-02 19:12:38, 16 files, 115.0 GB (16 files, 17.70 GB, 15.39% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:17:38 avtar Info <8688>: Status 2017-11-02 19:17:38, 16 files, 115.0 GB (16 files, 17.70 GB, 15.39% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:22:38 avtar Info <8688>: Status 2017-11-02 19:22:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:22:38 avtar Info <8688>: Status 2017-11-02 19:22:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 19:27:38 avtar Info <8688>: Status 2017-11-02 19:27:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:32:38 avtar Info <8688>: Status 2017-11-02 19:32:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:37:38 avtar Info <8688>: Status 2017-11-02 19:37:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:37:38 avtar Info <8688>: Status 2017-11-02 19:37:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 19:42:38 avtar Info <8688>: Status 2017-11-02 19:42:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:47:38 avtar Info <8688>: Status 2017-11-02 19:47:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:52:38 avtar Info <8688>: Status 2017-11-02 19:52:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 19:52:38 avtar Info <8688>: Status 2017-11-02 19:52:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 19:57:38 avtar Info <8688>: Status 2017-11-02 19:57:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:02:38 avtar Info <8688>: Status 2017-11-02 20:02:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:07:38 avtar Info <8688>: Status 2017-11-02 20:07:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:07:38 avtar Info <8688>: Status 2017-11-02 20:07:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 20:12:38 avtar Info <8688>: Status 2017-11-02 20:12:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:17:38 avtar Info <8688>: Status 2017-11-02 20:17:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:22:38 avtar Info <8688>: Status 2017-11-02 20:22:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:22:38 avtar Info <8688>: Status 2017-11-02 20:22:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 20:27:38 avtar Info <8688>: Status 2017-11-02 20:27:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:32:38 avtar Info <8688>: Status 2017-11-02 20:32:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:37:38 avtar Info <8688>: Status 2017-11-02 20:37:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:37:38 avtar Info <8688>: Status 2017-11-02 20:37:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 20:42:38 avtar Info <8688>: Status 2017-11-02 20:42:38, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:47:39 avtar Info <8688>: Status 2017-11-02 20:47:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:52:39 avtar Info <8688>: Status 2017-11-02 20:52:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 20:52:39 avtar Info <8688>: Status 2017-11-02 20:52:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 20:57:39 avtar Info <8688>: Status 2017-11-02 20:57:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:02:39 avtar Info <8688>: Status 2017-11-02 21:02:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:07:39 avtar Info <8688>: Status 2017-11-02 21:07:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:07:39 avtar Info <8688>: Status 2017-11-02 21:07:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 21:12:39 avtar Info <8688>: Status 2017-11-02 21:12:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:17:39 avtar Info <8688>: Status 2017-11-02 21:17:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:22:39 avtar Info <8688>: Status 2017-11-02 21:22:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:22:39 avtar Info <8688>: Status 2017-11-02 21:22:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/ - (target server)
2017-11-02 21:27:39 avtar Info <8688>: Status 2017-11-02 21:27:39, 27 files, 155.0 GB (27 files, 18.45 GB, 11.91% new) 322MB   0% CPU [slowClient]_UAhK6VSxtAVfy0IB1R7n5Q#972::/VMFiles/2/
2017-11-02 21:30:56 avtar Info <18789>: Backup Replication Stats: original backup size: 123,480,333,642 (115.0 GB), precompression size: 123,480,333,642 (115.0 GB), network bytes sent: 14,215,330,604 (13.24 GB), sent: 11.51%
2017-11-02 21:31:00 avtar Info <18132>: ReplicateTo: File: avamar-1424881284/STAGING/e1e925ca849d9ae6cf2d4b1e70e6defd7252a084/BACKUP-18CAAA8D0DCFA2FA805D4F9B1981D074F098830D-1D3512B8A5E64D4/ddr_files.xml, original file size: 4,286 (4.186 KB), precompression size: 4,286 (4.186 KB), network bytes sent: 2,440 (2.383 KB), percent sent 56.93%

Any ideas? The replication that last ran was 575 GB with an 11.8% change rate which took 13 hours and 5 minutes over a 100 MB pipe.

It's a VM image replication (we have other VM images that replicate much more quickly).

No Responses!
No Events found!

Top