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"
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.
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.
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.