matador OOM matando coisas com abundância (?) de RAM livre

Question

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

(Resolução completa )

(Resolução completa )

27 minutos e 408 processos depois, o sistema começou a responder novamente. Eu reiniciei cerca de uma hora depois, e logo em seguida 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á funcionando há aprox. 8 horas, e estes são os dois únicos processos que possuem valores ímpares. Minha suspeita é de que "algo mais" está acontecendo, potencialmente relevante para esses valores não-sensoriais. Em específico, 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% de CPU de forma consistente, quando o máximo teórico é de 400% neste sistema, de qualquer forma.

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!

edite: anexando a vm. sysctl tunables .. Eu tenho jogado com swappiness (evidenciado por ser 100), e eu 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 em cache cresceram para um tamanho um pouco normal, mas depois caíram rapidamente novamente. Eu reconheço que ter cache é uma Coisa Muito Boa, mas até eu entender isso ...

Também um pouco interessante é que, enquanto meu arquivo de paginação cresceu durante o evento, ele atingiu apenas ~ 20% da utilização total possível, o que não é característico de verdadeiros eventos OOM. No outro extremo do espectro, o disco ficou completamente maluco durante o mesmo período, o que é característico de um evento OOM quando o arquivo de paginação está em jogo.

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

edite: e anexando a primeira mensagem da OOM ... após uma inspeção mais detalhada, está dizendo que algo claramente saiu de seu caminho para comer todo o 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

    

Answer 1

Eu apenas olhei para o despejo de log oom, e questiono a precisão desse gráfico. Observe a primeira linha 'Node 0 DMA32'. Ele diz free:3376kB , min:3448kB e low:4308kB . Sempre que o valor livre cair abaixo do valor baixo, o kswapd deve começar a trocar as coisas até que o valor volte acima do valor alto. Sempre que o free cai abaixo de min, o sistema basicamente congela até que o kernel obtenha de volta 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, então não podia fazer nada, e o valor de pages_free ainda estava abaixo do valor pages_min, então a única opção era começar a matar coisas até conseguir o backup de pages_free. Você definitivamente ficou sem memória.

link tem um bom desempenho explicação de como isso funciona. Veja a seção "Implementação" na parte inferior.

    

Answer 2

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

Para interromper esse comportamento, recomendo testar este sysctl sintonizável. Este é um sistema RHEL / CentOS 6 e está claramente rodando em recursos restritos. É uma máquina virtual?

Tente modificar /proc/sys/vm/nr_hugepages e veja se os problemas persistem. Isso pode ser um problema de fragmentação de memória, mas veja se essa configuração faz diferença. Para tornar a mudança permanente, adicione vm.nr_hugepages = value ao seu /etc/sysctl.conf e execute sysctl -p para reler o arquivo de configuração ...

Veja também: Interpretando mensagens de "falha de alocação de página" do kernel criptografado

    

Answer 3

Não há dados disponíveis no gráfico desde quando o assassino da OOM começa até terminar. Acredito no intervalo de tempo em que o gráfico é interrompido que, na verdade, o consumo de memória aumenta e não há mais memória disponível. Caso contrário, o killer da OOM não seria usado. Se você observar o gráfico de memória livre após o killer da OOM parar, poderá ver que ele desce de um valor maior do que antes. Pelo menos, fez o seu trabalho corretamente, liberando memória.

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

O motivo pelo 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 é inédito.

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

Se o log também parar, tente outras coisas, despeje a lista de processos em um arquivo a cada segundo, o mesmo com as informações de desempenho do sistema. Execute-o com alta prioridade para que ele ainda possa fazer seu trabalho (esperançosamente) quando a carga aumentar. Embora, se você não tiver um kernel de preempção (às vezes indicado como um kernel "servidor"), você pode estar sem sorte a esse respeito.

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