5

I'm working on an embedded ARM-based platform. 32-bit, 512MB of RAM, no swap. Linux 3.10.53 (some variety of Ubuntu, if that's relevant).

Some code I'm working on is getting consistently oom-killed, even though everything I can actually measure suggests there's plenty of memory available when it dies. What might be causing this?

Before running the process, free -m reports about 320MB free, which is also close to the LowFree figure in /proc/meminfo; the sum of all numbers from ps -e -o vsize is about 212MB and the slab figure in /proc/meminfo is about 10MB, which handwavily suggest that no more than about 222MB should be being used, which is broadly consistent with the figures for free memory.

So then I run my code, and after a while it gets oom-killed. The note in dmesg says that the process had a total vsize of 180MB; note that this is much less than the 300MB-or-so that was supposedly free before running it. It was this process's own request for memory that triggered the oom-killer.

(It is definitely the oom-killer killing the process; it says as much in dmesg, and my ulimits are unlimited.)

A simple program

I find that I can reproduce the key thing I don't understand using an absolutely trivial program. I'll describe that, and then (in case anyone cares) return to the more complicated program that originally sent me here, on which I've done more extensive tests.

So, here's some code. Boring #includes omitted. 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;
}

Before running this, there appears to be about 320MB free. It allocates 16 10MB blocks and then gets oom-killed when it tries to allocate the 17th.

OK, now back to the original program.

The program this was originally about

If I run the process with strace -e trace=memory (so that I see calls to brk and m[un]map2): firstly, the output seems consistent with the 180MB process size; secondly, the last allocation the process performs immediately before getting oom-killed is of about 15MB.

If I run the process under gdb and stop it as near as I can to the point at which it dies, then:

  • /proc/meminfo's LowFree figure is still about 230MB
  • none of the other figures in /proc/meminfo seem to indicate other memory having been used (e.g., slab is still about 10MB so it doesn't seem like the process has somehow made the kernel allocate a lot)
  • ps reports that the vsize of this process is about 165MB (which is consistent with a 15MB allocation taking it to 180MB, which is evidently when the oom-killer kills it)
  • gdb's info proc mappings doesn't show anything that looks suspicious to me, [EDITED to add:] except that
    • one of the regions it lists has a name like [stack:14958], the number being the LWP ID of one of my threads, and appears to be something like 130MB in size, even though all the big memory allocations in the code are made on the heap via malloc or new. There is a region called heap but it's much smaller.
    • Tracing the process indicates that all those big memory allocations are actually mmap'ed under the hood; I guess that is sufficient to explain this (and so the "stack" name is misleading); but I am ignorant and therefore uncertain. (I have verified that the memory blocks returned by those mmap calls do lie inside that region.)

(Possibly relevant: when stopped there, gdb starts behaving oddly -- e.g., continue makes it say "warning: Unable to fetch general register" and apparently fail to continue running the program) which seems like it could conceivably be triggered by some kind of resource exhaustion.)

[EDITED to add: the process dies a little earlier when run under gdb, which is unsurprising since gdb itself uses a non-negligible amount of memory. Exactly when it dies under gdb apparently depends on, e.g., what breakpoints I set.]

This is all with vm.overcommit_memory=0 and vm.overcommit_ratio=50. Increasing the overcommit ratio to 90 appears to change nothing (but I have verified that the CommitLimit figure in meminfo increases appropriately).

Setting vm.overcommit_memory=2 (which I understand should turn off overcommitment) doesn't appear to change anything, which confuses me a bit (shouldn't disabling overcommit make the allocations fail when they're made, rather than succeed and then trigger the oom-killer?).

Here's what I take to be the most relevant information from the oom-killer's log:

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

If I understand right (a big if), the order=0 indicates that we were only asking for a single page at a time, which seems to rule out fragmentation as the culprit. And this report itself indicates that there are lots of free pages. What's going on?

  • I am not sure about what is happening, but I would suggest checking MemAvailable in /proc/meminfo. There may not be as much usable memory as it looks, especially thinking of DMA, disk caching, ... I would also strongly recommend adding a swap file to give Linux maneuvering space. – Jacopo Oct 17 '18 at 6:26
  • This question used to end with the remark that after rebooting the device, the strange behaviour described here mysteriously went away and (so far as I know) never returned. Someone has just edited the question to remove that. It seems to me like it was relevant information, but I don't want to get into an edit war so I'm leaving this comment instead of editing it back into the question. – Gareth McCaughan Nov 25 '18 at 1:57

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.