Restore very slow on NDMP ONTAP 9.1P3

[Tom_Egger]

the restore on the Netapp take too long. we use DAR and we've Qtrees and we backup on VeritasAppliances;  any Ideas?

15.08.2017 16:31:07 - begin Restore
15.08.2017 16:31:07 - Info bprd (pid=20597) Found (76,018,402) files in (172) images for Restore Job ID 2862183.xxx
15.08.2017 16:31:07 - restoring from image xxxxxx_1502503335
15.08.2017 16:31:07 - requesting resource @aaaae
15.08.2017 16:31:07 - granted resource MediaID=@aaaae;DiskVolume=PureDiskVolume;DiskPool=dp-xxxxxx-msdp;Path=PureDiskVolume;StorageServer=xxxxxx;MediaServer=xxxxxx
15.08.2017 16:31:08 - Info bprd (pid=20597) Searched ( 1) files of (76,018,402) files for Restore Job ID 2862183.xxx
15.08.2017 16:31:08 - Info bprd (pid=20597) Restoring from copy 1 of image created Sat Aug 12 04:02:15 2017 from policy BE_P_NDMP_NetApp_P_MSDP
15.08.2017 16:31:09 - Info bpbrm (pid=328282) xxxxxx is the host to restore to
15.08.2017 16:31:09 - Info bpbrm (pid=328282) reading file list for client
15.08.2017 16:31:09 - connecting
15.08.2017 16:31:09 - Info bpbrm (pid=328282) starting bptm
15.08.2017 16:31:09 - Info ndmpagent (pid=328287) Restore started
15.08.2017 16:31:09 - connected; connect time: 0:00:00
15.08.2017 16:31:09 - Info bpbrm (pid=328282) bptm pid: 328288
15.08.2017 16:31:10 - Info bptm (pid=328288) start
15.08.2017 16:31:10 - started process bptm (pid=328288)
15.08.2017 16:31:10 - Info bptm (pid=328288) reading backup image
15.08.2017 16:31:13 - begin reading
15.08.2017 16:31:14 - Info ndmpagent (pid=328287) INF - Restoring NDMP files from /h000ro/vol_u_07
15.08.2017 16:31:14 - Info ndmpagent (pid=328287) NDMP Remote disk
15.08.2017 16:31:17 - Info ndmpagent (pid=328287) This is CDOT restore
15.08.2017 16:31:17 - Info ndmpagent (pid=328287) DAR enabled
15.08.2017 16:31:18 - Info ndmpagent (pid=328287) xxxxxx: DIRECT ACCESS RECOVERY (DAR) requested
15.08.2017 16:31:18 - Info ndmpagent (pid=328287) xxxxxx: Session identifier for Restore : 9051
15.08.2017 16:36:19 - Info ndmpagent (pid=328287) xxxxxx: RESTORE: Tue Aug 15 16:36:19 2017 : We have read 489117 KB from the backup.
15.08.2017 16:41:19 - Info ndmpagent (pid=328287) xxxxxx: RESTORE: Tue Aug 15 16:41:19 2017 : We have read 979098 KB from the backup.
15.08.2017 16:46:19 - Info ndmpagent (pid=328287) xxxxxx: RESTORE: Tue Aug 15 16:46:19 2017 : We have read 1554107 KB from the backup.
15.08.2017 16:51:19 - Info ndmpagent (pid=328287) xxxxxx: RESTORE: Tue Aug 15 16:51:19 2017 : We have read 2000643 KB from the backup.
15.08.2017 16:52:57 - begin reading
15.08.2017 16:53:01 - begin reading
15.08.2017 16:53:19 - begin reading
15.08.2017 16:54:02 - begin reading
15.08.2017 16:54:16 - begin reading
15.08.2017 16:54:30 - begin reading
15.08.2017 16:54:39 - begin reading
15.08.2017 16:54:54 - begin reading
15.08.2017 16:55:08 - begin reading
15.08.2017 16:55:25 - begin reading
15.08.2017 16:55:40 - begin reading
15.08.2017 16:55:47 - begin reading
15.08.2017 16:56:02 - begin reading
15.08.2017 16:56:19 - begin reading
15.08.2017 16:56:20 - Info ndmpagent (pid=328287) xxxxxx: RESTORE: Tue Aug 15 16:56:20 2017 : We have read 2216056 KB from the backup.
15.08.2017 16:56:36 - begin reading
15.08.2017 16:56:42 - Info ndmpagent (pid=328287) xxxxxx: RESTORE: RESTORE IS DONE
15.08.2017 16:56:42 - Info ndmpagent (pid=328287) NDMP restore successful from path /xxxxxx/vol_u_07
15.08.2017 16:56:43 - Info ndmpagent (pid=328287) done. status: 0
15.08.2017 16:56:43 - end reading; read time: 0:00:07
15.08.2017 16:56:43 - Info bptm (pid=328288) completed reading backup image
15.08.2017 16:56:43 - Info bptm (pid=328288) EXITING with status 0 <----------
15.08.2017 16:56:43 - Info xxxxxx (pid=328288) StorageServer=PureDisk:xxxxxx; Report=PDDO Stats for (xxxxxx): read: 2345454 KB, CR received: 3824602 KB, CR received over FC: 0 KB, dedup: 0.0%
15.08.2017 16:56:44 - restored from image xxxxxx_1502503335; restore time: 0:25:37
15.08.2017 16:56:44 - Info ndmpagent (pid=328287) done. status: 0: the requested operation was successfully completed
15.08.2017 16:56:44 - end Restore; elapsed time 0:25:37
the requested operation was successfully completed (0)

[Marianne · Accepted solution]

Have you checked log files?
ndmpagent and bptm on media server.
Look for '.... waited for full / empty buffer' towards the end of the restore process  (pid=328288).

[eduncan]

There is not much information to go on in just the job details.

However they are technotes explaining why DAR can be slow.  Maybe should should check with NetApp:

http://www.veritas.com/docs/000090404

https://www.veritas.com/support/en_US/article.000012561

Just to be sure have you tried backing up to the Advanced Disk and restoring from the Advanced Disk to make sure the rehydration of the deduplicated data is not slowing you down?