Análise Forense do OOM-Assassino

Question

O Out-of-Memory Killer do Ubuntu causou estragos em meu servidor, silenciosamente assassinando meus aplicativos, sendmail, apache e outros.

Eu consegui aprender o que o OOM Killer é, e sobre suas regras de "maldade". Enquanto minha máquina é pequena, meus aplicativos são ainda menores, e normalmente apenas metade da minha memória física está em uso, e muito menos espaço de troca, então fiquei surpreso. Estou tentando descobrir o culpado, mas não sei ler os registros do OOM-Killer.

Alguém pode me indicar um tutorial sobre como ler os dados nos logs (quais são ve , free e gen ?) ou me ajudar a analisar esses logs?

Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 1, exc 2326 0 goal 2326 0...
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): task ebb0c6f0, thg d33a1b00, sig 1
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 1, exc 2326 0 red 61795 745
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 2, exc 122 0 goal 383 0...
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): task ebb0c6f0, thg d33a1b00, sig 1
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 2, exc 383 0 red 61795 745
Apr 20 20:03:27 EL135 kernel: kill_signal(13516.0): task ebb0c6f0, thg d33a1b00, sig 2
Apr 20 20:03:27 EL135 kernel: OOM killed process watchdog (pid=14490, ve=13516) exited, free=43104 gen=24501.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=4457, ve=13516) exited, free=43104 gen=24502.
Apr 20 20:03:27 EL135 kernel: OOM killed process ntpd (pid=10816, ve=13516) exited, free=43104 gen=24503.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=27401, ve=13516) exited, free=43104 gen=24504.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=29009, ve=13516) exited, free=43104 gen=24505.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=10557, ve=13516) exited, free=49552 gen=24506.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=24983, ve=13516) exited, free=53117 gen=24507.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=29129, ve=13516) exited, free=68493 gen=24508.
Apr 20 20:03:27 EL135 kernel: OOM killed process sendmail-mta (pid=941, ve=13516) exited, free=68803 gen=24509.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=12418, ve=13516) exited, free=69330 gen=24510.
Apr 20 20:03:27 EL135 kernel: OOM killed process python (pid=22953, ve=13516) exited, free=72275 gen=24511.
Apr 20 20:03:27 EL135 kernel: OOM killed process apache2 (pid=6624, ve=13516) exited, free=76398 gen=24512.
Apr 20 20:03:27 EL135 kernel: OOM killed process python (pid=23317, ve=13516) exited, free=94285 gen=24513.
Apr 20 20:03:27 EL135 kernel: OOM killed process tail (pid=29030, ve=13516) exited, free=95339 gen=24514.
Apr 20 20:03:28 EL135 kernel: OOM killed process apache2 (pid=20583, ve=13516) exited, free=101663 gen=24515.
Apr 20 20:03:28 EL135 kernel: OOM killed process logger (pid=12894, ve=13516) exited, free=101694 gen=24516.
Apr 20 20:03:28 EL135 kernel: OOM killed process bash (pid=21119, ve=13516) exited, free=101849 gen=24517.
Apr 20 20:03:28 EL135 kernel: OOM killed process atd (pid=991, ve=13516) exited, free=101880 gen=24518.
Apr 20 20:03:28 EL135 kernel: OOM killed process apache2 (pid=14649, ve=13516) exited, free=102748 gen=24519.
Apr 20 20:03:28 EL135 kernel: OOM killed process grep (pid=21375, ve=13516) exited, free=132167 gen=24520.
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 4, exc 4215 0 goal 4826 0...
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): task ede29370, thg df98b880, sig 1
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 4, exc 4826 0 red 189481 331
Apr 20 20:03:57 EL135 kernel: kill_signal(13516.0): task ede29370, thg df98b880, sig 2
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 5, exc 3564 0 goal 3564 0...
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): task c6c90110, thg cdb1a100, sig 1
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 5, exc 3564 0 red 189481 331
Apr 20 20:04:53 EL135 kernel: kill_signal(13516.0): task c6c90110, thg cdb1a100, sig 2
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): selecting to kill, queued 0, seq 6, exc 8071 0 goal 8071 0...
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): task d7294050, thg c03f42c0, sig 1
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): selected 1, signalled 1, queued 1, seq 6, exc 8071 0 red 189481 331
Apr 20 20:07:14 EL135 kernel: kill_signal(13516.0): task d7294050, thg c03f42c0, sig 2

Watchdog é uma tarefa de vigilância, que estava ociosa; Nada nos registros para sugerir que tinha feito qualquer coisa por dias. Seu trabalho é reiniciar uma das aplicações se ela morrer, então é um pouco irônico que seja a primeira a ser morta.

O Tail estava monitorando alguns arquivos de registros. É improvável que esteja consumindo a memória loucamente.

O servidor web apache só exibe páginas para uma velhinha que só usa para ir à igreja aos domingos alguns desenvolvedores que estavam na cama dormindo e não visitaram uma página no site por algumas semanas. O único tráfego que pode ter é dos scanners de porta; todo o conteúdo é protegido por senha e não está vinculado de qualquer lugar, portanto não há spiders interessados.

O Python está executando dois aplicativos personalizados separados. Nada nos registros para sugerir que eles não estavam funcionando normalmente. Um deles foi uma implementação relativamente recente, o que torna o suspeito # 1. Ele não possui nenhuma estrutura de dados de qualquer importância e normalmente usa apenas cerca de 8% do total de RAW físico. Não se comportou mal desde então.

O grep é o suspeito # 2, e o que eu quero ser culpado, porque foi um comando que acabou de ser feito. O comando (que canalizou a saída de um grep -r para outro grep) foi iniciado pelo menos 30 minutos antes, e o fato de ainda estar em execução é suspeito. No entanto, eu não teria pensado que o grep usaria uma quantidade significativa de memória. Demorou um pouco para o assassino da OOM chegar a ele, o que sugere que não estava enlouquecendo, mas o assassino da OOM parou quando foi morto, sugerindo que pode ter sido um porco da memória que finalmente satisfez a luxúria de sangue do assassino da OOM. .

    

Answer 1

Sou novo no ServerFault e acabei de ver este post. Parece ter ressurgido perto da frente da fila, embora seja antiga. Vamos colocar esse assustador na cama talvez?

Antes de tudo, tenho interesse neste tópico, pois estou otimizando sistemas com RAM limitada para executar muitos processos de usuário de maneira segura.

É minha opinião que as mensagens de erro neste log estão se referindo aos containers Linux do OpenVZ.

Um "ve" é um ambiente virtual e também conhecido como contêiner no OpenVZ. Cada contêiner recebe um ID e o número que você está vendo é esse ID. Mais sobre isso aqui:

link

O termo "livre" refere-se à memória livre em bytes naquele momento. Você pode ver a memória livre aumentando gradualmente conforme os processos são eliminados.

O termo "gen" estou um pouco inseguro. Eu acredito que isso se refere à geração. Ou seja, começa em 1 e aumenta em um para cada geração de um processo em um contêiner. Então, para o seu sistema, parece que foram executados 24k + processos desde o boot. Por favor me corrija se eu estiver errado. Isso deve ser fácil de testar.

Por que isso matou processos, isso é por causa da sua configuração matadora de OOM. Ele está tentando trazer a memória livre de volta para a quantidade esperada (que parece ser 128 Kb). A Oracle tem uma boa descrição de como configurar isso para algo que você pode gostar mais:

link

Além disso, se você quiser ver a configuração de memória de cada um dos seus contêineres, verifique:

link