Assassino de OOM matando coisas com bastante RAM (?) Livre

O assassino do OOM parece estar matando coisas, apesar de ter mais de RAM livre suficiente no meu sistema:

(Resolução total)

(Resolução total)

27 minutos e 408 processos depois, o sistema começou a responder novamente. Eu o reinicializei cerca de uma hora depois, e logo depois a utilização da memória voltou ao normal (para esta máquina).

Após a inspeção, tenho alguns processos interessantes em execução na minha caixa:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
[...snip...]
root      1399 60702042  0.2 482288 1868 ?     Sl   Feb21 21114574:24 /sbin/rsyslogd -i /var/run/syslogd.pid -c 4
[...snip...]
mysql     2022 60730428  5.1 1606028 38760 ?   Sl   Feb21 21096396:49 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
[...snip...]

Este servidor específico está em execução há aprox. 8 horas, e estes são os únicos dois processos que têm esses ... valores ímpares. Minha suspeita é que "algo mais" esteja acontecendo, potencialmente relevante para esses valores não sensoriais. Especificamente, acho que o sistema pensa que está sem memória, quando na realidade não está. Afinal, ele acha que o rsyslogd está usando 55383984% da CPU de forma consistente, quando o máximo teórico é de 400% neste sistema de qualquer maneira.

Esta é uma instalação totalmente atualizada do CentOS 6 (6.2) com 768MB de RAM. Qualquer sugestão sobre como descobrir por que isso está acontecendo seria apreciada!

editar: anexando a vm. sysctl tunables .. Eu tenho jogado com swappiness (evidenciado por ser 100) e também estou executando um script absolutamente terrível que despeja meus buffers e cache (evidenciado por vm.drop_caches sendo 3) + sincroniza o disco a cada 15 minutos. É por isso que, após a reinicialização, os dados armazenados em cache aumentaram para um tamanho normal, mas depois caíram rapidamente novamente. Reconheço que ter cache é uma coisa muito boa, mas até eu descobrir isso ...

Também interessante é que, embora meu arquivo de paginação tenha aumentado durante o evento, ele atingiu apenas 20% da utilização total possível, o que não é característico de eventos reais de OOM. No outro extremo do espectro, o disco ficou absolutamente louco durante o mesmo período, o que é característico de um evento OOM quando o arquivo de paginação está em execução.

sysctl -a 2>/dev/null | grep '^vm':

vm.overcommit_memory = 1
vm.panic_on_oom = 0
vm.oom_kill_allocating_task = 0
vm.extfrag_threshold = 500
vm.oom_dump_tasks = 0
vm.would_have_oomkilled = 0
vm.overcommit_ratio = 50
vm.page-cluster = 3
vm.dirty_background_ratio = 10
vm.dirty_background_bytes = 0
vm.dirty_ratio = 20
vm.dirty_bytes = 0
vm.dirty_writeback_centisecs = 500
vm.dirty_expire_centisecs = 3000
vm.nr_pdflush_threads = 0
vm.swappiness = 100
vm.nr_hugepages = 0
vm.hugetlb_shm_group = 0
vm.hugepages_treat_as_movable = 0
vm.nr_overcommit_hugepages = 0
vm.lowmem_reserve_ratio = 256   256     32
vm.drop_caches = 3
vm.min_free_kbytes = 3518
vm.percpu_pagelist_fraction = 0
vm.max_map_count = 65530
vm.laptop_mode = 0
vm.block_dump = 0
vm.vfs_cache_pressure = 100
vm.legacy_va_layout = 0
vm.zone_reclaim_mode = 0
vm.min_unmapped_ratio = 1
vm.min_slab_ratio = 5
vm.stat_interval = 1
vm.mmap_min_addr = 4096
vm.numa_zonelist_order = default
vm.scan_unevictable_pages = 0
vm.memory_failure_early_kill = 0
vm.memory_failure_recovery = 1

edit: e anexando a primeira mensagem do OOM ... após uma inspeção mais detalhada, está dizendo que algo claramente saiu do seu caminho para comer a totalidade do meu espaço de troca também.

Feb 21 17:12:49 host kernel: mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0
Feb 21 17:12:51 host kernel: mysqld cpuset=/ mems_allowed=0
Feb 21 17:12:51 host kernel: Pid: 2777, comm: mysqld Not tainted 2.6.32-71.29.1.el6.x86_64 #1
Feb 21 17:12:51 host kernel: Call Trace:
Feb 21 17:12:51 host kernel: [<ffffffff810c2e01>] ? cpuset_print_task_mems_allowed+0x91/0xb0
Feb 21 17:12:51 host kernel: [<ffffffff8110f1bb>] oom_kill_process+0xcb/0x2e0
Feb 21 17:12:51 host kernel: [<ffffffff8110f780>] ? select_bad_process+0xd0/0x110
Feb 21 17:12:51 host kernel: [<ffffffff8110f818>] __out_of_memory+0x58/0xc0
Feb 21 17:12:51 host kernel: [<ffffffff8110fa19>] out_of_memory+0x199/0x210
Feb 21 17:12:51 host kernel: [<ffffffff8111ebe2>] __alloc_pages_nodemask+0x832/0x850
Feb 21 17:12:51 host kernel: [<ffffffff81150cba>] alloc_pages_current+0x9a/0x100
Feb 21 17:12:51 host kernel: [<ffffffff8110c617>] __page_cache_alloc+0x87/0x90
Feb 21 17:12:51 host kernel: [<ffffffff8112136b>] __do_page_cache_readahead+0xdb/0x210
Feb 21 17:12:51 host kernel: [<ffffffff811214c1>] ra_submit+0x21/0x30
Feb 21 17:12:51 host kernel: [<ffffffff8110e1c1>] filemap_fault+0x4b1/0x510
Feb 21 17:12:51 host kernel: [<ffffffff81135604>] __do_fault+0x54/0x500
Feb 21 17:12:51 host kernel: [<ffffffff81135ba7>] handle_pte_fault+0xf7/0xad0
Feb 21 17:12:51 host kernel: [<ffffffff8103cd18>] ? pvclock_clocksource_read+0x58/0xd0
Feb 21 17:12:51 host kernel: [<ffffffff8100f951>] ? xen_clocksource_read+0x21/0x30
Feb 21 17:12:51 host kernel: [<ffffffff8100fa39>] ? xen_clocksource_get_cycles+0x9/0x10
Feb 21 17:12:51 host kernel: [<ffffffff8100c949>] ? __raw_callee_save_xen_pmd_val+0x11/0x1e
Feb 21 17:12:51 host kernel: [<ffffffff8113676d>] handle_mm_fault+0x1ed/0x2b0
Feb 21 17:12:51 host kernel: [<ffffffff814ce503>] do_page_fault+0x123/0x3a0
Feb 21 17:12:51 host kernel: [<ffffffff814cbf75>] page_fault+0x25/0x30
Feb 21 17:12:51 host kernel: Mem-Info:
Feb 21 17:12:51 host kernel: Node 0 DMA per-cpu:
Feb 21 17:12:51 host kernel: CPU    0: hi:    0, btch:   1 usd:   0
Feb 21 17:12:51 host kernel: CPU    1: hi:    0, btch:   1 usd:   0
Feb 21 17:12:51 host kernel: CPU    2: hi:    0, btch:   1 usd:   0
Feb 21 17:12:51 host kernel: CPU    3: hi:    0, btch:   1 usd:   0
Feb 21 17:12:51 host kernel: Node 0 DMA32 per-cpu:
Feb 21 17:12:51 host kernel: CPU    0: hi:  186, btch:  31 usd:  47
Feb 21 17:12:51 host kernel: CPU    1: hi:  186, btch:  31 usd:   0
Feb 21 17:12:51 host kernel: CPU    2: hi:  186, btch:  31 usd:   0
Feb 21 17:12:51 host kernel: CPU    3: hi:  186, btch:  31 usd: 174
Feb 21 17:12:51 host kernel: active_anon:74201 inactive_anon:74249 isolated_anon:0
Feb 21 17:12:51 host kernel: active_file:120 inactive_file:276 isolated_file:0
Feb 21 17:12:51 host kernel: unevictable:0 dirty:0 writeback:2 unstable:0
Feb 21 17:12:51 host kernel: free:1600 slab_reclaimable:2713 slab_unreclaimable:19139
Feb 21 17:12:51 host kernel: mapped:177 shmem:84 pagetables:12939 bounce:0
Feb 21 17:12:51 host kernel: Node 0 DMA free:3024kB min:64kB low:80kB high:96kB active_anon:5384kB inactive_anon:5460kB active_file:36kB inactive_file:12kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:14368kB mlocked:0kB dirty:0kB writeback:0kB mapped:16kB shmem:0kB slab_reclaimable:16kB slab_unreclaimable:116kB kernel_stack:32kB pagetables:140kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:8 all_unreclaimable? no
Feb 21 17:12:51 host kernel: lowmem_reserve[]: 0 741 741 741
Feb 21 17:12:51 host kernel: Node 0 DMA32 free:3376kB min:3448kB low:4308kB high:5172kB active_anon:291420kB inactive_anon:291536kB active_file:444kB inactive_file:1092kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:759520kB mlocked:0kB dirty:0kB writeback:8kB mapped:692kB shmem:336kB slab_reclaimable:10836kB slab_unreclaimable:76440kB kernel_stack:2520kB pagetables:51616kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:2560 all_unreclaimable? yes
Feb 21 17:12:51 host kernel: lowmem_reserve[]: 0 0 0 0
Feb 21 17:12:51 host kernel: Node 0 DMA: 5*4kB 4*8kB 2*16kB 0*32kB 0*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 3028kB
Feb 21 17:12:51 host kernel: Node 0 DMA32: 191*4kB 63*8kB 9*16kB 2*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 3396kB
Feb 21 17:12:51 host kernel: 4685 total pagecache pages
Feb 21 17:12:51 host kernel: 4131 pages in swap cache
Feb 21 17:12:51 host kernel: Swap cache stats: add 166650, delete 162519, find 1524867/1527901
Feb 21 17:12:51 host kernel: Free swap  = 0kB
Feb 21 17:12:51 host kernel: Total swap = 523256kB
Feb 21 17:12:51 host kernel: 196607 pages RAM
Feb 21 17:12:51 host kernel: 6737 pages reserved
Feb 21 17:12:51 host kernel: 33612 pages shared
Feb 21 17:12:51 host kernel: 180803 pages non-shared
Feb 21 17:12:51 host kernel: Out of memory: kill process 2053 (mysqld_safe) score 891049 or a child
Feb 21 17:12:51 host kernel: Killed process 2266 (mysqld) vsz:1540232kB, anon-rss:4692kB, file-rss:128kB

Eu apenas olhei para o despejo de log oom e questiono a precisão desse gráfico. Observe a primeira linha 'Nó 0 DMA32'. Ele diz free:3376kB, min:3448kBe low:4308kB. Sempre que o valor livre cai abaixo do valor baixo, o kswapd deve começar a trocar as coisas até que esse valor volte acima do valor alto. Sempre que o free cai abaixo de min, o sistema basicamente congela até que o kernel o recupere acima do valor min. Essa mensagem também indica que a troca foi completamente usada onde diz Free swap = 0kB.
Então, basicamente, o kswapd foi acionado, mas o swap estava cheio, por isso não podia fazer nada, e o valor de pages_free ainda estava abaixo do valor de pages_min, portanto, a única opção era começar a matar as coisas até que o pág.
Você definitivamente ficou sem memória.

http://web.archive.org/web/20080419012851/http://people.redhat.com/dduval/kernel/min_free_kbytes.html tem uma explicação muito boa de como isso funciona. Veja a seção 'Implementação' na parte inferior.

Livre-se do script drop_caches. Além disso, você deve postar as partes relevantes de sua saída dmesge /var/log/messagesmostrar as mensagens OOM.

Para interromper esse comportamento, no entanto, recomendo tentar esse sysctlajuste. Este é um sistema RHEL / CentOS 6 e está funcionando claramente com recursos restritos. É uma máquina virtual?

Tente modificar /proc/sys/vm/nr_hugepagese veja se os problemas persistem. Isso pode ser um problema de fragmentação da memória, mas veja se essa configuração faz diferença. Para tornar a alteração permanente, adicione vm.nr_hugepages = valueao seu /etc/sysctl.confe execute sysctl -ppara reler o arquivo de configuração ...

Consulte também: Interpretando mensagens criptográficas de "falha na alocação de página" do kernel

Não há dados disponíveis no gráfico desde o momento em que o killer do OOM é iniciado até terminar. Acredito no período em que o gráfico é interrompido que, de fato, o consumo de memória aumenta e não há mais memória disponível. Caso contrário, o assassino da OOM não seria usado. Se você observar o gráfico de memória livre após a interrupção do killer do OOM, poderá ver que ele diminui de um valor mais alto do que antes. Pelo menos ele fez seu trabalho corretamente, liberando memória.

Observe que seu espaço de troca é quase totalmente utilizado até a reinicialização. Isso quase nunca é bom e um sinal claro de que resta pouca memória livre.

A razão pela qual não há dados disponíveis para esse período específico é porque o sistema está muito ocupado com outras coisas. Valores "engraçados" na sua lista de processos podem ser apenas um resultado, não uma causa. Não é algo inédito.

Verifique /var/log/kern.log e / var / log / messages, que informações você pode encontrar lá?

Se o registro também parou, tente outras coisas, despeje a lista de processos em um arquivo a cada segundo, aproximadamente com as informações de desempenho do sistema. Execute-o com alta prioridade para que ele ainda possa fazer seu trabalho (espero) quando a carga aumentar. Embora se você não tiver um kernel preemptor (às vezes indicado como um kernel "servidor"), poderá ter azar nesse aspecto.

Acho que você descobrirá que o (s) processo (s) que está (estão) usando mais% de CPU no momento em que seus problemas começam é (são) a causa. Eu nunca vi o rsyslogd nem o mysql se comportando dessa maneira. Os culpados mais prováveis ​​são aplicativos java e aplicativos guiados por GUI, como um navegador.