Desenvolvimento

18 set, 2012

Sobre segmentation faults, stack overflows, GDB e OCaml

Publicidade

Alguns meses atrás, recebemos relatos de falhas aleatórias do nosso armazenamento consistente e distribuído de chave-valor, Arakoon (se você não conhece, vá conferir!). O processo morreu, de repente, devido a uma segmentation fault. Essas falhas pareceram ocorrer de forma aleatória, e não encontramos uma maneira de reproduzi-las. Tudo o que conseguimos foram alguns core dumps.

O Arakoon é escrito em OCaml utiliza a biblioteca Lwt para threads leves (oferecendo suporte para a concorrência).

Existem alguns motivos que causam segmentation faults: escrever ou ler a partir da memória não mapeada, escrever para um mapeamento somente leitura etc. Ao carregar o binário falho e o coredump no depurador GNU, GDB, um backtrace sensível não poderia ser criado. Infelizmente não tenho mais a saída de “bt” por aí.

O backtrace exibido não fazia sentido. Aparentemente, o GDB não foi capaz de construir um backtrace correto. Após um pouco mais de investigação e de bater cabeça, percebemos que o valor do ponteiro da pilha, armazenado no registro “rsp”, ficou a menos de um limite de 4 kilobytes. Olhando para o código ao redor do ponteiro de instrução (o registro morto) no momento do crash, as nossas suspeitas se confirmaram: um valor foi escrito no stack, logo abaixo desse limite de 4k.

Em sistemas Intel x86 (como os que estamos usando, x86-64), o stack é, basicamente, uma região de memória semelhante ao heap, que cresce em direção os endereços mais baixos (para a parte inferior). As falhas que estávamos investigando foram causadas por um stack overflow: o processo que tentou escrever em um endereço abaixo das páginas mapeadas do stack!

Note que, ao usar OCaml, há apenas duas razões para falhas de segmentação, a menos que haja algum bug improvável no gerador/compilador de código: stack overflows ou qualquer coisa que ocorre quando chamamos o código C (no caso em que o problema não esteja relacionado ao OCaml de maneira alguma).

Para gerar um backtrace útil, exigido para ser capaz de identificar o problema e consertá-lo, tivemos que recorrer a outros meios. Ao inspecionar a montagem do código que falhou, bem como o conteúdo da memória do processo logo acima da página alinhada em 4k no topo do ponteiro da pilha, fomos capazes de raciocinar sobre o que aconteceu durante o tempo de execução, e calcular os valores válidos para o stack pointer e para o ponteiro de instruções, isto é, os valores da rsp, e registros mortos válidos no quadro antes daquele em que a segmentation fault ocorreu.

Depois que descobrimos esses dois valores, substituímos as falhas no arquivo binário do core dump usando um editor hexadecimal, pegando a ordem de bytes da máquina na conta (ou seja, ao substituir 0x00007fff5ed6b000, deve-se procurar a seqüência ’0×00 0xb0 0xd6 0x5e 0xff 0x7f 0×00 0×00′!). Uma vez que o core dump era ‘fixado’, podíamos carregá-lo em GDB, e um backtrace válido poderia ser gerado, o que confirmou as nossas suspeitas (havia mais de 1,3 milhão de quadros no stack!), E foi fácil extrair uma sequência recorrente de quadros, aqui está:

#1309851 0x00007f8b7e936d40 in ?? ()
#1309852 0x00000000004c38bd in camlLwt__fun_838 ()
#1309853 0x000000001d457348 in ?? ()
#1309854 0x00000000004c2a3d in camlLwt__fun_724 ()
#1309855 0x00007fffb67bd570 in ?? ()
#1309856 0x00000000004c2a21 in camlLwt__fun_724 ()
#1309857 0x00000000028a2bf8 in ?? ()
#1309858 0x00000000004c3cd0 in camlLwt__run_waiters_rec_207 ()
#1309859 0x000000001d457330 in ?? ()
#1309860 0x000000001d457320 in ?? ()
#1309861 0x00000000007d8dd0 in camlLwt__77 ()
#1309862 0x00000000004c3d7e in camlLwt__run_waiters_231 ()
#1309863 0x0000000000000001 in ?? ()
#1309864 0x00000000004c65fd in camlLwt_mutex__fun_112 ()

Como você pode ver, o compilador OCaml usa um esquema de nome deturpado para gerar nomes de símbolo. Alguns são óbvios (“camlLwt__run_waiters_rec ‘é’ Lwt.run_waiters_rec ‘), outros não são: todos os símbolos ‘*__fun_*’ são devidos aos closures anônimos. Usando o código de montagem dessas funções, juntamente com o código fonte LWT, fomos capazes de reconstruir o que estava acontecendo.

Finalmente descobrimos o que causou os stack overflows que estávamos enfrentando, e poderíamos criar dois pequenos casos de teste, expondo a questão em uma escala mais manejável.

Uma solução alternativa foi criada, e relatamos o problema para os desenvolvedores LWT, que o corrigiram alguns dias depois.Verifique a thread na lista de endereços deles aqui.

Recebemos um novo relatório de falhas de segmentação ocorrendo. Começamos a investigar o core dumpusando GDB mais uma vez, notamos que um backtrace sensível não poderia ser gerado, e tentamos alterar o core dump novamente. Isso foi o que o GDB nos disse:

#0 0x00000000005617c2 in camlLwt__try_bind_1339 ()
(gdb) bt
#0 0x00000000005617c2 in camlLwt__try_bind_1339 ()
#1 0x00007fff5ed6b040 in ?? ()
#2 0x00000000005617a6 in camlLwt__try_bind_1339 ()
#3 0x0000000000000000 in ?? ()
(gdb) p/x $rsp
$1 = 0x7fff5ed6b000
(gdb) p/x $rip
$2 = 0x5617c2

Como você pode ver, o ponteiro da pilha está no limite de 4k novamente. Fazendo uma engenharia reversa da função que falhou, podemos dar uma olhada nos dados do stack:

(gdb) disassemble $rip
Dump of assembler code for function camlLwt__try_bind_1339:
0x0000000000561790 : sub    $0x28,%rsp
0x0000000000561794 : mov    %rax,%rsi
0x0000000000561797 : mov    %rbx,0x18(%rsp)
0x000000000056179c : mov    %rdi,0x10(%rsp)
0x00000000005617a1 : callq  0x5617b0
0x00000000005617a6 : callq  0x560d70
0x00000000005617ab : jmp    0x5617ca
0x00000000005617ad : nopl   (%rax)
0x00000000005617b0 : push   %r14
0x00000000005617b2 : mov    %rsp,%r14
0x00000000005617b5 : mov    $0x1,%rax
0x00000000005617bc : mov    (%rsi),%rdi
0x00000000005617bf : mov    %rsi,%rbx
=> 0x00000000005617c2 :  callq  *%rdi
0x00000000005617c4 : pop    %r14
0x00000000005617c6 : add    $0x8,%rsp
0x00000000005617ca : callq  0x560630

A função subtrai 0×28 de ‘rsp’ na entrada, então o quadro anterior usa ‘rsp + 0×28′  como ponteiro da pilha, que podemos imprimir:

(gdb) x/64 $rsp + 0x28
0x7fff5ed6b028: 0x58002ef0 0x00007f08 0x0774cd58 0x00000000
0x7fff5ed6b038: 0x0055eda5 0x00000000 0x5ed6b0b0 0x00007fff
0x7fff5ed6b048: 0x0055ed87 0x00000000 0x0774cd58 0x00000000
0x7fff5ed6b058: 0x00560785 0x00000000 0x0774cd48 0x00000000
0x7fff5ed6b068: 0x00000001 0x00000000 0x58002f68 0x00007f08
0x7fff5ed6b078: 0x0056080e 0x00000000 0x00000001 0x00000000
0x7fff5ed6b088: 0x00563cdd 0x00000000 0x58002fb8 0x00007f08
0x7fff5ed6b098: 0x0056006d 0x00000000 0x58002f78 0x00007f08
0x7fff5ed6b0a8: 0x0055eda5 0x00000000 0x5ed6b120 0x00007fff
0x7fff5ed6b0b8: 0x0055ed87 0x00000000 0x0774cb30 0x00000000
0x7fff5ed6b0c8: 0x00560785 0x00000000 0x0774cb20 0x00000000
0x7fff5ed6b0d8: 0x00000001 0x00000000 0x58003050 0x00007f08
0x7fff5ed6b0e8: 0x0056080e 0x00000000 0x00000001 0x00000000
0x7fff5ed6b0f8: 0x00563cdd 0x00000000 0x580030a0 0x00007f08
0x7fff5ed6b108: 0x0056006d 0x00000000 0x58003060 0x00007f08
0x7fff5ed6b118: 0x0055eda5 0x00000000 0x5ed6b190 0x00007fff

Se você olhar de perto, você ver um padrão recorrente começando em 0x7fff5ed6b038, pelo menos parcialmente: eles são endereços de funções que fazem parte do loop recursivo, e seus (variados) argumentos. Usando algumas chamadas para fazer ‘info symbol’ e oferecendo e retornando endereços, os nomes das funções podem ser recuperados. Houve muita semelhança com o que nós vimos antes…

Nós desenterramos os casos de teste que usamos antes, e os compilamos usando Lwt 2.3.0, a versão contra a qual o binário Arakoon que estava falhando foi compilado também, e nosso medo se confirmou: o mesmo problema foi introduzido no Lwt novamente, uma regressão! Felizmente, o problema foi corrigido mais tarde de novo: compilar os testes usando Lwt 2.3.2 confirmou isso. Tivemos builds do Arakoon contra Lwt 2.3.2, então os sistemas de produção poderiam ser atualizados para uma versão segura novamente. Acho que deveríamos adicionar os casos de teste do Lwt para a suíte de testes do Arakoon.

Li sobre o suporte para scripts Python introduzido nas versões recentes do GDB e decidi automatizar a depuração desse problema, se possível. Assim, criei um script que implementa um comando GDB novo, ‘ocaml-detect-recursion’, que tem um endereço de stack opcional (o padrão é ‘rsp’), lê um pouco de memória stack, e tenta encontrar endereços de retorno nesses bytes. O buffer é verificado pela leitura de 8 bytes de cada vez (estamos em um sistema de 64 bits, que utiliza 8 endereços de bytes), então verifica se esse valor faz parte de uma função conhecida. Se for, é anexada a um lista.

Uma vez feito isso, um padrão mínimo recorrente é detectado, se possível. O algoritmo utilizado é extremamente simples nesse momento (divide a lista de endereços no n-grams para aumentar valores de n; em seguida, verifica se todos os n-grams são idênticos).

Assim que o padrão recorrente for detectado, um resumo, incluindo os nomes das funções originais, é exibido:

(gdb) source ocaml_detect_recursion.py
(gdb) ocaml-detect-recursion
Recurring call pattern starting at frame 1
==========================================
camlLwt__fun_1826 @ 0x55eda5
camlLwt__fun_1826 @ 0x55ed87
camlLwt__run_waiters_rec_1181 @ 0x560785
camlLwt__run_waiters_1199 @ 0x56080e
camlLwt_mutex__fun_1084 @ 0x563cdd
camlLwt__fun_1956 @ 0x56006d

Usar esse plugin torna a questão muito fácil para depurar caso algum dia ela volte a ocorrer no futuro.

Scripting GDB leva algum tempo (vá verificar os documentos), mas eu acho que vale a pena. Outra característica interessante é personalizar pretty-printers (uma para valores OCaml pode ser útil, *hint hint*).

Para concluir, você pode encontrar o script GDB aqui e aqui. Sinta-se livre para meter o bedelho e melhorá-lo, ou conte pra gente se você foi capaz de depurar um problema usando-o!

***

Texto original disponível em http://blog.incubaid.com/2011/12/04/on-segmentation-faults-stack-overflows-gdb-and-ocaml/