Alocação de páginas longas no Linux - por que isso acontece?

3

Eu tenho um problema (que eu posso reproduzir de forma confiável) em um monte de hosts Linux, onde o sistema fica completamente sem resposta depois que um processo consome memória de forma agressiva. Eu vejo coisas como esta no log do kernel:

2017-09-14 19:53:51.252365 kernel: hyperkube: page allocation stalls for 62933ms, order:0, mode:0x14201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=(null)
2017-09-14 19:53:51.252402 kernel: hyperkube cpuset=kube-proxy mems_allowed=0
2017-09-14 19:53:51.252440 kernel: CPU: 1 PID: 1438 Comm: hyperkube Not tainted 4.11.9-coreos #1
2017-09-14 19:53:51.252478 kernel: Hardware name: Xen HVM domU, BIOS 4.2.amazon 11/11/2016
2017-09-14 19:53:51.252512 kernel: Call Trace:
2017-09-14 19:53:51.252591 kernel:  dump_stack+0x63/0x90
2017-09-14 19:53:51.252628 kernel:  warn_alloc+0x11c/0x1b0
2017-09-14 19:53:51.252682 kernel:  __alloc_pages_slowpath+0x811/0xe50
2017-09-14 19:53:51.252720 kernel:  ? alloc_pages_current+0x8c/0x110
2017-09-14 19:53:51.258910 kernel:  __alloc_pages_nodemask+0x21b/0x230
2017-09-14 19:53:51.258951 kernel:  alloc_pages_current+0x8c/0x110
2017-09-14 19:53:51.259009 kernel:  __page_cache_alloc+0xae/0xc0
2017-09-14 19:53:51.259041 kernel:  filemap_fault+0x338/0x630
2017-09-14 19:53:51.268298 kernel:  ? filemap_map_pages+0x19d/0x390
2017-09-14 19:53:51.268360 kernel:  ext4_filemap_fault+0x31/0x50 [ext4]
2017-09-14 19:53:51.268397 kernel:  __do_fault+0x1e/0xc0
2017-09-14 19:53:51.268436 kernel:  __handle_mm_fault+0xb06/0x1090
2017-09-14 19:53:51.268471 kernel:  handle_mm_fault+0xd1/0x240
2017-09-14 19:53:51.268504 kernel:  __do_page_fault+0x222/0x4b0
2017-09-14 19:53:51.268539 kernel:  do_page_fault+0x22/0x30
2017-09-14 19:53:51.268572 kernel:  page_fault+0x28/0x30
2017-09-14 19:53:51.268605 kernel: RIP: 0033:0x45d561
2017-09-14 19:53:51.268666 kernel: RSP: 002b:00007f64d3ef2de8 EFLAGS: 00010246
2017-09-14 19:53:51.268717 kernel: RAX: 0000000000000000 RBX: 000000000000007c RCX: 000000000045d561
2017-09-14 19:53:51.268757 kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
2017-09-14 19:53:51.277186 kernel: RBP: 00007f64d3ef2df8 R08: 00007f64d3ef2de8 R09: 0000000000000000
2017-09-14 19:53:51.277239 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
2017-09-14 19:53:51.277283 kernel: R13: 0000000000000034 R14: 0000000000000000 R15: 00000000000000f3
2017-09-14 19:53:51.277322 kernel: Mem-Info:
2017-09-14 19:53:51.277355 kernel: active_anon:903273 inactive_anon:164 isolated_anon:0
                                    active_file:166 inactive_file:754 isolated_file:0
                                    unevictable:0 dirty:0 writeback:0 unstable:0
                                    slab_reclaimable:8251 slab_unreclaimable:17340
                                    mapped:591 shmem:2354 pagetables:4389 bounce:0
                                    free:14896 free_pcp:73 free_cma:0
2017-09-14 19:53:51.277393 kernel: Node 0 active_anon:3613092kB inactive_anon:656kB active_file:864kB inactive_file:2744kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:2364kB dirty:0kB writeback:0kB shmem:9416kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 606208kB writeback_tmp:0kB unstable:0kB pages_scanned:246 all_unreclaimable? no
2017-09-14 19:53:51.288390 kernel: Node 0 DMA free:15052kB min:184kB low:228kB high:272kB active_anon:764kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15900kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:84kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
2017-09-14 19:53:51.288448 kernel: lowmem_reserve[]: 0 3717 3717 3717
2017-09-14 19:53:51.288483 kernel: Node 0 DMA32 free:44532kB min:44868kB low:56084kB high:67300kB active_anon:3612328kB inactive_anon:656kB active_file:912kB inactive_file:2516kB unevictable:0kB writepending:0kB present:3915776kB managed:3841148kB mlocked:0kB slab_reclaimable:33004kB slab_unreclaimable:69276kB kernel_stack:10096kB pagetables:17556kB bounce:0kB free_pcp:412kB local_pcp:156kB free_cma:0kB
2017-09-14 19:53:51.288520 kernel: lowmem_reserve[]: 0 0 0 0
2017-09-14 19:53:51.288553 kernel: Node 0 DMA: 5*4kB (UM) 1*8kB (M) 3*16kB (UM) 2*32kB (UM) 1*64kB (M) 2*128kB (UM) 1*256kB (U) 0*512kB 2*1024kB (UM) 0*2048kB 3*4096kB (ME) = 15052kB
2017-09-14 19:53:51.288609 kernel: Node 0 DMA32: 537*4kB (UMEH) 360*8kB (UMEH) 397*16kB (UMEH) 238*32kB (UMEH) 141*64kB (UMEH) 61*128kB (E) 22*256kB (E) 4*512kB (ME) 1*1024kB (M) 0*2048kB 0*4096kB = 44532kB
2017-09-14 19:53:51.288735 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
2017-09-14 19:53:51.288784 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
2017-09-14 19:53:51.294569 kernel: 3234 total pagecache pages
2017-09-14 19:53:51.294619 kernel: 0 pages in swap cache
2017-09-14 19:53:51.294670 kernel: Swap cache stats: add 0, delete 0, find 0/0
2017-09-14 19:53:51.294747 kernel: Free swap  = 0kB
2017-09-14 19:53:51.294781 kernel: Total swap = 0kB
2017-09-14 19:53:51.294825 kernel: 982941 pages RAM
2017-09-14 19:53:51.300569 kernel: 0 pages HighMem/MovableOnly
2017-09-14 19:53:51.300616 kernel: 18679 pages reserved
2017-09-14 19:53:51.300673 kernel: 0 pages hwpoisoned

Como você pode ver aqui, o sistema aparentemente ficou parado por > 60 segundos tentando alocar memória. Após cerca de 10 minutos do sistema estar completamente inutilizável, o assassino da OOM intervém e mata o processo ganancioso.

Eu realmente adoraria se alguém pudesse me ajudar a entender:

  • Por que o assassino da OOM demora tanto para agir?
  • Por que essas alocações demoram tanto? Se não houver memória disponível, por que isso não falha?
por obeattie 17.09.2017 / 15:22

2 respostas

2

Confiar no assassino da OOM significa que você já perdeu. OOM é apenas um último esforço para evitar um pânico no kernel.

A coleta de dados de desempenho mostrará os sintomas de deixar de responder. Em particular, se a média de carga é muito maior que o número de CPUs, você tem muitos prontos para executar tarefas acumulando. Provavelmente por gastar muito tempo do sistema para escanear páginas de memória. O que resultará em um tempo de resposta ruim.

A respeito de por que não determinar a memória não é trivial, dê uma olhada em Documentation / sysctl / vm.txt especificamente overcommit_memory. O kernel é bastante sofisticado ao fingir que há mais memória disponível, porque o uso físico real é tipicamente muito menor do que o que é alocado. Isso leva um pouco de tempo de CPU, o que pode ser exacerbado em condições de memória patologicamente baixas.

Eu vejo que este é um Xen VM provavelmente no EC2. Nas nuvens, é fácil girar VMs maiores se você quiser lançar recursos para o problema.

Se você suspeitar que esse tanto de alocado é muito para o aplicativo, faça com que seus desenvolvedores olhem seu perfil de memória, como o Valgrind, ou procurando por um kdump quando for retirado do OOM.

    
por 17.09.2017 / 17:48
0

Este é um problema de bug / performance do kernel em MM, no que me diz respeito. O núcleo deve desistir mais cedo, seja iniciando um assassino de OOM ou falhando na alocação.

E, sim, essa máquina estava totalmente sem memória, já que essa era uma alocação de ordem 0 (os poucos MB extras não contam, pois poderiam ser pools de reserva de memória do kernel que essa alocação em particular não tinha permissão para tocar). Talvez o kernel tenha tido mais dificuldade em satisfazer uma alocação de __GFP_COLD, mas não deveria ter levado 62 segundos!

    
por 30.08.2018 / 22:30