Forum Discussion

grocanar's avatar
grocanar
Level 3
2 years ago

how to troubleshoot slow vm backup

I m using netbackup 9.1 to backup vm.

All is running fine except the backup of a particuliar vm that is extremely slow. 

the vmdk is 800Go size ans it take more than 12 hours to backup

i have CBT enabled , i have the accelerator enabled. 

is there some way to improve the speed. 
Here is the output of backup

BEGIN_WRITING 1678239682
LOG 1678276628 4 bpbkar 13924 INF - Transport Type = hotadd
LOG 1678277288 4 bpbkar 13924 accelerator sent 32837355520 bytes out of 824100023296 bytes to server, optimization 96,0%
LOG 1678277288 4 bptm 13452 waited for full buffer 5710 times, delayed 2457281 times
LOG 1678277315 4 bptm 13452 EXITING with status 0 <----------
LOG 1678277315 4 netmedia.admin.institut-genomique.fr 13452 StorageServer=PureDisk:netmedia.admin.institut-genomique.fr; Report=PDDO Stats for (netmedia.admin.institut-genomique.fr): scanned: 805599404 KB,
CR sent: 7516980 KB, CR sent over FC: 0 KB, dedup: 99,1%, cache disabled, where dedup space saving:97,4%, compression space saving:1,6%
LOG 1678277315 4 bpbrm 13337 validating image for client ares.genoscope.cns.fr
LOG 1678277315 4 bpbkar 13924 done. status: 0: the requested operation was successfully completed
END_WRITING 1678277455
Started 1678239673
KbPerSec 21423
Kilobytes 804785188
Files 5163970
ActivePid 13337
Status 0
DestStorageUnit dedup-stu
DestMediaServer netmedia.admin.institut-genomique.fr
Transport 0
Ended 1678277456

  • You omit the time in front of each line, and this makes it difficult for us to understand the problem.

    So, to make it easier to read, I manually added the time.

    Wednesday, March 8, 2023 1:41:22 AM BEGIN_WRITING
    Wednesday, March 8, 2023 11:57:08 AM bpbkar 13924 INF - Transport Type = hotadd
    Wednesday, March 8, 2023 12:08:08 PM bptm 13452 waited for full buffer 5710 times, delayed 2457281 times

    So what I understand is that the real backup (the reading of the blocks) starts at 11:57:08 AM and the backup ends at 12:08:08 PM. Witch is fast. Only 32 GB of data was backed up (96% acceleration)
    The problem is to understanding what netbackup is doing from 1:41:22 AM until 11:57:08 AM.
    There is a possibility that other backups run at the same time and a restore limit is reached

    Can you run a manual backup at a time that any other backup run?
    open the bpbrm log on the media server and bpbkar log on the backup host

    • grocanar's avatar
      grocanar
      Level 3

      Hi Stefanos

      Thanks for the reply

      Indeed i have missed this peculiar point. 

      but when i look at my log i read

      Wed Mar 8 02:41:22 CET 2023 BEGIN_WRITING 1678239682

      the process seem begin to write a 02:41:22

      I have read the logs in my backup host for bpbkar process

      2:39:01.494 [13924.13924] <2> bpbkar main: previous backup id list:<ares.genoscope.cns.fr_1678152019,ares.genoscope.cns.fr_1678152019>
      02:39:01.496 [13924.13924] <2> logparams: bpbkarv -r 2678400 -dt 0 -to 0 -bpstart_time 1678239973 -clnt ares.genoscope.cns.fr -class BCKP_VM -sched Bckp_VM_quotidien -st FUL
      L -bpstart_to 300 -bpend_to 300 -read_to 900 -ru root -stream_count 244 -stream_number 244 -jobgrpid 1401182 -blks_per_buffer 512 -use_otm -fso -ifr -pid 13337 -mediasvr net
      media.admin.institut-genomique.fr -bt 1678239673 -t 0 -b ares.genoscope.cns.fr_1678239673 -kl 7 -fi -S netbackup.cng.fr -fim NONE -ct 40 -fscp -S netbackup.cng.fr -storagesv
      r netmedia.admin.institut-genomique.fr -bidlist bid@BCKP_VM_ares.genoscope.cns.fr_1678239673
      02:39:01.498 [13924.13924] <4> bpbkar main: INF - setenv BACKUPID=ares.genoscope.cns.fr_1678239673
      02:39:01.610 [13924.13924] <4> bpbkar expand_wildcards: start to backup filelist /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.ares.genoscope.cns.fr_1678239638.1.0.NBU_
      DATA.xml ,nb_fscp_enabled is 1
      02:39:01.610 [13924.13924] <4> bpbkar expand_wildcards: INF - Processing /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.ares.genoscope.cns.fr_1678239638.1.0.NBU_DATA.xml
      02:39:01.623 [13924.13924] <4> bpfsmap: INF - bpfsmap: arg list: brmpid 13337 rawdisk /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.ares.genoscope.cns.fr_1678239638.1.0
      .NBU_DATA.xml datafd -1 inctime 0
      02:39:01.623 [13924.13924] <4> bpfsmap: INF - bpfsmap butime 1678239673 clientname ares.genoscope.cns.fr hostname netmedia.admin.institut-genomique.fr buid ares.genoscope.
      cns.fr_1678239673
      02:39:01.634 [13924.13924] <4> logBackupInfo: INF - Backing up vCenter server chaos.genoscope.cns.fr, ESX host cngvsan1.cng.fr, BIOS UUID 422a7ebc-9a88-2b6e-b400-651816baeab
      f, Instance UUID 502ac048-319b-00eb-2efe-7188e85bd472, Display Name ares.genoscope.cns.fr, Hostname ares.genoscope.cns.fr
      13:08:08.025 [13924.13924] <4> bpbkar expand_wildcards: end backup for filelist /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.ares.genoscope.cns.fr_1678239638.1.0.NBU_D
      ATA.xml

      the bpbkar start at 2h39 and finish at 13h08.

      I m wondering if i should consider it slow or not 

       

       

       

  • Due to insufficient information so we are unable to understand your problem. 

  • it looks like you are using hotadd transport mode, did you tried nbd  to test

    • grocanar's avatar
      grocanar
      Level 3

      Hi

      No i didn"t try try as this vm is one of 200+ VM we backup. 

      On my netbackup training it was told that hotadd is better than nbd. 

      I will make that test uin my next backup 

  • Have you resolved your problem? If yes, then let me know how you resolved your problem so that I have more information about problem-solving as I am struggling with the balloon business and trying hard to solve the issues.

    • grocanar's avatar
      grocanar
      Level 3

      No i haven't yet but new problem arise then i haven't time to cope with this peculiar one. 

      I will post here if i find a solution