Processo morto por OOM killer quando muita memória aparentemente livre

Question

Estou trabalhando em uma plataforma embarcada baseada em ARM. 32 bits, 512 MB de RAM, sem troca. Linux 3.10.53 (alguma variedade de Ubuntu, se for relevante).

Algum código em que estou trabalhando está sendo consistentemente eliminado, embora tudo que eu possa realmente medir sugira que há bastante memória disponível quando ela morre. O que pode estar causando isso?

Antes de executar o processo, o free -m reporta cerca de 320MB grátis , que também está próximo do número LowFree em / proc / meminfo; a soma de todos os números de ps-e-o vsize é de cerca de 212MB e o número de laje em / proc / meminfo é de cerca de 10MB, o que sugere que não mais do que 222MB devem ser usados, o que é consistente com os números de memória livre.

Então eu corro meu código, e depois de um tempo ele é morto. A nota no dmesg diz que o processo teve um total vsize de 180MB ; Note que isto é muito menos do que o 300MB ou então que era supostamente livre antes de executá-lo. Foi o próprio pedido deste processo para memória que acionou o assassino de oom.

(É definitivamente o assassino matando o processo; diz tanto no dmesg, e meus ulimits são ilimitados.)

Um programa simples

Acho que posso reproduzir a coisa chave que não entendo usando um programa absolutamente trivial. Vou descrever isso, e então (no caso de alguém se importar) retornar ao programa mais complicado que originalmente me enviou aqui, no qual fiz testes mais extensos.

Então, aqui está um código. Chato #inclui omitido. Plain ol 'C.

int main(void) {
  int i=0, j;
  char * p;
  while (1) {
    fprintf(stderr, "allocating block %d\n", ++i);
    p = malloc(10000000);
    for (j=0; j<10000000; ++j) p[j] = j; /* touch memory */
  }
  return 0;
}

Antes de executar isso, parece haver cerca de 320 MB livres. Ele aloca 16 blocos de 10MB e, em seguida, recebe oom-kill quando tenta alocar o 17º.

OK, agora de volta ao programa original.

O programa era originalmente sobre

Se eu executar o processo com strace -e trace = memory (para que eu veja chamadas para brk e m [un] map2): em primeiro lugar, a saída parece consistente com o tamanho do processo de 180MB; em segundo lugar, a última alocação que o processo realiza imediatamente antes de ser morto é de cerca de 15MB.

Se eu executar o processo em gdb e pará-lo o mais próximo possível do ponto em que ele morrer, então:

O valor LowFree de
• / proc / meminfo ainda é de cerca de 230MB
• nenhuma das outras figuras em / proc / meminfo parece indicar que outra memória foi usada (por exemplo, slab ainda tem cerca de 10MB, então não parece que o processo tenha feito o kernel alocar muito)
• ps relata que o vsize deste processo é de cerca de 165MB (o que é consistente com uma alocação de 15MB levando-o a 180MB, o que é evidentemente quando o invasor o mata)
• O info proc mappings do gdb não mostra nada que pareça suspeito para mim, [EDITADO para adicionar:] exceto que
  • uma das regiões que ele lista tem um nome como [stack:14958] , o número sendo o ID LWP de um dos meus segmentos e parece ter algo como 130 MB, mesmo que todas as grandes alocações de memória no código sejam feita no heap via malloc ou new . Existe uma região chamada heap , mas é muito menor.
  • Rastrear o processo indica que todas as grandes alocações de memória são realmente mapeadas sob o capô; Eu acho que isso é suficiente para explicar isso (e assim o nome "stack" é enganoso); mas sou ignorante e, portanto, incerto. (Verifiquei que os blocos de memória retornados por essas chamadas mmap estão dentro dessa região.)

(Possivelmente relevante: quando parado lá, o gdb começa a se comportar de forma estranha - por exemplo, continue diz "aviso: não é possível buscar registro geral" e aparentemente falha ao continuar executando o programa) que parece que poderia ser desencadeada por algum tipo de esgotamento de recursos.)

[EDITADO para adicionar: o processo morre um pouco antes quando executado sob o gdb, o que não é surpreendente, já que o próprio gdb usa uma quantidade não desprezível de memória. Exatamente quando ele morre no gdb aparentemente depende, por exemplo, de quais pontos de interrupção eu configurei.]

Tudo isso com vm.overcommit_memory = 0 e vm.overcommit_ratio = 50. Aumentar a taxa de supercomprimimento para 90 parece não mudar nada (mas verifiquei que o valor de CommitLimit no meminfo aumenta apropriadamente).

A definição de vm.overcommit_memory = 2 (que eu entendo que deve desativar o comprometimento excessivo) não parece alterar nada, o que me confunde um pouco (não desabilitar o excesso de comprometimento faz com que as alocações falhem quando elas são feitas, em vez de ter êxito e, em seguida, acionar o assassino de oom?).

Aqui está o que eu considero ser a informação mais relevante do log do assassino:

Sep 24 11:02:04 wandboard kernel: MY_PROCESS_NAME invoked oom-killer: gfp_mask=0x2084d0, order=0, oom_score_adj=0
Sep 24 11:02:04 wandboard kernel: CPU: 0 PID: 14294 Comm: MY_PROCESS_NAME Not tainted 3.10.53-1.1.0_ga-wandboard-06034-g13bb184-dirty #1
Sep 24 11:02:04 wandboard kernel: [<80013acc>] (unwind_backtrace+0x0/0xf8) from [<80011544>] (show_stack+0x10/0x14)
Sep 24 11:02:04 wandboard kernel: [<80011544>] (show_stack+0x10/0x14) from [<8067d0cc>] (dump_header.isra.10+0x64/0x188)
Sep 24 11:02:04 wandboard kernel: [<8067d0cc>] (dump_header.isra.10+0x64/0x188) from [<80092170>] (oom_kill_process+0x270/0x3c8)
Sep 24 11:02:04 wandboard kernel: [<80092170>] (oom_kill_process+0x270/0x3c8) from [<80092710>] (out_of_memory+0x27c/0x2d4)
Sep 24 11:02:04 wandboard kernel: [<80092710>] (out_of_memory+0x27c/0x2d4) from [<80096568>] (__alloc_pages_nodemask+0x834/0x85c)
Sep 24 11:02:04 wandboard kernel: [<80096568>] (__alloc_pages_nodemask+0x834/0x85c) from [<800ab4a0>] (__pte_alloc+0x24/0x13c)
Sep 24 11:02:04 wandboard kernel: [<800ab4a0>] (__pte_alloc+0x24/0x13c) from [<800ae474>] (handle_mm_fault+0xdc/0xf0)
Sep 24 11:02:04 wandboard kernel: [<800ae474>] (handle_mm_fault+0xdc/0xf0) from [<800185e4>] (do_page_fault+0x208/0x368)
Sep 24 11:02:04 wandboard kernel: [<800185e4>] (do_page_fault+0x208/0x368) from [<80008370>] (do_DataAbort+0x34/0x9c)
Sep 24 11:02:04 wandboard kernel: [<80008370>] (do_DataAbort+0x34/0x9c) from [<8000deb4>] (__dabt_usr+0x34/0x40)
Sep 24 11:02:04 wandboard kernel: Exception stack(0x8b6a1fb0 to 0x8b6a1ff8)
Sep 24 11:02:04 wandboard kernel: 1fa0:                                     6dd95001 7ed706a8 6cdfffff 000000e6
Sep 24 11:02:04 wandboard kernel: 1fc0: 6dd95001 000006f2 00000603 7ed706c8 0014c0a0 7ed70910 00000003 7ed706f4
Sep 24 11:02:04 wandboard kernel: 1fe0: 6cdffffe 7ed70690 6ce00000 00195a6c 200f0010 ffffffff
Sep 24 11:02:04 wandboard kernel: Mem-info:
Sep 24 11:02:04 wandboard kernel: DMA per-cpu:
Sep 24 11:02:04 wandboard kernel: CPU    0: hi:   42, btch:   7 usd:  33
Sep 24 11:02:04 wandboard kernel: active_anon:44721 inactive_anon:36 isolated_anon:0
Sep 24 11:02:04 wandboard kernel: active_file:7 inactive_file:1 isolated_file:0
Sep 24 11:02:04 wandboard kernel: unevictable:0 dirty:0 writeback:0 unstable:0
Sep 24 11:02:04 wandboard kernel: free:40238 slab_reclaimable:720 slab_unreclaimable:1594
Sep 24 11:02:04 wandboard kernel: mapped:4 shmem:77 pagetables:257 bounce:0
Sep 24 11:02:04 wandboard kernel: free_cma:39999
Sep 24 11:02:04 wandboard kernel: DMA free:160952kB min:1684kB low:2104kB high:2524kB active_anon:178884kB inactive_anon:144kB active_file:28kB inactive_file:4kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:524288kB managed:177468kB mlocked:0kB dirty:0kB writeback:0kB mapped:16kB shmem:308kB slab_reclaimable:2880kB slab_unreclaimable:6376kB kernel_stack:1160kB pagetables:1028kB unstable:0kB bounce:0kB free_cma:159996kB writeback_tmp:0kB pages_scanned:75 all_unreclaimable? yes
Sep 24 11:02:04 wandboard kernel: lowmem_reserve[]: 0 0 0 0
Sep 24 11:02:04 wandboard kernel: DMA: 3486*4kB (UMC) 3056*8kB (UC) 2814*16kB (MC) 2395*32kB (UMC) 14*64kB (MC) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB 0*32768kB = 160952kB
Sep 24 11:02:04 wandboard kernel: 90 total pagecache pages
Sep 24 11:02:04 wandboard kernel: 0 pages in swap cache
Sep 24 11:02:04 wandboard kernel: Swap cache stats: add 0, delete 0, find 0/0
Sep 24 11:02:04 wandboard kernel: Free swap  = 0kB
Sep 24 11:02:04 wandboard kernel: Total swap = 0kB
Sep 24 11:02:04 wandboard kernel: 131072 pages of RAM
Sep 24 11:02:04 wandboard kernel: 40500 free pages
Sep 24 11:02:04 wandboard kernel: 4710 reserved pages
Sep 24 11:02:04 wandboard kernel: 1715 slab pages
Sep 24 11:02:04 wandboard kernel: 264131 pages shared
Sep 24 11:02:04 wandboard kernel: 0 pages swap cached
Sep 24 11:02:04 wandboard kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
Sep 24 11:02:04 wandboard kernel: [  254]     0   254      623      154       3        0             0 upstart-udev-br
Sep 24 11:02:04 wandboard kernel: [  269]     0   269     2377      156       6        0         -1000 systemd-udevd
Sep 24 11:02:04 wandboard kernel: [  290]   103   290      889      139       5        0             0 dbus-daemon
Sep 24 11:02:04 wandboard kernel: [  348]     0   348      826       46       4        0             0 bluetoothd
Sep 24 11:02:04 wandboard kernel: [  363]     0   363      841       74       5        0             0 systemd-logind
Sep 24 11:02:04 wandboard kernel: [  436]   109   436      705       86       5        0             0 avahi-daemon
Sep 24 11:02:04 wandboard kernel: [  441]   101   441     7429      206       9        0             0 rsyslogd
Sep 24 11:02:04 wandboard kernel: [  444]   109   444      675       55       5        0             0 avahi-daemon
Sep 24 11:02:04 wandboard kernel: [  539]     0   539     1810      176       7        0             0 cups-browsed
Sep 24 11:02:04 wandboard kernel: [  603]     0   603      486       45       3        0             0 upstart-socket-
Sep 24 11:02:04 wandboard kernel: [  606]     0   606      621      185       5        0             0 upstart-file-br
Sep 24 11:02:04 wandboard kernel: [  704]     0   704      845       29       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [  705]     0   705      845       29       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [  709]     0   709      845       29       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [  710]     0   710      845       29       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [  713]     0   713      845       29       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [  734]     0   734     1471      120       6        0         -1000 sshd
Sep 24 11:02:04 wandboard kernel: [  742]     0   742      565       45       5        0             0 cron
Sep 24 11:02:04 wandboard kernel: [  998]     0   998      845       29       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [  999]     0   999      407       28       5        0             0 getty
Sep 24 11:02:04 wandboard kernel: [ 1024]  1000  1024      676       47       4        0             0 ssh-agent
Sep 24 11:02:04 wandboard kernel: [ 8516]     0  8516     1729      222       7        0             0 cupsd
Sep 24 11:02:04 wandboard kernel: [13071]     0 13071     6958      244      11        0             0 console-kit-dae
Sep 24 11:02:04 wandboard kernel: [13136]     0 13136     8426      155      10        0             0 polkitd
Sep 24 11:02:04 wandboard kernel: [13482]     0 13482     2458      192       8        0             0 sshd
Sep 24 11:02:04 wandboard kernel: [13501]  1000 13501     2458      195       8        0             0 sshd
Sep 24 11:02:04 wandboard kernel: [13504]  1000 13504     1491      553       6        0             0 bash
Sep 24 11:02:04 wandboard kernel: [14291]     0 14291     1432      104       5        0             0 sudo
Sep 24 11:02:04 wandboard kernel: [14294]     0 14294    45100    41145      89        0             0 MY_PROCESS_NAME
Sep 24 11:02:04 wandboard kernel: Out of memory: Kill process 14294 (MY_PROCESS_NAME) score 316 or sacrifice child
Sep 24 11:02:04 wandboard kernel: Killed process 14294 (MY_PROCESS_NAME) total-vm:180400kB, anon-rss:164580kB, file-rss:0kB

Se bem entendi (um grande se), a ordem = 0 indica que estávamos pedindo apenas uma página por vez, o que parece excluir a fragmentação como o culpado. E este relatório indica que existem muitas páginas gratuitas. O que está acontecendo?