Video Screencast Help

Progress of Optimized Duplication

Created: 17 Sep 2012 | 1 comment
Morten Seeberg's picture

Is there any way of seeing actual progress of the entire Optimized Duplication job?

We are seeing some MSDP->MSDP jobs running for several days (which might be OK, 1-2Tb over 3-4MBit connections. Thing is, that if I track the fragment duplication in bpdm logs, I see all of the fragments finishing pretty fast, and also bpimagelist shows that copies exist in both source and destination location.

But the job hangs at 99% for a VERY long time, and nothing really happens in the bpdm logs while this happens....
(PS, yes I know the job below is not one of the big ones, just an example job :-) ).

bpdm log:

11:13:13.843 [3616.2868] <4> copy_data: successfully copied (duplicate-optimized) backup id CLIENTNAME.Domain.Local_1347582047, copy 1, fragment 7, 38238764 Kbytes at 19895298.647 Kbytes/sec
(Last fragment of the image)
11:13:14.921 [3616.2868] <2> add_to_validate_image_list: Adding to val_img_list: CLIENTNAME.Domain.Local_1347582047_C2_F7_R20
11:13:14.921 [3616.2868] <2> add_to_validate_image_list: added CLIENTNAME.Domain.Local_1347582047_C2_F7_R20 to val_img_list
11:13:14.921 [3616.2868] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver.domain.local, query type 70
11:13:14.921 [3616.2868] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1530] in failed cache ERR=11001 NAME=randomclient.domain.local SVC=NULL
11:13:14.921 [3616.2868] <8> vnet_cached_getaddrinfo: [vnet_addrinfo.c:1273] vnet_cached_getaddrinfo_and_update() failed 6 0x6
11:13:15.046 [3616.2868] <2> vnet_pbxConnect: pbxConnectEx Succeeded
11:13:15.046 [3616.2868] <2> logconnections: BPDBM CONNECT FROM 10.211.5.42.52641 TO 10.201.28.34.1556 fd = 1112
11:13:15.046 [3616.2868] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
11:13:15.109 [3616.2868] <2> db_end: Need to collect reply
11:13:15.515 [3616.2868] <2> bp_sts_open_image: STH set to STS_SA_IMAGE
11:13:15.515 [3616.2868] <2> construct_sts_isid: master_server masterserver.domain.local, client CLIENTNAME.Domain.Local, backup_time 1347582047, copy_number 1, stream_number 0, fragment_number 0, resume_number 0, spl_name NULL
11:13:15.859 [3616.2868] <8> 529337:bptm:3616:sourcemedia.domain.local: [WARN] PDSTS: impl_set_imh_image_prop: PdvfsUnlink(/targetmedia.domain.local#2/2/CLIENTNAME.Domain.Local/Vstorage-UK/CLIENTNAME.Domain.Local_1347582047_C2_HDR_R20.info) failed (2:No such file or directory)
11:13:18.312 [3616.2868] <2> bp_sts_open_image: STH set to STS_SA_IMAGE
11:13:18.312 [3616.2868] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver.domain.local, query type 77
11:13:18.312 [3616.2868] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1530] in failed cache ERR=11001 NAME=randomclient.domain.local SVC=NULL
11:13:18.312 [3616.2868] <8> vnet_cached_getaddrinfo: [vnet_addrinfo.c:1273] vnet_cached_getaddrinfo_and_update() failed 6 0x6
11:13:18.437 [3616.2868] <2> vnet_pbxConnect: pbxConnectEx Succeeded
11:13:18.437 [3616.2868] <2> logconnections: BPDBM CONNECT FROM 10.211.5.42.52643 TO 10.201.28.34.1556 fd = 1116
11:13:18.437 [3616.2868] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
11:13:18.484 [3616.2868] <2> db_end: Need to collect reply
11:13:18.859 [3616.2868] <2> construct_sts_isid: master_server masterserver.domain.local, client CLIENTNAME.Domain.Local, backup_time 1347582047, copy_number 2, stream_number 0, fragment_number -1, resume_number 20, spl_name NULL
11:13:19.203 [3616.2868] <8> 529337:bptm:3616:sourcemedia.domain.local: [WARN] PDSTS: impl_set_imh_image_prop: PdvfsUnlink(/targetmedia.domain.local#2/2/CLIENTNAME.Domain.Local/Vstorage-UK/CLIENTNAME.Domain.Local_1347582047_C2_TIR_R20.info) failed (2:No such file or directory)
11:13:20.062 [3616.2868] <2> add_to_validate_image_list: Adding to val_img_list: CLIENTNAME.Domain.Local_1347582047_C2_TIR_R20
11:13:20.062 [3616.2868] <2> add_to_validate_image_list: added CLIENTNAME.Domain.Local_1347582047_C2_TIR_R20 to val_img_list
11:13:20.062 [3616.2868] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver.domain.local, query type 70
11:13:20.062 [3616.2868] <8> vnet_cached_getaddrinfo_and_update: [vnet_addrinfo.c:1530] in failed cache ERR=11001 NAME=randomclient.domain.local SVC=NULL
11:13:20.062 [3616.2868] <8> vnet_cached_getaddrinfo: [vnet_addrinfo.c:1273] vnet_cached_getaddrinfo_and_update() failed 6 0x6
11:13:20.187 [3616.2868] <2> vnet_pbxConnect: pbxConnectEx Succeeded
11:13:20.187 [3616.2868] <2> logconnections: BPDBM CONNECT FROM 10.211.5.42.52644 TO 10.201.28.34.1556 fd = 1116
11:13:20.187 [3616.2868] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
11:13:20.249 [3616.2868] <2> db_end: Need to collect reply
11:13:20.609 [3616.2868] <2> send_end_repl_marker: Creating OPT_DUP_END marker
11:13:20.609 [3616.2868] <2> construct_sts_isid: master_server masterserver.domain.local, client CLIENTNAME.Domain.Local, backup_time 1347582047, copy_number 1, stream_number 0, fragment_number 0, resume_number 0, spl_name NULL
11:13:20.609 [3616.2868] <2> bp_sts_open_image: STH set to STS_SA_IMAGE
11:13:20.609 [3616.2868] <8> 529337:bptm:3616:sourcemedia.domain.local: [WARN] PDSTS: impl_set_imh_image_prop: PdvfsUnlink(/sourcemedia.domain.local#1/2/CLIENTNAME.Domain.Local/Vstorage-UK/CLIENTNAME.Domain.Local_1347582047_C1_OPT_DUP_END.info) failed (2:No such file or directory)
11:13:20.640 [3616.2868] <2> construct_sts_isid: master_server masterserver.domain.local, client CLIENTNAME.Domain.Local, backup_time 1347582047, copy_number 2, stream_number 0, fragment_number 0, resume_number 20, spl_name NULL
11:13:20.984 [3616.2868] <8> 529337:bptm:3616:sourcemedia.domain.local: [WARN] PDSTS: impl_set_imh_image_prop: PdvfsUnlink(/targetmedia.domain.local#2/2/CLIENTNAME.Domain.Local/Vstorage-UK/CLIENTNAME.Domain.Local_1347582047_C2_OPT_DUP_END.info) failed (2:No such file or directory)
 

So what is it doing now?

Comments 1 CommentJump to latest comment

Morten Seeberg's picture

Here is what bpimagelist thinks about an example fragment:
 

Copy number:       1

Fragment:         1

Kilobytes:        51200000

Remainder:        0

Media Type:       Disk (0)

Density:          qscsi (0)

File Num:         0

ID:               @aaabQ

Host:             sourcemedia.domain.local

Block Size:       262144

Offset:           0

Media Date:            01-01-1970 01:00:00 (0)

Dev Written On:   -1

Flags:            0x4

Media Descriptor:        1;PureDisk;sourcemedia.domain.local;UK-staging;PureDiskVolume;0

Expiration Time:            INFINITY       (2147483647)

MPX:              0

retention_lvl:    1 week (0)

Try to Keep Time:       21-09-2012 02:20:47 (1348186847)

Copy Creation Time:       14-09-2012 04:47:09 (1347590829)

Data Format:      Tar

checkpoint:       0

resume num:       0

Copy on hold:     0


Copy number:       2

Fragment:         1

Kilobytes:        51200000

Remainder:        0

Media Type:       Disk (0)

Density:          qscsi (0)

File Num:         0

ID:               @aaabK

Host:             sourcemedia.domain.local

Block Size:       262144

Offset:           0

Media Date:            01-01-1970 01:00:00 (0)

Dev Written On:   -1

Flags:            0x4

Media Descriptor:        1;PureDisk;targetmedia.domain.local;Dedup-targetmedia;PureDiskVolume;0

Expiration Time:       01-01-1970 01:00:00 (0)

MPX:              0

retention_lvl:    2 months (4)

Try to Keep Time:       01-01-1970 01:00:00 (0)

Copy Creation Time:       01-01-1970 01:00:00 (0)

Data Format:      Tar

checkpoint:       0

resume num:       20

Copy on hold:     0

Did you restore something today?