A restauração do NDMP do NetApp Filer está lenta

Question

Este é um 7-modo FAS2240 8.2P3

Software de backup: EMC Networker 8.1

O NDMP é configurado e executado dentro de um vFiler.

Vamos começar com o backup. O comando de backup no Networker é:

nsrndmp_save -T dump

Você também pode especificar -M (DSA), mas acho que aqui está implícito.

As informações do aplicativo são (apenas recriamos o cliente NDMP no Networker usando o Assistente de novo cliente para estar no lado seguro):

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

O backup completo é executado com mais ou menos 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

NO ENTANTO: Nós só obtemos cerca de 10MB / seg em média ao restaurar da fita. O backup para fita foi feito quando nada mais estava sendo executado, então o problema não é que os dados sejam intercalados na fita.

O comando e a saída do Networker são (restaurando para um volume vazio):

# 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

Aqui estão as estatísticas no arquivador durante uma restauração

>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

O uso da CPU parece alto em comparação ao backup, em que o uso do disco era alto, como deveria.

Fazer a mesma coisa entre dois arquivadores dá cerca de 40MB / seg. média:

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

Também tentei as opções ndmpd.tcpnodelay.enable, como sugerido no link , sem efeito.

Até compramos o arquivador com um cartão de 10GbE para que o arquivador tenha pelo menos o potencial de realmente fornecer, mas por enquanto não tenho certeza de que isso aconteça.

O volume que usei para o teste está localizado em um snaplock agravado com discos SATA subjacentes de 10x 7200 rpm (8 utilizáveis com paridade dupla).

O dia em que precisaríamos restaurar uma quantidade maior de dados seria um inferno neste cenário, porque um dia não seria tempo suficiente para restaurar alguns TB ...

Alguém tem alguma ideia útil?

Obrigado.

UPDATE # 1

Ok não relacionado ao NDMP Eu tenho 10MB / s lendo quase todo o tempo em que consigo pensar, então aqui algumas estatísticas de desempenho que usei usando este 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

e a saída pode ser encontrada aqui .

Observe que esse arquivador parece ter 768 MB de NVRAM e o agregado em que estamos trabalhando tem 10 discos SATA de 7200 rpm em um RAID-5

UPDATE # 2 10 de jun

Não sei por que estávamos atingindo muitas marcas d'água altas no exemplo anterior, mas, por enquanto, descobri o seguinte com a ajuda do suporte:

• as leituras de 10MB / s parecem normais, pois o arquivador está sempre limpando os discos
• desabilitar o failover do controlador (cf disable) faz restaurações do NDMP (assim escritas) prosseguir com 5 ou mais vezes a velocidade (50-100MB / s) e isso é esperado

Ainda não tenho certeza então porque eles nos venderam um cartão de 10G para max. 100MB / s, mas vou continuar nisso. Especialmente, desde que eu entendi, o WAFL usa todos os discos o tempo todo para espalhar gravações em tantos fusos quanto possível, e esse arquivador tem cerca de 20 discos, embora eles sejam apenas "BSAS"

    

Answer 1

A parte mais interessante da saída acima é o systat recolhido durante o despejo. Vemos uma CPU atrelada, mas isso pode ser enganoso porque a saída da CPU systat -x mostra apenas a CPU mais vinculada, não uma média por núcleo. Mas vemos algo mais interessante. Estamos quase constantemente fazendo CPs, e eles são H CPs (marca d'água alta). Isso indica que os dados na NVRAM a serem confirmados no disco excederam a marca d'água alta. Então, vamos bloquear as solicitações do cliente para tentar liberar os dados da NVRAM para o disco. Mas, para complicar as coisas, estamos apenas a fazer cerca de 20-25MB / s e os nossos CPs estão a acontecer a cada segundo e, por vezes, demoram 3 segundos a concluir. Essa matemática não confere. Não tenho certeza de qual é o tamanho da NVRAM por parceiro de HA em um 2240, mas sei que é pelo menos 256 MB por cabeça e provavelmente maior. Com 25MB / s é de 8-10 segundos para atingir a marca d'água alta, e nós nos comprometeríamos antes disso, e não é isso que estamos vendo aqui.

Em resumo, a saída acima sugere que o arquivador faça outra coisa nos bastidores. Eu sugeriria cavar em systat -m para ver qual domínio é mais ativo. Se é Kahuna e um núcleo é fixado em 100%, então poderíamos estar atingindo um gargalo WAFL. Eu também avaliaria qualquer outro processamento em segundo plano que possa estar ocorrendo (trabalhos sis, tarefas com snap *, etc.)

Se você não conseguir rastreá-lo, reproduza o problema enquanto coleta um perfstat e obtenha o Suporte da NetApp.

    

Answer 2

Confira o systat -m. Aquele arquivador está fazendo outra coisa, caso contrário, você não conseguiria atingir os pontos de checagem CP tão rapidamente com apenas 20m / s de IO. Há algo correndo em segundo plano durante o seu teste - ou algum tipo de bug no jogo.

Pessoal da equipa de perfumes adoram estas coisas. Capture um perfstat enquanto faz o ndmp e abra um caso técnico perfeito.

    

Answer 3

Em primeiro lugar, o 2240 é um dos sistemas inferiores, com RAM de baixo custo. O tipo "H" CP que eu acredito é "high-watermark" e você também está recebendo "f" depois disso, o que significa que 1/2 do NVMEM foi preenchido antes do CP terminar na gravação.

A conclusão é que o desempenho de gravação é limitado por a) a quantidade de NVMEM / NVRAM no sistema combinada com o número de eixos que o sistema pode explodir em disco para limpar o cache de gravação o mais rápido possível .

O sysstat que você tem aqui mostra que você está constantemente em CP, o que parece indicar que você provavelmente está preso ao fuso. Se você postou a saída de "statit -b" (espere um minuto) e "statit -e", então podemos ter certeza. Certifique-se de "priv set advanced" primeiro.