0

I have come across plenty of info on oom in general but not much to identify the root cause of the issue. OOm killer kills processes based on its scoring but the process it kills need not be the one that hogs the memory. In my embedded system there is just a journal log I can rely on this hard to reproduce issue. How am I to deduce the memory hogging process from this ? How do I make sense of the OOM killer's log dump ?

Jan 16 14:30:41 Esystem kernel: steaming_device_driver invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
Jan 16 14:30:41 Esystem kernel: CPU: 0 PID: 386 Comm: steaming_device_driver Tainted: G           O      5.4.47-1.3.0-511_02111356_a81cba7f+DEBUG+g5ec03d06f54e #1
Jan 16 14:30:41 Esystem kernel: Hardware name: i.MX8MNano DDR4 board (DT)
Jan 16 14:30:41 Esystem kernel: Call trace:
Jan 16 14:30:41 Esystem kernel:  dump_backtrace+0x0/0x140
Jan 16 14:30:41 Esystem kernel:  show_stack+0x14/0x20
Jan 16 14:30:41 Esystem kernel:  dump_stack+0xb4/0xf8
Jan 16 14:30:41 Esystem kernel:  dump_header+0x44/0x1ec
Jan 16 14:30:41 Esystem kernel:  oom_kill_process+0x1d4/0x1d8
Jan 16 14:30:41 Esystem kernel:  out_of_memory+0x170/0x4e0
Jan 16 14:30:41 Esystem kernel:  __alloc_pages_slowpath+0x954/0x9f8
Jan 16 14:30:41 Esystem kernel:  __alloc_pages_nodemask+0x21c/0x280
Jan 16 14:30:41 Esystem kernel:  alloc_pages_current+0x7c/0xe8
Jan 16 14:30:41 Esystem kernel:  __page_cache_alloc+0x80/0xa8
Jan 16 14:30:41 Esystem kernel:  pagecache_get_page+0x150/0x300
Jan 16 14:30:41 Esystem kernel:  filemap_fault+0x544/0x950
Jan 16 14:30:41 Esystem kernel:  ext4_filemap_fault+0x30/0x8b8
Jan 16 14:30:41 Esystem kernel:  __do_fault+0x4c/0x188
Jan 16 14:30:41 Esystem kernel:  __handle_mm_fault+0xb5c/0x10a0
Jan 16 14:30:41 Esystem kernel:  handle_mm_fault+0xdc/0x1a8
Jan 16 14:30:41 Esystem kernel:  do_page_fault+0x130/0x460
Jan 16 14:30:41 Esystem kernel:  do_translation_fault+0x5c/0x78
Jan 16 14:30:41 Esystem kernel:  do_mem_abort+0x3c/0x98
Jan 16 14:30:41 Esystem kernel:  do_el0_ia_bp_hardening+0x38/0xb8
Jan 16 14:30:41 Esystem kernel:  el0_ia+0x18/0x1c
Jan 16 14:30:41 Esystem kernel: Mem-Info:
Jan 16 14:30:41 Esystem kernel: active_anon:95298 inactive_anon:96 isolated_anon:0
                                     active_file:141 inactive_file:467 isolated_file:0
                                     unevictable:0 dirty:0 writeback:0 unstable:0
                                     slab_reclaimable:2677 slab_unreclaimable:8348
                                     mapped:112 shmem:205 pagetables:846 bounce:0
                                     free:1314 free_pcp:0 free_cma:0
Jan 16 14:30:41 Esystem kernel: Node 0 active_anon:381192kB inactive_anon:384kB active_file:564kB inactive_file:1868kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:448kB dirty:0kB writeback:0kB shmem:820kB shmem_thp: 0kB shmem_pmdmapp
Jan 16 14:30:41 Esystem kernel: Node 0 DMA32 free:5256kB min:7092kB low:7636kB high:8180kB active_anon:381192kB inactive_anon:384kB active_file:564kB inactive_file:1868kB unevictable:0kB writepending:0kB present:491520kB managed:454112kB mlocked:0kB 
Jan 16 14:30:41 Esystem kernel: lowmem_reserve[]: 0 0 0
Jan 16 14:30:41 Esystem kernel: Node 0 DMA32: 112*4kB (UMEC) 184*8kB (UE) 117*16kB (UE) 46*32kB (UE) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB 0*32768kB = 5264kB
Jan 16 14:30:41 Esystem kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jan 16 14:30:41 Esystem kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=32768kB
Jan 16 14:30:41 Esystem kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jan 16 14:30:41 Esystem kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=64kB
Jan 16 14:30:41 Esystem kernel: 812 total pagecache pages
Jan 16 14:30:41 Esystem kernel: 0 pages in swap cache
Jan 16 14:30:41 Esystem kernel: Swap cache stats: add 0, delete 0, find 0/0
Jan 16 14:30:41 Esystem kernel: Free swap  = 0kB
Jan 16 14:30:41 Esystem kernel: Total swap = 0kB
Jan 16 14:30:41 Esystem kernel: 122880 pages RAM
Jan 16 14:30:41 Esystem kernel: 0 pages HighMem/MovableOnly
Jan 16 14:30:41 Esystem kernel: 9352 pages reserved
Jan 16 14:30:41 Esystem kernel: 32768 pages cma reserved
Jan 16 14:30:41 Esystem kernel: 0 pages hwpoisoned
Jan 16 14:30:41 Esystem kernel: Tasks state (memory values in pages):
Jan 16 14:30:41 Esystem kernel: [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Jan 16 14:30:41 Esystem kernel: [    292]     0   292     9543      157    98304        0          -250 systemd-journal
Jan 16 14:30:41 Esystem kernel: [    306]     0   306     3159      191    57344        0         -1000 systemd-udevd
Jan 16 14:30:41 Esystem kernel: [    317]   993   317     4079      123    57344        0             0 systemd-network
Jan 16 14:30:41 Esystem kernel: [    331]     0   331    19289       37    45056        0             0 rngd
Jan 16 14:30:41 Esystem kernel: [    332]   992   332     1926       99    53248        0             0 systemd-resolve
Jan 16 14:30:41 Esystem kernel: [    333]   991   333    20408      110    65536        0             0 systemd-timesyn
Jan 16 14:30:41 Esystem kernel: [    339]     0   339      880       65    49152        0             0 auto-update.sh
Jan 16 14:30:41 Esystem kernel: [    340]   995   340     1210       86    45056        0             0 avahi-daemon
Jan 16 14:30:41 Esystem kernel: [    345]     0   345      799       31    40960        0             0 klogd
Jan 16 14:30:41 Esystem kernel: [    347]   995   347     1179       63    45056        0             0 avahi-daemon
Jan 16 14:30:41 Esystem kernel: [    348]     0   348      799       26    45056        0             0 syslogd
Jan 16 14:30:41 Esystem kernel: [    350]   996   350     1128      149    49152        0          -900 dbus-daemon
Jan 16 14:30:41 Esystem kernel: [    352]     0   352     2151      174    61440        0             0 ofonod
Jan 16 14:30:41 Esystem kernel: [    365]   998   365      926       65    45056        0             0 rpcbind
Jan 16 14:30:41 Esystem kernel: [    372]     0   372    37478       22    53248        0             0 tee-supplicant
Jan 16 14:30:41 Esystem kernel: [    381]     0   381     1924      122    57344        0             0 systemd-logind
Jan 16 14:30:41 Esystem kernel: [    385]     0   385     1037       59    49152        0             0 xsystrack
Jan 16 14:30:41 Esystem kernel: [    386]     0   386    98589      172   131072        0             0 steaming_device_driver
Jan 16 14:30:41 Esystem kernel: [    387]     0   387   131366      145   151552        0             0 user_psu_daemon
Jan 16 14:30:41 Esystem kernel: [    389]     0   389   203209     3492   274432        0             0 xproc_manager.py
Jan 16 14:30:41 Esystem kernel: [    431]     0   431      511       37    45056        0             0 hciattach
Jan 16 14:30:41 Esystem kernel: [    434]     0   434     1696      150    57344        0             0 bluetoothd
Jan 16 14:30:41 Esystem kernel: [    456]     0   456     2524      190    53248        0             0 wpa_supplicant
Jan 16 14:30:41 Esystem kernel: [    457]   997   457      791      145    45056        0             0 rpc.statd
Jan 16 14:30:41 Esystem kernel: [    460]     0   460     9884      162    69632        0             0 tcf-agent
Jan 16 14:30:41 Esystem kernel: [    461]     0   461      648       24    40960        0             0 xinetd
Jan 16 14:30:41 Esystem kernel: [    466]     0   466     1252       32    45056        0             0 agetty
Jan 16 14:30:41 Esystem kernel: [    467]     0   467      509       26    45056        0             0 agetty
Jan 16 14:30:41 Esystem kernel: [    477]     0   477      509       26    40960        0             0 agetty
Jan 16 14:30:41 Esystem kernel: [    489]     0   489     4640       18    45056        0             0 umtprd
Jan 16 14:30:41 Esystem kernel: [    541]     0   541   206089    20731   385024        0             0 application1
Jan 16 14:30:41 Esystem kernel: [    574]     0   574   309918    60424  1114112        0             0 python3
Jan 16 14:30:41 Esystem kernel: [    658]     0   658    71768     2840   143360        0             0 updater
Jan 16 14:30:41 Esystem kernel: [ 102299]     0 102299     1935      155    57344        0             0 sshd
Jan 16 14:30:41 Esystem kernel: [ 102302]     0 102302     2320      242    65536        0             0 systemd
Jan 16 14:30:41 Esystem kernel: [ 102303]     0 102303    23402      523    69632        0             0 (sd-pam)
Jan 16 14:30:41 Esystem kernel: [ 102312]     0 102312      940      128    45056        0             0 sh
Jan 16 14:30:41 Esystem kernel: [ 102342]     0 102342    26140       94   241664        0             0 journalctl
Jan 16 14:30:41 Esystem kernel: [ 120859]     0 120859   108920     3034   155648        0             0 sch_manage
Jan 16 14:30:41 Esystem kernel: [ 120885]     0 120885      855       51    49152        0             0 sh
Jan 16 14:30:41 Esystem kernel: [ 120886]     0 120886      880       65    49152        0             0 auto-update.sh
Jan 16 14:30:41 Esystem kernel: [ 120888]     0 120888      499       23    36864        0             0 ls
Jan 16 14:30:41 Esystem kernel: [ 120889]     0 120889      480       19    45056        0             0 head
Jan 16 14:30:41 Esystem kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/nw.service,task=python3,pid=574,uid=0
Jan 16 14:30:41 Esystem kernel: Out of memory: Killed process 574 (python3) total-vm:1239672kB, anon-rss:241684kB, file-rss:0kB, shmem-rss:12kB, UID:0 pgtables:1088kB oom_score_adj:0
Jan 16 14:30:41 Esystem kernel: sched: RT throttling activated
Jan 16 14:30:41 Esystem kernel: oom_reaper: reaped process 574 (python3), now anon-rss:0kB, file-rss:0kB, shmem-rss:4kB
Jan 16 14:30:40 Esystem kernel[345]: [53284.724775] steaming_device_driver invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0

How do I interpret this ? Is there any documentation on this?

0

1 Answer 1

1

RSS is resident set size, in other words the RAM consumption of a process. Process IDs 541 (application1) and 574 (python3) are by far the biggest as far as RSS is concerned. And 574 received the death penalty.

Now, "python3" is not extremely specific, but if you know the stuff that's running on your system, you can probably figure out what process that was.

Regarding documentation, I would search oom site:kernel.org for a start, or look at publications like linuxtoday or the Linux Journal.

After reading OOM documentation, it's obvious to me that virtual, not physical memory is used to determine which process should be terminated. Caveat: I have not checked if that documentation page is still up to date.

6
  • Do you know if RSS in bytes or KB or KiB ?
    – preetam
    Mar 16, 2021 at 21:28
  • The answer is in the log message: "memory values in pages". Also, near the end: "Killed process 574 (python3) total-vm:1239672kB, anon-rss:241684kB". This matches the 60424 pages in the "task states" list. Mar 16, 2021 at 21:37
  • I don't see pagesl. Are you referring to pgtables_bytes.
    – preetam
    Mar 17, 2021 at 0:24
  • Jan 16 14:30:41 Esystem kernel: Tasks state (memory values in pages): Mar 17, 2021 at 0:44
  • Shouldn't I be considering the total_vm instead of rss as this seems to be a swap lless system ?
    – preetam
    Mar 17, 2021 at 5:03

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.