Restores happening sequentially, not in parallel

[Joe_Hartley]

Hi all.

I test NDMP backup performance for a particular storage appliance, which involves writing and running scripts that perform backup and restorations, using up to ten tape drives across two different tape libraries at a time.  These scripts use bpbackup and bprestore, and each job uses ten different policies, rather than multiple sources in a single policy.  Functionally, the scripts all work fine.  Except...

The backup jobs kick off fine, all drives are loaded as quickly as the robots will allow and much data is written to all ten drives simultaneously.

The restore jobs all get kicked off, but only run serially!  That is, all jobs are submitted and are visible to the activity monitor and bpdbjobs, and the first job gets its tape loaded and reading commences, but the rest of the jobs just sit there waiting for the first job to finish.  Only then will the next tape be picked up by the robot and inserted into the tape drive, and the next job in line starts reading.  This continues, one job at a time, until all jobs have completed.

The usual problem seen with folks not using the full contingent of available drives is that the "max concurrent write drives" value for the storage unit is not set correctly, but this is for reading, and when writing, all drives get used.

This has stumped the folks within my organization!  Any hints as to the cause here will be greatly appreciated.  Thanks!

[cruisen]

WOW, I can only explain this, becuase the second restore job is waiting for the media of the first restore job to insert, and because it is in USE no way.

You need to have an efficient media management during backup, so that you would create different pools or so that only media that belongs to the backup for exact one policy.

Best regards,

Cruisen

[Joe_Hartley]

Cruisen, thanks for replying.

I don't think this is a media issue, as part of the overall testing process suspends and expires any tapes that may have been in use at various intervals.

My media list after the backup job shows ten tapes used, one for each policy.  Since the tape used policy #1 has no connection to the tape used by policy #2, what would keep #2 from loading its tape as soon as it could?

[cruisen]

Joe,

Have you really configured for every policy one storage pool, can you confirm this. have you checked the detail of the restore job why it is not executing it is waiting for what, what does the job details say? Can you post this. For me when a media is not loaded it is because it is in use. Please double check this.

best regards

[Joe_Hartley]

No, I don't have a storage pool for each policy.  I have one big storage pool with lots of tapes.  When I start the test, all tapes are expired, the robots rescanned, and the media is seen as all new and available to NBU.

The job details for the second job in the list looks like this:

03/03/2016 15:48:08 - begin Restore
03/03/2016 15:48:08 - Info bprd (pid=3387) Found (840) files in (10) images for Restore Job ID 454.xxx
03/03/2016 15:48:08 - number of images required: 1
03/03/2016 15:48:08 - media needed: AIE618

Note the five minute delay between the next entry - the previous restoration, which used a different tape (F60574) in a different library, ended at 15:53:14.

03/03/2016 15:53:15 - restoring from image aie-client_1457025668
03/03/2016 15:53:15 - Info bpbrm (pid=3851) aie-client is the host to restore to
03/03/2016 15:53:15 - Info bpbrm (pid=3851) telling media manager to start restore on client
03/03/2016 15:53:15 - Info bpbrm (pid=3851) spawning a brm child process
03/03/2016 15:53:15 - Info bpbrm (pid=3851) child pid: 3899
03/03/2016 15:53:15 - Info bpbrm (pid=3899) start tar on client
03/03/2016 15:53:15 - Info tar (pid=3903) Restore started.
03/03/2016 15:53:15 - requesting resource AIE618
03/03/2016 15:53:16 - Info bptm (pid=3879) Waiting for mount of media id AIE618 (copy 1) on server aie-server.
03/03/2016 15:53:16 - started process bptm (pid=3879)
03/03/2016 15:53:16 - mounting AIE618
03/03/2016 15:53:16 - Info bptm (pid=3879) INF - Waiting for mount of media id AIE618 on server aie-server for reading.
03/03/2016 15:53:16 - granted resource  AIE618
03/03/2016 15:53:16 - granted resource  HP.ULTRIUM6-SCSI.003
03/03/2016 15:54:39 - mounted AIE618; mount time: 0:01:23
03/03/2016 15:54:39 - Info bptm (pid=3879) AIE618
03/03/2016 15:54:39 - Info bptm (pid=3879) INF - Waiting for positioning of media id AIE618 on server aie-server for reading.
03/03/2016 15:54:39 - positioning AIE618 to file 1
03/03/2016 15:54:39 - positioned AIE618; position time: 0:00:00
03/03/2016 15:54:39 - begin reading

For completeness, here are the job details for the first restore job:

03/03/2016 15:47:44 - begin Restore
03/03/2016 15:47:44 - Info bprd (pid=3344) Found (840) files in (10) images for Restore Job ID 453.xxx
03/03/2016 15:47:44 - number of images required: 1
03/03/2016 15:47:44 - media needed: F60574
03/03/2016 15:47:45 - restoring from image aie-client_1457025672
03/03/2016 15:47:45 - Info bpbrm (pid=3355) aie-client is the host to restore to
03/03/2016 15:47:45 - Info bpbrm (pid=3355) telling media manager to start restore on client
03/03/2016 15:47:46 - Info bpbrm (pid=3355) spawning a brm child process
03/03/2016 15:47:46 - Info bpbrm (pid=3355) child pid: 3360
03/03/2016 15:47:46 - Info bpbrm (pid=3360) start tar on client
03/03/2016 15:47:46 - Info tar (pid=3364) Restore started.
03/03/2016 15:47:46 - requesting resource F60574
03/03/2016 15:47:46 - Info bptm (pid=3357) Waiting for mount of media id F60574 (copy 1) on server aie-server.
03/03/2016 15:47:46 - started process bptm (pid=3357)
03/03/2016 15:47:46 - mounting F60574
03/03/2016 15:47:46 - Info bptm (pid=3357) INF - Waiting for mount of media id F60574 on server aie-server for reading.
03/03/2016 15:47:46 - granted resource  F60574
03/03/2016 15:47:46 - granted resource  HP.ULTRIUM6-SCSI.002
03/03/2016 15:48:47 - mounted F60574; mount time: 0:01:01
03/03/2016 15:48:47 - Info bptm (pid=3357) F60574
03/03/2016 15:48:47 - Info bptm (pid=3357) INF - Waiting for positioning of media id F60574 on server aie-server for reading.
03/03/2016 15:48:47 - positioning F60574 to file 1
03/03/2016 15:48:47 - positioned F60574; position time: 0:00:00
03/03/2016 15:48:47 - begin reading
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) INF - Restoring NDMP files from /export/all-zeroes-08/ to [See line below]
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) INF - Restoring NDMP files from [See line above] to /export/res-all-zeroes-08
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) DAR disabled - continuing restore without DAR
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) Attempting normal restore.
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) aie-zs3-2c: Running Restore without Direct Access Restore
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) aie-zs3-2c: Restoring to "/export/res-all-zeroes-08/".
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) aie-zs3-2c: Tape server: local.
03/03/2016 15:48:48 - Info ndmpagent (pid=3364) aie-zs3-2c: Tape record size: 65536.
03/03/2016 15:53:14 - Info ndmpagent (pid=3364) NDMP restore successful from path /export/all-zeroes-08
03/03/2016 15:53:14 - Info ndmpagent (pid=3364) done. status: 0: the requested operation was successfully completed
03/03/2016 15:53:14 - end reading; read time: 0:04:27
03/03/2016 15:53:14 - Info bpbrm (pid=3355) media manager for backup id aie-client_1457025672 exited with status 0: the requested operation was successfully completed
03/03/2016 15:53:14 - restored from image aie-client_1457025672; restore time: 0:05:29
03/03/2016 15:53:14 - end Restore; elapsed time 0:05:30
the requested operation was successfully completed  (0)

[Will_Restore]

I think this is by design since restore is going to the same device.  NetBackup doesn't know if you might be restoring the same file(s).  So the logic is wait for the first job to finish before continuing a second.  That's my guess, at least.

[Joe_Hartley]

Will, I've had multiple restore jobs running to the same client simultaneously before on other installations, so I don't think there are any design constraints that I'm running into.  The jobs back up completely different filesystems, so limiting the number of restore jobs simply because the client is the same doesn't seem like a reasonable design decision.

I'm with cruisen in that something's holding the jobs back.  I don't believe the answer is multiple volume pools, but I'm in the middle of giving that a go.

[Joe_Hartley]

I created 10 new volume pools, assigned a tape to each pool (paying attention to what tapes are in which library) and kicked off my test again.

Once again, all 10 tape drives got used for writing the backup, but the restore jobs are happening serially.

Oh well, it was worth a try.

[Michal_Mikulik1]

Hello,

my first idea when reading this thread was that you probably used one "Select for Restore" window in BAR GUI to define all data for restore. Instead of one "Select for Restore" window for every restore stream.

But you mention that you use bprestore-based scripts, so I hope that it is one bprestore command for each restored stream, all running independently.

I am not aware of any restriction on NetBackup side for this. Check your NAS vendor doc if there is not some restriction.

Regards

Michal

[Marianne]

Are the rest of the restore jobs queued? Does it say in Job details why it is queued?

[Joe_Hartley]

Michal, the jobs are each kicked off with a separate command.  Each job runs a different policy for a different mountpoint.  I'm testing for a storage appliance manufacturer, so I know there are no restrictions from that end, either as a disk target, tape target, or backup source.

Marianne, the jobs don't actually say that they're queued or waiting for a resource, they sit not showing any kind of status until it's their turn for a tape drive.  As you can see from the logs above, the media needed is identified, then there's simply a wait until its turn for a drive.

Over the course of the restoration, all 10 drives get used so it's not a matter of unavailable hardware.

Separate volume pools for each policy does not change the behavior.  Kicking off the restores via the GUI, either as one job for all mountpoints or as separate jobs, does not change anything - all jobs line up and get their drives serially.

[Marianne]

Stuck at 'Media needed....'

This reminds me of a NetBackup bug that has never been acknowledged and fixed (except for a custom bprd that was created for me...).

Have a look at my comments in this post:

https://www.veritas.com/community/forums/all-restores-not-working-backups-are#comment-8291781 

All I can suggest is to log a Support call with Veritas and be prepared to upload level 5 logs till the cows come home.....

[Will_Restore]

A bug that has never been acknowledged and fixed is a "feature".

[Joe_Hartley]

Hmmm, thanks, Marianne.

I wouldn't say the jobs are "stuck at" media needed, as the first job immediately gets its tape, and when its done, the second job gets its tape. 

The pointer to the bprd log seems helpful - here's what I see when I run my test.  The first restore starts and everything else gets held up:

07:37:22.441 [171] <2> start_image_restore: restfiles pid 119 brm pid 206 aie-zs3-2c_1457101670
07:37:22.441 [171] <2> start_image_restore: start_msg = START RESTORE -k 0 -c aie-zs3-2c -hostname aie-zs3-2c -rclnt aie-x3-2d -rclnthostname aie-x3-2d -browse_clnt aie-zs3-2c -ru root -firstblk 0 -cl allzeroes06 -bt 1457101670 -st 0 -secure 1 -b aie-zs3-2c_1457101670 -cn 1 -rst 1457102240 -ct 19 -flport 0 -flipc /usr/openv/var/tmp/vnet-00119457102242369154000000013-bja4oa -restoreid 541.001 -jobid 541 -job_total 1 -rg root -cv -R /root/ndmp/rename-allzeroes-06 -clnt_lc_messages en_US.UTF-8 -clnt_lc_time en_US.UTF-8 -clnt_lc_ctype C -clnt_lc_collate en_US.UTF-8 -clnt_lc_numeric en_US.UTF-8
07:37:22.441 [171] <2> start_indep_grp: skipping image aie-zs3-2c_1457101674 for now... another NDMP restore is in progress
07:37:22.441 [171] <2> start_indep_grp: (pid 121) p_image = NULL
07:37:22.441 [171] <2> start_indep_grp: (pid 121) oldest_time = 0x7fffffff
[ 8 more sets of skipping image lines]

NBU seems to be deciding to only handle one NDMP restore at a time

[cruisen]

perhaps it is not NBU that holds the job, perhaps it is the ndmp device, that is by design like this, because of performance issues or internal stuff.

But this should not be standard. what do you mean by storage applinace vendor, and when you say disk, tape or backup source.

THIS is not a robot I suppose, kind of virtal library, no. You should get more information about how the commands are handeld to the NDMP device, and if it waits internaly the first restore job end,  before executing the new one?, because of internal processes.

[Joe_Hartley]

cruisen, the tape libraries are directly connected to our storage appliance via Fibre Channel, which is seen in NBU as an NDMP host.  In this circumstance, I'm backing up from the appliance to tape, then trying to restore back to the same storage appliance.

In this case, my company makes both the storage appliances and tape libraries; the communication between devices is very well understood, and the folks here say that there's nothing on the appliance or tape libraries that should be holding up jobs.  I've looked at the logs (even the internal ones) for the appliance that's the NDMP host, and there's nothing there indicating that it's the gate in this case. Given that other installations work fine (and in fact so did this one when I last worked with it some 6 months ago) I'm sure it's not happening by design on either end.

[Marianne]

It seems to me that NBU is only allowing one NDMP restore job at a time. I cannot say that I have seen this documented anywhere. Maybe worth logging a Support call with Veritas?