NDMP restore of NetApp Filer is slow

Question

This is a FAS2240 8.2P3 7-Mode

Backup Software: EMC Networker 8.1

NDMP is configured and running inside a vFiler.

Let's start with the backup. The backup command in Networker is:

nsrndmp_save -T dump

You can also specify -M (DSA) but I think here it is implicit.

Application information is (just recreated the NDMP client in Networker using the New Client Wizard to be on the safe side):

USE_TBB_IF_AVAILABLE=Y
DIRECT=Y
BUTYPE=dump
HIST=Y
UPDATE=Y

Full backup runs at more or less wirespeed

> sysstat -x 5
CPU    NFS   CIFS   HTTP   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk   OTHER    FCP  iSCSI     FCP   kB/s   iSCSI   kB/s
                                       in    out    read  write    read  write    age    hit  time  ty  util                            in    out      in    out
29%      0      0      0       1     485  94867   98060     11       0      0     0s    91%    0%  -    90%       1      0      0       0      0       0      0
31%      0      0      0       1     502  97711  101518    490       0      0     0s    89%   13%  T    90%       1      0      0       0      0       0      0
32%      0      0      0      57     530 103167  107344    251       0      0     0s    89%    5%  Zf   88%      57      0      0       0      0       0      0
30%      0      0      0      41     552 107049  110286    222       0      0     0s    89%    7%  :    87%      41      0      0       0      0       0      0

HOWEVER: We only get about 10MB/sec avg when restoring from tape. The backup to tape was made when nothing else was running, so the problem is not that data is interleaved on the tape.

The command and output from Networker is (restoring to an empty volume):

# nsrndmp_recover -S 1760972238 -m /vol/vfprod_xtest /vol/vfprod_x
42795:nsrndmp_recover: Performing recover from Non-NDMP type of device
85183:nsrndmp_recover: DSA is listening for an NDMP data connection on: 1.2.4.5, port = 8745
42690:nsrndmp_recover: Performing non-DAR Recovery..
86724:nsrdsa_recover: DSA listening at: host 'backupserv', IP address '1.2.4.5', port '8745'.
42937:nsrdsa_recover: Performing Immediate recover
42940:nsrdsa_recover: Reading Data...
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Dump came from a SnapLock volume.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Incremental restores to SnapLock volumes are not supported.
All files will be correctly restored, but subsequent restores
of incremental backups will not recreate the file system as
it appeared during the final incremental backup.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: ./.etc/gid_map: cannot create file: Read-only file system
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Sat Feb  8 14:52:25 2014: Writing data to files.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Sat Feb  8 14:56:43 2014 : We have read 3361690 KB from the backup.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Sat Feb  8 15:01:43 2014 : We have read 7053433 KB from the backup.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Sat Feb  8 15:06:43 2014 : We have read 10908694 KB from the backup.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: failed to find the file
42617:nsrndmp_recover: NDMP Service Log: RESTORE: Sat Feb  8 15:11:22 2014: Restoring NT ACLs.
42617:nsrndmp_recover: NDMP Service Log: RESTORE: RESTORE IS DONE
42942:nsrdsa_recover: Reading data...DONE.
42927:nsrndmp_recover: Successfully done

Here are stats on the filer during a restore

>sysstat -x 5
CPU    NFS   CIFS   HTTP   Total     Net   kB/s    Disk   kB/s    Tape   kB/s  Cache  Cache    CP  CP  Disk   OTHER    FCP  iSCSI     FCP   kB/s   iSCSI   kB/s
                                       in    out    read  write    read  write    age    hit  time  ty  util                            in    out      in    out
91%      0      0      0      35   15364    143    5369  20946       0      0     0s    98%   56%  H    55%      35      0      0       0      0       0      0
91%      0      0      0      20   14668    126    5135  20617       0      0    59s    98%   56%  H    56%      20      0      0       0      0       0      0
91%      2      0      0       3   14407    119    5685  20954       0      0     1     98%   53%  H    52%       1      0      0       0      0       0      0
91%      0      0      0       1   15564    154    5454  20711       0      0     1     98%   56%  Hf   53%       1      0      0       0      0       0      0
91%      0      0      0       2   14447    121    6502  14358       0      0     1     98%   42%  Hf   56%       2      0      0       0      0       0      0
...
92%      6      0      0       6   19503    245    4696  15072       0      0     1     98%   46%  :    56%       0      0      0       0      0       0      0
93%      0      0      0       3   18902    253    7667  13669       0      0     0s    98%   22%  Hf   63%       3      0      0       0      0       0      0
91%      6      0      0       7   18099    216    1957  32432       0      0     0s    97%  100%  :f   45%       1      0      0       0      0       0      0
91%      6      0      0       6   16111    153    4427  23419       0      0     0s    98%   55%  :    56%       0      0      0       0      0       0      0
92%      7      0      0       7   15629    156    8155      0       0      0     1     98%    0%  -    68%       0      0      0       0      0       0      0
91%      0      0      0       3   14226    125    4427  32453       0      0     1     99%   79%  Hf   53%       3      0      0       0      0       0      0
94%      6      0      0       6   32264    594     744  38453       0      0     2     97%  100%  :f   45%       0      0      0       0      0       0      0
92%      6      0      0       6   14781    127    9846     59       0      0     2     98%    7%  Hn   61%       0      0      0       0      0       0      0
90%      6      0      0      63   11546     57    2073  42592       0      0     2     99%  100%  :f   50%      57      0      0       0      0       0      0

CPU usage seems high compared to backup, where disk util was high, as it should.

Doing the same thing between two filers gives about 40MB/sec avg.:

na1> ndmpcopy -sa root:xx -da root:xx /vol/vfprod_x/fs1 na2:/vol/test/xtest
Ndmpcopy: Starting copy [ 1 ] ...
Ndmpcopy: na1: Notify: Connection established
Ndmpcopy: na2: Notify: Connection established
Ndmpcopy: na1: Connect: Authentication successful
Ndmpcopy: na2: Connect: Authentication successful
Ndmpcopy: na1: Log: DUMP: creating "/vol/vfprod_x/../snapshot_for_backup.10825" snapshot.
Ndmpcopy: na1: Log: DUMP: Dumping from a SnapLock volume
Ndmpcopy: na1: Log: DUMP: Using subtree dump
Ndmpcopy: na1: Log: DUMP: Date of this level 0 dump: Sat Feb  8 15:23:04 2014.
Ndmpcopy: na1: Log: DUMP: Date of last level 0 dump: the epoch.
Ndmpcopy: na1: Log: DUMP: Dumping /vol/vfprod_x/fs1 to NDMP connection
Ndmpcopy: na1: Log: DUMP: mapping (Pass I)[regular files]
Ndmpcopy: na1: Log: DUMP: mapping (Pass II)[directories]
Ndmpcopy: na2: Log: RESTORE: Dump came from a SnapLock volume.
Ndmpcopy: na1: Log: DUMP: estimated 16178315 KB.
Ndmpcopy: na1: Log: DUMP: dumping (Pass III) [directories]
Ndmpcopy: na1: Log: DUMP: dumping (Pass IV) [regular files]
Ndmpcopy: na2: Log: RESTORE: Sat Feb  8 15:23:12 2014: Begin level 0 restore
Ndmpcopy: na2: Log: RESTORE: Sat Feb  8 15:23:12 2014: Reading directories from the backup
Ndmpcopy: na2: Log: RESTORE: Sat Feb  8 15:23:13 2014: Creating files and directories.
Ndmpcopy: na2: Log: RESTORE: Sat Feb  8 15:23:31 2014: Writing data to files.
Ndmpcopy: na1: Log: DUMP: Sat Feb  8 15:28:11 2014 : We have written 12577964 KB.
Ndmpcopy: na2: Log: RESTORE: Sat Feb  8 15:28:11 2014 : We have read 12575988 KB from the backup.
Ndmpcopy: na1: Log: ACL_START is '16565304320'
Ndmpcopy: na1: Log: DUMP: dumping (Pass V) [ACLs]
Ndmpcopy: na1: Log: DUMP: 16177066 KB
Ndmpcopy: na1: Log: DUMP: DUMP IS DONE
Ndmpcopy: na2: Log: RESTORE: Sat Feb  8 15:29:36 2014: Restoring NT ACLs.
Ndmpcopy: na1: Log: DUMP: Deleting "/vol/vfprod_x/../snapshot_for_backup.10825" snapshot.
Ndmpcopy: na1: Log: DUMP_DATE is '5686836680'
Ndmpcopy: na1: Notify: dump successful
Ndmpcopy: na2: Log: RESTORE: RESTORE IS DONE
Ndmpcopy: na2: Notify: restore successful
Ndmpcopy: Transfer successful [ 0 hours, 6 minutes, 41 seconds ]
Ndmpcopy: Done

Also tried options ndmpd.tcpnodelay.enable on, as suggested in https://communities.netapp.com/thread/15890, to no effect.

We even bought the filer with a 10GbE card so the filer at least has the potential to really deliver, but for now I'm not sure it does.

The volume I used for test is located on a snaplock aggreate with underlying 10x 7200rpm SATA disks (8 usable, double parity).

The day we would need to restore a larger amount of data would be hell in this scenario, because a day would not be enough time to restore a few TB...

Anyone have any useful ideas?

Thanks.

UPDATE #1

Ok unrelated to NDMP I've 10MB/s read almost all the time I can think of, so here are some performance stats which I got using this script

#!/bin/sh
#
if [ -z $1 ]; then
echo " "
echo "I need a filer target"
echo "An example syntax"
echo " $0 filer01.msg.dcn"
echo " "
exit 0
fi

SSH="ssh -i /root/.ssh/id_rsa-netapp"

FILER=$1
#
DATAFILE="${FILER}_$(date +%Y%m%d%H%M)"
echo "" >> $DATAFILE
date >> $DATAFILE
echo "------------------------------" >> $DATAFILE
$SSH $FILER 'priv set -q diag; statit -b' 2>/dev/null
echo "Starting statit sample" >> $DATAFILE
$SSH $FILER 'priv set -q diag; nfsstat -z' 2>/dev/null
echo "Zeroing nfsstat" >> $DATAFILE
$SSH $FILER 'priv set -q diag; nfs_hist -z' 2>/dev/null
echo "Zeroing nfs_hist" >> $DATAFILE
$SSH $FILER 'priv set -q diag; wafl_susp -z' 2>/dev/null
echo "Zeroing wafl_susp" >> $DATAFILE
$SSH $FILER 'sysstat -xs -c 30 1' >> $DATAFILE

# And we wait...

$SSH $FILER 'priv set -q diag; statit -en' >> $DATAFILE 2>/dev/null
$SSH $FILER 'priv set -q diag; nfsstat -d' >> $DATAFILE
$SSH $FILER 'priv set -q diag; nfs_hist' >> $DATAFILE
$SSH $FILER 'priv set -q diag; wafl_susp -w' >> $DATAFILE

echo " ** " >> $DATAFILE

and the output can be found here.

Note that this filer seems to have 768 MB of NVRAM and the aggregate we're working on has 10 7200rpm SATA disks in a RAID-5

UPDATE #2 Jun 10

I'm not sure why we were hitting that many high watermarks in the example earlier, but for now I have found out the following with the help of support:

the 10MB/s reads seems to be normal as the filer is always scrubbing the disks
disabling controller failover (cf disable) makes NDMP restores (thus writes) proceed at 5 or more times the speed (50-100MB/s) and this is expected

Still I'm not sure then why they sold us a 10G card for max. 100MB/s, but I'll keep at it. Especially, since as far as I understood it, WAFL uses all the disks all the time to spread writes across as many spindles as possible, and this filer that about 20 disks even though they're only "BSAS"

If the assembled worthies of SF don't come up with an answer, you may be able to get some useful information from [the NetApp admins mailing list](http://www.teaparty.net/mailman/listinfo/toasters) (disclaimer: I run the list). — MadHatter, May 13 '14 at 12:15

score 1 · Answer 1 · answered Mar 08 '14 at 22:49

The most interesting part of the output above is the systat gathered during the dump. We see a pegged CPU, but that can be misleading because the systat -x CPU output only shows the highest pegged CPU, not a per-core average. But, we see something else interesting. We're almost constantly doing CPs, and they are H CPs (high watermark.) This indicates that the data in NVRAM to be committed to disk has exceeded the high watermark. So we're going to block client requests to try and flush the NVRAM data to disk. But, to complicate things we're only doing about 20-25MB/s in and our CPs are happening every second, and sometimes taking 3 seconds to complete. That math doesn't check out. I'm not sure what the per-HA-partner NVRAM size is on a 2240, but I know it is at least 256MB per head, and probably larger. At 25MB/s that's 8-10 seconds to hit high watermark, and we'd commit before that anyway, and that's not what we're seeing here.

All in all the output above hints at the filer doing something else behind the scenes. I would suggest digging into systat -m to see what domain is most active. If it is Kahuna and one core is pinned at 100% then we could be hitting a WAFL bottleneck. I'd also evaluate any other background processing that may be occurring (sis jobs, snap* jobs, etc.)

If you can't track it down yourself then reproduce the issue while gathering a perfstat and hit up NetApp Support.

score 0 · Answer 2 · answered Mar 08 '14 at 22:42

Check out systat -m. That filer's doing something else, otherwise you couldn't hit CP checkpoints so fast with only 20m/s of IO. There's something running in the background during your test - or some sort of wonky bug at play.

Perf team guys love this stuff. Capture a perfstat while doing the ndmp and open a technical perf case.

score 0 · Answer 3 · answered Mar 10 '14 at 01:11

OK first, the 2240 is one of the lower end systems, with lower-end RAM. The "H" CP type I believe is 'high-watermark' and you're also getting "f"'s after that meaning that 1/2 of NVMEM has been filled before the CP is finished on the write.

Bottom line is that write performance is limited by a) the amount of NVMEM/NVRAM in the system combined with the number of spindles the system can blast out to disk to, in order to clear out the write cache as quickly as possible.

The sysstat you have here shows you're constantly in CP so it would seem to indicate that you're likely spindle bound. If you posted the output of "statit -b" (wait a minute) and "statit -e" then we can be sure. Make sure you "priv set advanced" first.

NDMP restore of NetApp Filer is slow

3 Answers3