I also say "Maybe". I assume

VictorCharlesEd · ‎04-16-2013

Is an NDMP restore speed of 11577 KB/s from an LTO4 tape normal? We perform NDMP backups utilizing the same tape drive / source volume and acheive 75812 KB/s write speeds.

Here is the log from the restore job in Activity Monitor:

04/15/2013 16:41:28 - begin Restore
04/15/2013 16:41:28 - number of images required: 1
04/15/2013 16:41:28 - media needed: 16781
04/15/2013 16:41:28 - media needed: 11399
04/15/2013 16:41:28 - media needed: 11465
04/15/2013 16:41:29 - restoring from image netappFiler_1XXX
04/15/2013 16:41:29 - Info bpbrm (pid=31925) netappFiler is the host to restore to
04/15/2013 16:41:29 - Info bpbrm (pid=31925) telling media manager to start restore on client
04/15/2013 16:41:29 - Info bpbrm (pid=31925) spawning a brm child process
04/15/2013 16:41:29 - Info bpbrm (pid=31925) child pid: 31930
04/15/2013 16:41:29 - Info bpbrm (pid=31930) start tar on client
04/15/2013 16:41:29 - Info tar (pid=31934) Restore started.
04/15/2013 16:41:29 - requesting resource 11399
04/15/2013 16:41:30 - awaiting resource 11399.
          A pending request has been generated for this resource request.
          Operator action may be required. Pending Action: All drives down,
          Media ID: 11399, Barcode: 11399, Density: hcart2, Access Mode: Read,
          Action Drive Name: N/A, Action Media Server: N/A, Robot Type(Number): 8(3),
          Volume Group: 000_00003_TLD, Action Acs: N/A, Action Lsm: N/A
04/15/2013 16:41:45 - awaiting resource 11399.
          A pending request has been generated for this resource request.
          Operator action may be required. Pending Action: All drives down,
          Media ID: 11399, Barcode: 11399, Density: hcart2, Access Mode: Read,
          Action Drive Name: N/A, Action Media Server: N/A, Robot Type(Number): 8(3),
          Volume Group: 000_00003_TLD, Action Acs: N/A, Action Lsm: N/A
04/15/2013 16:42:31 - Info bptm (pid=31927) Waiting for mount of media id 11399 (copy 1) on server netbackupServer.
04/15/2013 16:42:31 - started process bptm (pid=31927)
04/15/2013 16:42:31 - mounting 11399
04/15/2013 16:42:31 - Info bptm (pid=31927) INF - Waiting for mount of media id 11399 on server netbackupServer for reading.
04/15/2013 16:42:31 - granted resource  11399
04/15/2013 16:42:31 - granted resource  IBM.ULT3580-HH5.003
04/15/2013 16:43:24 - mounted 11399; mount time: 0:00:53
04/15/2013 16:43:24 - Info bptm (pid=31927) 11399
04/15/2013 16:43:24 - Info bptm (pid=31927) INF - Waiting for positioning of media id 11399 on server netbackupServer for reading.
04/15/2013 16:43:24 - positioning 11399 to file 3
04/15/2013 16:44:25 - positioned 11399; position time: 0:01:01
04/15/2013 16:44:25 - begin reading
04/15/2013 16:44:26 - Info ndmpagent (pid=31934) INF - Restoring NDMP files from /vol/someVol/someDir to [See line below]
04/15/2013 16:44:26 - Info ndmpagent (pid=31934) INF - Restoring NDMP files from [See line above] to /vol/restoreVol/someDir
04/15/2013 16:44:27 - Info ndmpagent (pid=31934) DAR enabled
04/15/2013 16:49:26 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 16:49:27 2013 : We have read 804864 KB from the backup.
04/15/2013 16:55:28 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 16:55:28 2013 : We have read 1111838 KB from the backup.
04/15/2013 17:00:36 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:00:37 2013 : We have read 1204660 KB from the backup.
04/15/2013 17:05:58 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:05:58 2013 : We have read 1449531 KB from the backup.
04/15/2013 17:11:01 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:11:01 2013 : We have read 1580948 KB from the backup.
04/15/2013 17:16:14 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:16:14 2013 : We have read 2605094 KB from the backup.
04/15/2013 17:21:48 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:21:48 2013 : We have read 3280795 KB from the backup.
04/15/2013 17:27:14 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:27:14 2013 : We have read 3683012 KB from the backup.
04/15/2013 17:32:32 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:32:32 2013 : We have read 4603050 KB from the backup.
04/15/2013 17:37:47 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:37:47 2013 : We have read 5696493 KB from the backup.
04/15/2013 17:42:46 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:42:47 2013 : We have read 7982849 KB from the backup.
04/15/2013 17:47:48 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:47:48 2013 : We have read 8998421 KB from the backup.
04/15/2013 17:52:49 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:52:50 2013 : We have read 10268863 KB from the backup.
04/15/2013 17:57:56 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 17:57:56 2013 : We have read 11647244 KB from the backup.
04/15/2013 18:03:12 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:03:12 2013 : We have read 13994956 KB from the backup.
04/15/2013 18:08:16 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:08:16 2013 : We have read 15025278 KB from the backup.
04/15/2013 18:13:25 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:13:25 2013 : We have read 16017387 KB from the backup.
04/15/2013 18:18:35 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:18:35 2013 : We have read 17036205 KB from the backup.
04/15/2013 18:23:48 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:23:48 2013 : We have read 18351793 KB from the backup.
04/15/2013 18:28:58 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:28:58 2013 : We have read 19070099 KB from the backup.
04/15/2013 18:34:05 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:34:05 2013 : We have read 20469679 KB from the backup.
04/15/2013 18:39:07 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:39:07 2013 : We have read 22557788 KB from the backup.
04/15/2013 18:44:07 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:44:08 2013 : We have read 25113288 KB from the backup.
04/15/2013 18:49:09 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:49:09 2013 : We have read 26615977 KB from the backup.
04/15/2013 18:50:37 - positioning 11399 to file 4
04/15/2013 18:50:38 - positioned 11399; position time: 0:00:01
04/15/2013 18:54:42 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 18:54:42 2013 : We have read 27100045 KB from the backup.
04/15/2013 19:00:22 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:00:22 2013 : We have read 27120764 KB from the backup.
04/15/2013 19:05:37 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:05:37 2013 : We have read 27157143 KB from the backup.
04/15/2013 19:10:21 - current media 11399 complete, requesting next media IBM.ULT3580-HH5.003:11465
04/15/2013 19:10:40 - awaiting resource IBM.ULT3580-HH5.003:11465. Waiting for resources.
          Reason: Drives are in use, Media server: netbackupServer,
          Robot Type(Number): TLD(3), Media ID: N/A, Drive Name: N/A,
          Volume Pool: N/A, Storage Unit: N/A, Drive Scan Host: N/A,
          Disk Pool: N/A, Disk Volume: N/A
04/15/2013 19:12:33 - Info bptm (pid=31927) Waiting for mount of media id 11465 (copy 1) on server netbackupServer.
04/15/2013 19:12:33 - started process bptm (pid=31927)
04/15/2013 19:12:33 - mounting 11465
04/15/2013 19:12:33 - Info bptm (pid=31927) INF - Waiting for mount of media id 11465 on server netbackupServer for reading.
04/15/2013 19:12:33 - granted resource  11465
04/15/2013 19:12:33 - granted resource  IBM.ULT3580-HH5.003
04/15/2013 19:13:25 - mounted 11465; mount time: 0:00:52
04/15/2013 19:13:25 - Info bptm (pid=31927) 11465
04/15/2013 19:13:25 - Info bptm (pid=31927) INF - Waiting for positioning of media id 11465 on server netbackupServer for reading.
04/15/2013 19:13:25 - positioning 11465 to file 1
04/15/2013 19:13:25 - positioned 11465; position time: 0:00:00
04/15/2013 19:13:49 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:13:50 2013 : We have read 27279436 KB from the backup.
04/15/2013 19:19:18 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:19:18 2013 : We have read 27355475 KB from the backup.
04/15/2013 19:24:19 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:24:20 2013 : We have read 27453240 KB from the backup.
04/15/2013 19:29:21 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:29:21 2013 : We have read 27486400 KB from the backup.
04/15/2013 19:34:24 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:34:25 2013 : We have read 27543179 KB from the backup.
04/15/2013 19:39:43 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:39:43 2013 : We have read 27704754 KB from the backup.
04/15/2013 19:45:11 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:45:12 2013 : We have read 27782937 KB from the backup.
04/15/2013 19:51:13 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:51:14 2013 : We have read 27820589 KB from the backup.
04/15/2013 19:57:16 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 19:57:16 2013 : We have read 27861444 KB from the backup.
04/15/2013 20:02:16 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:02:17 2013 : We have read 27951968 KB from the backup.
04/15/2013 20:07:41 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:07:42 2013 : We have read 28112114 KB from the backup.
04/15/2013 20:12:56 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:12:57 2013 : We have read 28209461 KB from the backup.
04/15/2013 20:18:22 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:18:23 2013 : We have read 28307084 KB from the backup.
04/15/2013 20:23:35 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:23:35 2013 : We have read 28419580 KB from the backup.
04/15/2013 20:27:02 - positioning 11465 to file 2
04/15/2013 20:27:02 - positioned 11465; position time: 0:00:00
04/15/2013 20:28:40 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:28:40 2013 : We have read 28524814 KB from the backup.
04/15/2013 20:34:06 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:34:06 2013 : We have read 28590541 KB from the backup.
04/15/2013 20:39:13 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:39:14 2013 : We have read 28793421 KB from the backup.
04/15/2013 20:44:26 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:44:26 2013 : We have read 29321217 KB from the backup.
04/15/2013 20:49:40 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:49:41 2013 : We have read 29469967 KB from the backup.
04/15/2013 20:55:00 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 20:55:00 2013 : We have read 29705510 KB from the backup.
04/15/2013 21:00:00 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:00:00 2013 : We have read 29901084 KB from the backup.
04/15/2013 21:05:10 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:05:10 2013 : We have read 30134388 KB from the backup.
04/15/2013 21:10:11 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:10:11 2013 : We have read 30273222 KB from the backup.
04/15/2013 21:15:32 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:15:33 2013 : We have read 31404723 KB from the backup.
04/15/2013 21:20:40 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:20:41 2013 : We have read 31832629 KB from the backup.
04/15/2013 21:26:07 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:26:07 2013 : We have read 32226338 KB from the backup.
04/15/2013 21:31:12 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:31:13 2013 : We have read 32399313 KB from the backup.
04/15/2013 21:35:25 - current media 11465 complete, requesting next media IBM.ULT3580-HH5.003:16781
04/15/2013 21:35:50 - awaiting resource IBM.ULT3580-HH5.003:16781. Waiting for resources.
          Reason: Drives are in use, Media server: netbackupServer,
          Robot Type(Number): TLD(3), Media ID: N/A, Drive Name: N/A,
          Volume Pool: N/A, Storage Unit: N/A, Drive Scan Host: N/A,
          Disk Pool: N/A, Disk Volume: N/A
04/15/2013 21:36:44 - Info bptm (pid=31927) Waiting for mount of media id 16781 (copy 1) on server netbackupServer.
04/15/2013 21:36:44 - started process bptm (pid=31927)
04/15/2013 21:36:44 - mounting 16781
04/15/2013 21:36:44 - Info bptm (pid=31927) INF - Waiting for mount of media id 16781 on server netbackupServer for reading.
04/15/2013 21:36:44 - granted resource  16781
04/15/2013 21:36:44 - granted resource  IBM.ULT3580-HH5.003
04/15/2013 21:37:36 - mounted 16781; mount time: 0:00:52
04/15/2013 21:37:36 - Info bptm (pid=31927) 16781
04/15/2013 21:37:36 - Info bptm (pid=31927) INF - Waiting for positioning of media id 16781 on server netbackupServer for reading.
04/15/2013 21:37:36 - positioning 16781 to file 1
04/15/2013 21:37:36 - positioned 16781; position time: 0:00:00
04/15/2013 21:38:32 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:38:33 2013 : We have read 33618969 KB from the backup.
04/15/2013 21:43:52 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:43:53 2013 : We have read 33984748 KB from the backup.
04/15/2013 21:48:59 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:49:00 2013 : We have read 34507325 KB from the backup.
04/15/2013 21:54:11 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:54:11 2013 : We have read 38025639 KB from the backup.
04/15/2013 21:59:16 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 21:59:15 2013 : We have read 40206603 KB from the backup.
04/15/2013 22:04:28 - Info ndmpagent (pid=31934) netappFiler: RESTORE: Mon Apr 15 22:04:28 2013 : We have read 41763747 KB from the backup.
04/15/2013 22:07:56 - Info ndmpagent (pid=31934) netappFiler: RESTORE: RESTORE IS DONE
04/15/2013 22:08:01 - Info ndmpagent (pid=31934) NDMP restore successful from path /vol/someVol
04/15/2013 22:08:02 - Info ndmpagent (pid=31934) done. status: 0: the requested operation was successfully completed
04/15/2013 22:08:02 - end reading; read time: 5:23:37
04/15/2013 22:08:02 - Info bpbrm (pid=31925) media manager for backup id netappFiler_1322337601 exited with status 0: the requested operation was successfully completed
04/15/2013 22:08:02 - restored from image netappFiler_1322337601; restore time: 5:26:33
04/15/2013 22:08:02 - end Restore; elapsed time 5:26:34
the requested operation was successfully completed  (0)

Nicolai · ‎04-16-2013

Maybe. Restoring small files will never utilize the full bandwidth of the tape drive.

Are you restoring all files in the backup image or is it only a single file restore ?

What is the fragment size set to in the storage unit configuration - If it's the default value you may need to tewak it. See the two tech notes below:

http://www.symantec.com/docs/TECH15692

http://www.symantec.com/docs/HOWTO56051

VictorCharlesEd · ‎04-17-2013

Thanks for pointing me in the right direction Nicolai, but the properties for this NDMP Storage Unit (attached) do not really line up with the example in the tech note.

I was only restoring a 50GB directory, there were about 50 directories and ~1000 files. It did require three tapes though.

Yasuhisa_Ishika · ‎04-17-2013

I also say "Maybe".

I assume you are using tape drives attached to media server. backup marks 75MB/s, so media server can transfer data in at least 75 MB/s. I guess it came from performance characteristics of your filer. Consider to check I/O load in your filer.

BTW, 50GB in 3 LTO tapes - are you using VTL? It is too small to fill up real tapes.

VOX

Slow NDMP Restore Speeds