Vários clientes bacula-fd estão fazendo backup em um SD bacula (usando arquivos de disco 2G em RAID massivo, não em fita), geralmente 2-3 deles simultaneamente. Funciona bem, exceto quando 2 clientes maiores (cerca de 400-900 GB cada) precisam executar backups completos, que ficam terrivelmente lentos (geralmente cerca de 200-2500 Kbyte/s), então o backup completo não termina em vários dias, o que é um problema problema para nós (então cancelamos e continuamos com incremental).
O servidor e os clientes estão em diferentes VLANs/sub-redes, portanto, são roteados por outra máquina debian wheezy com VLANs e poucos switches. As NICs são de 1 Gbps em todas as máquinas (uma com ligação de rede ativa-passiva - o failover não ajuda na velocidade), assim como os switches. As máquinas são quádruplas e de 8 núcleos, com 8-64 GB de RAM, sem troca e com carga entre 0,2-2, então acho que não é CPU, E/S nem falta de memória. Bacula-sd também está em RAID de hardware que não parece estar sob carga. A rede também está quase ociosa no momento, portanto, não deve haver congestionamento de largura de banda. A versão do Bacula é padrão wheezy 5.2.6+dfsg-9, e o kernel do Linux também é padrão wheezy 3.2.60-1+deb7u3.
Parece que a transferência começa bem (em cerca de 20+ Mbytes/s, o que é esperado com muitos arquivos pequenos), mas em um momento o Send-Q sobe e não desce por dezenas de segundos (ou minutos) , e o netstat mostra o soquete no cronômetro "unkn-4", reiniciando com tempos limite crescentes exponencialmente:
# netstat -tpno | grep bacula
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name Timer
tcp 0 967688 10.66.3.135:49668 10.66.2.11:9103 ESTABLISHED 2964/bacula-fd unkn-4 (1.86/0/0)
tcp 0 0 10.66.3.135:9102 10.66.2.11:54499 ESTABLISHED 2964/bacula-fd keepalive (5882.64/0/0)
depois de algum tempo, os pacotes parecem recomeçar:
# netstat -tpno | grep bacula
tcp 0 38054 10.66.3.135:49668 10.66.2.11:9103 ESTABLISHED 2964/bacula-fd on (0.21/0/0)
tcp 0 0 10.66.3.135:9102 10.66.2.11:54499 ESTABLISHED 2964/bacula-fd keepalive (385.49/0/0)
e o backup continua (confirmado com status client=blowgun-fdno bconsole). Por exemplo:
* status client=axe-fd
newaxe-fd Version: 5.2.6 (21 February 2012) x86_64-pc-linux-gnu debian 7.0
Daemon started 24-Oct-14 17:27. Jobs: run=0 running=0.
Heap: heap=683,600 smbytes=761,617 max_bytes=807,280 bufs=396 max_bufs=426
Sizeof: boffset_t=8 size_t=8 debug=200 trace=1
Running Jobs:
JobId 12640 Job axe.2014-10-24_23.05.01_40 is running.
Full Backup Job started: 24-Oct-14 23:05
Files=2,529,050 Bytes=253,018,715,824 Bytes/sec=1,479,901 Errors=6
Files Examined=2,529,050
Processing file: /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
SDReadSeqNo=5 fd=5
Director connected at: 26-Oct-14 21:34
bg.jpg tem 1,2 MB de tamanho e permaneceu nele por alguns minutos...
O intervalo de pulsação está definido como 120 nas configurações do diretor, SD e arquivo deamon e parece estar funcionando bem. Ativando o arquivo de rastreamento de depuração com setdebug level=200 trace=1 all, vejo:
newaxe-fd: backup.c:371-0 FT_REG saving: /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
newaxe-fd: backup.c:469-0 bfiled: sending /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg to stored
newaxe-fd: crypto.c:607-0 crypto_digest_new jcr=2f01748
newaxe-fd: backup.c:1467-0 No strip for /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
newaxe-fd: backup.c:609-0 type=3 do_read=1
newaxe-fd: bfile.c:963-0 open file /home/users/novoselo/public_html/~2511/templates/js_corp/images/bg.jpg
newaxe-fd: backup.c:1194-0 Send data to SD len=65135
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: backup.c:1194-0 Send data to SD len=65562
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0
strace parece confirmar que:
# strace -tt -ff -s999 -p 3907
Process 3907 attached with 4 threads - interrupt to quit
[pid 27650] 22:25:15.705796 write(5, "[....]"..., 55110 <unfinished ...>
[pid 27661] 22:25:15.706103 select(6, [5], NULL, NULL, {2, 804806} <unfinished ...>
[pid 3912] 22:25:15.706147 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
[pid 3907] 22:25:15.706168 select(4, [3], NULL, NULL, NULL <unfinished ...>
[pid 3912] 22:25:16.619938 <... restart_syscall resumed> ) = -1 ETIMEDOUT (Connection timed out)
[pid 3912] 22:25:16.620008 futex(0x397d82d0240, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 3912] 22:25:16.620092 futex(0x397d82d0284, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 13229, {1414358746, 620076000}, ffffffff <unfinished ...>
[pid 27661] 22:25:18.513819 <... select resumed> ) = 0 (Timeout)
[pid 27661] 22:25:18.513858 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:18.513928 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout)
[pid 27661] 22:25:23.519025 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:23.519139 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout)
[pid 27661] 22:25:28.524240 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:28.524317 select(6, [5], NULL, NULL, {5, 0}) = 0 (Timeout)
[pid 27661] 22:25:33.529409 write(15, "newaxe-fd: heartbeat.c:96-0 wait_intr=0 stop=0\n", 47) = 47
[pid 27661] 22:25:33.529508 select(6, [5], NULL, NULL, {5, 0}^C <unfinished ...>
fd 5 é uma conexão de rede para bacula-sd, e o processo está bloqueando ao gravar nele. A pesquisa de unkn-4 parece indicar que, na verdade, é "temporizador de sondagem de janela zero pendente".
Então, parece-me que é bacula-sd fazendo a limitação por algum motivo (bug?) Ou (mais provavelmente IMHO) algum tipo de problema de rede.
não parece haver erros nos adaptadores ethernet ativos. Eu tentei usar ethtoolpara desabilitar o descarregamento e outros recursos, não ajudou. ping -fnão perde pacotes mesmo quando o problema no TCP está se manifestando:
axe# ping -s1400 -f -c1000 10.66.2.11
--- slingshot.tomsoft.lan ping statistics ---
1000 packets transmitted, 1000 received, 0% packet loss, time 607ms
rtt min/avg/max/mdev = 0.391/0.582/0.672/0.039 ms, ipg/ewma 0.608/0.585 ms
Estou procurando ideias de como proceder para solucionar problemas (e finalmente corrigir, é claro) isso?
ATUALIZAÇÃO1 : mesmo depois de ajustar os buffers TCP , a situação não é melhor - apenas a fila fica maior, mas ainda bloqueia e o backup ainda é lento. Depois de olhar um pouco mais para os dumps do wireshark, parece ser um problema de software bacula-sd, e que o TCP ZeroWindow é a maneira normal do kernel de limitar o TCP nesse caso. Portanto, a máquina parece receber dados OK, mas bacula-sd não parece ser capaz de processar dados rápido o suficiente, embora a máquina não esteja sob carga; isso está no lado do bacula-sd:
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name Timer
tcp 3952353 0 10.66.2.11:9103 10.66.3.132:45226 ESTABLISHED 15839/bacula-sd keepalive (4863.09/0/0)
# uptime
05:23:13 up 2 days, 14:40, 2 users, load average: 0.42, 0.32, 0.27
Era SQL.
Por padrão, cada vez que o bacula-fd envia um novo arquivo, o bacula-sd tenta (via bacula-dir) inserir atributos de arquivo na
batchtabela SQL. Se você tiver muitos arquivos pequenos e seu SQL não for incrivelmente rápido, ele inserirá um pequeno atraso. Muitos pequenos atrasos = velocidade limitada = backups cancelados devido aoMax Run Sched Timeexcedido. E devido à arquitetura, mesmo se você tivesse vários backups em execução, todos ficariam mais lentos.A solução (mais ou menos) foi adicionar:
na
JobDefs {...}seção debacula-dir.conf(observe que estou usandoSpool Data = noporque é armazenamento em disco, não em fita, portanto, apenas adicionaria sobrecarga). ComSpool Attributes = yesbacula grava atributos de arquivo em um arquivo, e somente quando o trabalho é concluído é que o arquivo é enviado para o servidor SQL. Observe que nessa conexão obacula-fdé liberado (e a carga do disco/rede no cliente termina) assim que a transferência de dados é concluída (portanto, não espera a conclusão da inserção do SQL).Algumas notas:
LOAD DATA LOCAL INFILE), mas envia esses 3 milhões de inserts um a um, esperando a confirmação de cada um (os dados do atributo são armazenados em um arquivo binário compacto com cerca de 1 GB de tamanho. Traduzido para ASCII instruções SQL INSERT certamente será o dobro disso). Portanto, o aumento da latência devido ao MySQL estar em outra máquina parece matar totalmente o desempenho.Edit1 : atualizando o bacula para (pacote criado manualmente) 5.2.13 que contém suporte para inserções em lote (em vez do pacote 5.2.6 no Debian wheezy/jessie que não contém ) e ajustando o banco de dados MySQL para que tabelas temporárias sejam criadas em tmpfs, reduziu o tempo de despool do atributo mencionado de 56,5 horas para 30 minutos. Acho que substituí-lo pelo PostgreSQL na máquina local (mesmo onde estão bacula-sd e bacula-dir) provavelmente pode melhorar mesmo nisso, mas isso é bom o suficiente para nós.