bacula backups muito lentos com o socket TCP no estado 'unkn-4'

Question

Vários clientes bacula-fd estão fazendo backup de um bacula SD (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-900GB cada) precisam executar backups completos, que ficam terrivelmente lentos (geralmente cerca de 200-2500 Kbytes / s), então o backup completo não termina em vários dias, o que é um problema para nós (por isso, cancelá-lo e ir com incremental).

O servidor e os clientes estão em VLANs / sub-redes diferentes, portanto são roteados por outra máquina sibilante debian com VLANs e poucos switches. As placas de rede são de 1 Gbps em todas as máquinas (uma com ligação à rede ativa-passiva - o failover não ajuda com a velocidade), assim como os switches. As máquinas são quad e 8-core, tendo 8-64GB RAM, não entrando em swap, e tendo carga entre 0,2-2, então eu acho que não é CPU, E / S nem falta de memória. Bacula-sd também está no RAID de hardware que não parece estar sob carga. A rede também está praticamente 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 Linux também é padrão wheezy 3.2.60-1 + deb7u3.

Parece que a transferência começa bem (em cerca de 20+ Mbytes / seg, o que é esperado com muitos arquivos pequenos), do que em um momento Send-Q sobe e não desce por dezenas de segundos ( ou minutos), e netstat mostra o socket no temporizador "unkn-4", reiniciando com timeouts de aumento exponencial:

# 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 começar de novo:

# 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-fd no 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,2MB de tamanho e ficou hospedado por alguns minutos ...

O intervalo de audição está definido para 120 nas configurações de diretor, SD e arquivo deamon e parece estar funcionando bem. Ativando o arquivo de rastreio 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 é a conexão de rede para bacula-sd, e o processo está bloqueando ao escrever para isso. Pesquisando unkn-4 parece indica que, na verdade, "o cronômetro da sonda da janela zero está pendente".

Então, parece-me que é ou bacula-sd fazendo o afogamento 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 ethtool para desativar o descarregamento e outros recursos, não ajudou. ping -f nã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 à procura de ideias sobre como proceder para resolver (e finalmente corrigir, claro) isto?

UPDATE1 : mesmo depois de ajustar os buffers TCP , a situação não é melhor ainda - apenas a fila fica maior, mas ainda bloqueia, e o backup ainda é lento. Depois de olhar um pouco mais em wireshark dumps, parece ser um problema de software bacula-sd, e esse TCP ZeroWindow é uma 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 com rapidez suficiente, embora a máquina não esteja sobrecarregada; isso está no lado 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

    

Answer 1

Era o SQL.

Por padrão, toda vez que o bacula-fd envia um novo arquivo, bacula-sd tenta (via bacula-dir) inserir os atributos do arquivo em SQL batch table. Se você tiver muitos arquivos pequenos e seu SQL não for incrivelmente rápido, ele inserirá um pequeno atraso. Muitos pequenos atrasos = velocidade controlada = backups cancelados devido a Max Run Sched Time excedido. E, devido à arquitetura, mesmo que você tivesse vários backups em execução, tudo ficava mais lento.

A solução (tipo de) foi adicionar:

Spool Data = no
Spool Attributes = yes

na seção JobDefs {...} de bacula-dir.conf (observe que estou usando Spool Data = no porque é o armazenamento em disco, não o armazenamento em fita, portanto, apenas adicionaria sobrecarga). Com Spool Attributes = yes bacula grava atributos de arquivo em um arquivo, e somente quando o trabalho é concluído é o arquivo enviado ao servidor SQL. Observe que nessa conexão a bacula-fd é liberada (e a carga de disco / rede no cliente termina) assim que a transferência de dados é feita (portanto, ele não espera a inserção da SQL para concluir).

Algumas notas:

• "o seu SQL não é incrivelmente rápido" significa que faz apenas algumas dúzias de consultas por segundo.
• no meu caso, o servidor problemático tinha cerca de 3 milhões de arquivos e 350 GB de espaço em disco. Não foi possível concluir o backup completo em 4 dias , com as velocidades de transferência caindo para 200 Kbytes / s.
• com o spooling de atributos, ele consegue terminar em 2 dias e 13 horas. Não é uma melhora tão grande à vista (embora os backups originais nunca tenham terminado, talvez seja), mas: a própria transferência de dados leva apenas 4,5 horas , com velocidade média de ~ 18 Mbytes / s (o que não é tão ruim para muitos arquivos pequenos, e compressão, enquanto o servidor faz outras coisas). No entanto, o atributo despooling do arquivo local para o SQL Server leva em 56,5 horas . Mais de dois dias !!
• o servidor SQL em questão é dedicado ao MySQL (5.5.40-0 + wheezy1) no 8-core I7 @ 3.70GHz com 64GB de RAM, em 4 discos RAID-10. Ele também faz outras coisas e possui binlogs ativados, mas fica ocioso enquanto os backups são executados. Funciona muito bem para outra carga, e innodb_buffer_pool_size é maior que todos os índices de bacula. deve ser funcionando bem.
• parece que mesmo com o spooling de atributo ativado, o bacula não usa inserções em lote (nem LOAD DATA LOCAL INFILE ), mas envia 3 milhões de inserções uma por uma, aguardando confirmação em cada uma (dados de atributo são armazenados em arquivo binário compacto sobre 1GB grande. Traduzido para ASCII instruções SQL INSERT certamente será o dobro disso). Assim, o aumento da latência devido ao fato de o MySQL estar em outra máquina parece matar totalmente o desempenho.
• Tentarei analisar mais detalhadamente por que o SQL é lento, mas acho que a melhor solução seria colocar o MySQL em uma máquina local (com desempenho muito menor). Provavelmente, substituindo pelo PostgreSQL preferido, enquanto eu estou nisso.

Edit1 : atualizando o bacula para (pacote criado manualmente) 5.2.13 que faz contém suporte para inserções em lote (em vez do pacote 5.2.6 no Debian wheezy / jessie que não ), e o ajuste do banco de dados MySQL para que as tabelas temporárias sejam criadas no tmpfs, reduziu o tempo de despool do atributo mencionado de 56,5 horas para 30 minutos. Eu acho que substituí-lo com o PostgreSQL na máquina local (mesmo onde bacula-sd e bacula-dir são) provavelmente poderia melhorar mesmo nisso, mas isso é bom o suficiente para nós.