Very slow performance of NDMP Restore

Last updated

May 8, 2024
Save as PDF
Share
1. Share
2. Tweet
3. Share

Views:: 1,106

Visibility:: Public

Votes:: 1

Category:: ndmp

Specialty:: dp

Last Updated:: 5/8/2024, 7:31:02 AM

Applies to

ONTAP 9
Three-way NDMP
Restore
Networker
NetBackup

Issue

NDMP logs show a constant PAUSED state for the reading data from the tape

Sun Jul 25 2021 05:21:54 +02:00 [kern_ndmpd:info:5516] [36326]   INFO: DATA read at offset 1788662062080 with length 131072
Sun Jul 25 2021 05:21:55 +02:00 [kern_ndmpd:info:5516] [36326]   INFO: DATA notification state 3 (SESS_STATE: PAUSED) event 8 (EVENT: SEEK)
Sun Jul 25 2021 05:21:55 +02:00 [kern_ndmpd:info:5516] [36326]   INFO: DATA read at offset 1793047803904 with length 65536
Sun Jul 25 2021 05:21:56 +02:00 [kern_ndmpd:info:5516] [36326]   INFO: DATA notification state 3 (SESS_STATE: PAUSED) event 8 (EVENT: SEEK)
Sun Jul 25 2021 05:21:56 +02:00 [kern_ndmpd:info:5516] [36326]   INFO: DATA read at offset 1793047869440 with length 131072
Sun Jul 25 2021 05:21:56 +02:00 [kern_ndmpd:info:5516] [36326]   INFO: DATA notification state 3 (SESS_STATE: PAUSED) event 8 (EVENT: SEEK)

Getting the inode file information from the tape (PHASE I) during the restore takes a long time:

rst Tue Jul 27 12:26:38 CEST 202 /svm_3/vol3_backup/ Tape_close (ndmp)
rst Tue Jul 27 12:26:38 CEST 202 /svm_3/vol3_backup/ End (250 files, 2006 MB)
rst Tue Jul 27 12:31:59 CEST 202 /svm_3/vol3_backup/ Start (Level 0, NDMP:36326)
rst Tue Jul 27 12:31:59 CEST 202 /svm_3/vol3_backup/ Options (b=0, d, y, H, TCP recv buffer size = 33580, TCP send buffer size = 33580)
rst Tue Jul 27 12:31:59 CEST 202 /svm_3/vol3_backup/ Tape_open (ndmp)
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (Total P2 threads (3))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (P2 thread 0: time (msec) (6), dirs processed (0))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (P2 thread 1: time (msec) (0), dirs processed (0))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (P2 thread 2: time (msec) (0), dirs processed (0))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM clrimap : wait_time (msec) (0), lookup_time (msec) (2290))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM dumpmap : wait_time (msec) (310), lookup_time (msec) (6170))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM inomap  : wait_time (msec) (309), lookup_time (msec) (3078748))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM inomap  : Cache hits (6983253), Cache misses (677340))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM basemap : wait_time (msec) (0), lookup_time (msec) (0))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM filemap : wait_time (msec) (38), lookup_time (msec) (8440))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM dirmap  : wait_time (msec) (37), lookup_time (msec) (62875))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (VM inotab  : wait_time (msec) (25), lookup_time (msec) (39916))
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (Phase 1 percent spent in reading from media: 0%)
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (Phase 1 total time (msec): 7604422)
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (Phase 2 total time (msec): 2237)
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (Phase 3 percent spent in reading from media: 0%)
rst Tue Jul 27 14:49:07 CEST 202 /svm_3/vol3_backup/ Log_msg (Phase 3 total time (msec): 620921