Reading an OOM kill in a journalctl export

Before the Linux kernel kills a process for memory, it writes a report. The report names the thread that asked for memory, the pages each eligible process held and the victim it chose.¹

systemd then writes its own lines about the unit, and two of its settings decide what happens next.⁷ Read both in the right units, and the logs separate what happened from what you suspect.

An example to read along

The report here is INC-0142, an example from the Foxborne example dataset, not a field report. A Q4 recon quad carries a Jetson Orin NX 16 GB companion computer running Linux 5.15.148-tegra. Its perception_node process streams obstacle distances to PX4 and keeps a cache of map tiles.

At 14:32:04.118 UTC the companion’s journal recorded the kill, and a telemetry gap followed. This post reads only the kill, line by line, in the order the kernel printed it.

In the export, each line of the report is a separate entry. Source excerpts below are from the v5.15 tag of mainline Linux.

Who asked: the invoking thread

tile_decode invoked oom-killer: gfp_mask=0x1100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
CPU: 5 PID: 2247 Comm: tile_decode Tainted: G           O      5.15.148-tegra #1
Hardware name: Harrow Q4 compute carrier, Jetson Orin NX 16GB (DT)
Call trace:
...
 out_of_memory+0xf4/0x35c
 __alloc_pages_slowpath.constprop.0+0x7d0/0x964
 __alloc_pages+0x2a8/0x2c0
 alloc_pages_vma+0x9c/0x264
 __handle_mm_fault+0x7e0/0x1060
 handle_mm_fault+0xe8/0x260
 do_page_fault+0x15c/0x530
 do_translation_fault+0x8c/0xa0
...

The first line comes from dump_header(). Its first field is the name of the task that was allocating when memory ran out:¹

pr_warn("%s invoked oom-killer: gfp_mask=%#x(%pGg), order=%d, oom_score_adj=%hd\n",
	current->comm, oc->gfp_mask, &oc->gfp_mask, oc->order,
		current->signal->oom_score_adj);

That task is tile_decode, and the next line gives its ID, 2247. It has no row in the tasks table further down, because that table lists processes.¹ In the example it is a thread of perception_node, pid 2213.

The rest of the line describes the request. gfp_mask holds the allocation flags, printed once as a number and once by name. GFP_HIGHUSER_MOVABLE is the kernel’s mask for user-space pages that reclaim or migration can move.³

order=0 gives the size as a power of two: 2⁰ pages, a single page.² oom_score_adj=0 is the asking process’s score adjustment, the same value the tasks table shows for it.

Read the call trace from the bottom up. tile_decode took a page fault, and the kernel needed a new page to map into its memory. alloc_pages_vma asked for one, and the allocator’s slow path called out_of_memory.²

The frames cut from the top of the excerpt are the report printing itself: oom_kill_process calls dump_header(), which calls dump_stack().¹ So one ordinary page triggered the kill. The kill line reads “Out of memory”, not “Out of memory (oom_kill_allocating_task)”, so the kernel picked its victim by score.¹

Who died, and why: the tasks table

Next come Mem-Info, the kernel’s page counts for the whole machine, and then the tasks table.¹ Its heading says what matters most:

pr_info("Tasks state (memory values in pages):\n");
pr_info("[  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name\n");

The memory columns count pages, except pgtables_bytes, which is in bytes despite the heading.¹ These are six of the example’s 147 rows:

Tasks state (memory values in pages):
[  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
...
[    412]     0   412    12644      987          94208        0          -250 systemd-journal
[    611]   104   611    40211      612          98304        0             0 chronyd
[   1388]  1001  1388    18233     2210         131072        0             0 mavlink-routerd
[   1502]  1001  1502   257411    28310         720896        0             0 collector
[   2186]  1001  2186   512993    60521        1150976        0             0 depth_driver
[   2213]  1001  2213  2968312  1708439       15073280        0             0 perception_node

You do not have to assume the page size. The kill line below prints the victim’s virtual size in kB. It matches this table only at 4 KiB a page: 2,968,312 pages × 4 KiB = 11,873,248 kB.

So the rss column converts to MiB as pages × 4 ÷ 1,024. For perception_node: 1,708,439 × 4 = 6,833,756 KiB, and 6,833,756 ÷ 1,024 = 6,673.6 MiB. depth_driver holds 60,521 pages, 236.4 MiB, and mavlink-routerd holds 2,210 pages, 8.6 MiB.

The kernel does not pick by rss alone. oom_badness() adds swap entries and page-table pages, then adds oom_score_adj in units of a thousandth of the memory in play:¹

points = get_mm_rss(p->mm) + get_mm_counter(p->mm, MM_SWAPENTS) +
	mm_pgtables_bytes(p->mm) / PAGE_SIZE;
task_unlock(p);

/* Normalize to oom_score_adj units */
adj *= totalpages / 1000;
points += adj;

For perception_node that is 1,708,439 + 0 + 15,073,280 ÷ 4,096 = 1,708,439 + 3,680 = 1,712,119. depth_driver scores 60,521 + 0 + 281 = 60,802, so the choice was not close: 28 to 1.

A negative adjustment, like the -250 on systemd-journal, lowers a score. A systemd unit sets it with OOMScoreAdjust=.⁷

Where it ran out: the constraint line

oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/perception.service,task=perception_node,pid=2213,uid=1001

dump_oom_summary() builds this line from several pieces.¹ CONSTRAINT_NONE means no cpuset, memory policy or memory cgroup narrowed the search, so the kernel counted all RAM and swap as the pool.¹

global_oom means the whole machine ran out, not a cgroup at its limit, which would print oom_memcg= instead.⁵ task_memcg is the victim’s memory cgroup, and its path names the systemd unit.⁵ This is where the kernel’s report meets systemd’s.

The kill line, in MiB

Out of memory: Killed process 2213 (perception_node) total-vm:11873248kB, anon-rss:6823516kB, file-rss:10240kB, shmem-rss:0kB, UID:1001 pgtables:14720kB oom_score_adj:0

do_send_sig_info(SIGKILL, SEND_SIG_PRIV, victim, PIDTYPE_TGID);
mark_oom_victim(victim);
pr_err("%s: Killed process %d (%s) total-vm:%lukB, anon-rss:%lukB, file-rss:%lukB, shmem-rss:%lukB, UID:%u pgtables:%lukB oom_score_adj:%hd\n",
	message, task_pid_nr(victim), victim->comm, K(mm->total_vm),
	K(get_mm_counter(mm, MM_ANONPAGES)),
	K(get_mm_counter(mm, MM_FILEPAGES)),
	K(get_mm_counter(mm, MM_SHMEMPAGES)),
	from_kuid(&init_user_ns, task_uid(victim)),
	mm_pgtables_bytes(mm) >> 10, victim->signal->oom_score_adj);

The kernel sends SIGKILL to the whole process first, then prints the line. K() shifts a page count left by PAGE_SHIFT-10 bits, which multiplies by 4 on a 4 KiB page, so the kernel’s kB are KiB.¹

• total-vm: 11,873,248 kB ÷ 1,024 = 11,595.0 MiB of virtual address space.
• anon-rss: 6,823,516 kB ÷ 1,024 = 6,663.6 MiB of anonymous memory, backed by no file.
• file-rss: 10,240 kB = 10.0 MiB. shmem-rss: nothing.
• pgtables: 14,720 kB, which is the table’s 15,073,280 bytes ÷ 1,024.

The three resident counters add to 6,833,756 kB, the table’s 1,708,439 pages × 4. That is by construction: get_mm_rss() returns exactly that sum.⁴ Resident at the kill: 6,673.6 MiB.

What systemd writes next

14:32:04.121  perception.service: A process of this unit has been killed by the OOM killer.
14:32:04.133  perception.service: Main process exited, code=killed, status=9/KILL
14:32:04.134  perception.service: Failed with result 'oom-kill'.
14:32:09.141  perception.service: Scheduled restart job, restart counter is at 1.
14:32:09.214  Started Perception service.

Three milliseconds after the kernel line, systemd logs the OOM kill inside the unit. At .133 the main process is gone, killed by signal 9. At .134 the unit fails with the result oom-kill.

OOMPolicy= sets what systemd does when the kernel kills a process of the unit: continue, stop or kill. Under stop and kill, the man page says the unit ends in the oom-kill failed state, which is what this journal shows. kill also has the kernel kill every other process in the unit.⁷

Here the policy mattered little. The victim was the main process, and by default systemd considers a service stopped when its main process exits.⁷ If the unit sets no policy, it gets DefaultOOMPolicy=, or continue when Delegate= is on.⁷

Restart= decides whether the service comes back. The man page’s table lists termination due to OOM as a restart cause for on-failure, on-abnormal and always.⁷

The restart job was scheduled 5.007 s after the failure: 14:32:09.141 minus 14:32:04.134. RestartSec= defaults to 100 ms, so this unit’s settings ask for something slower.⁷ Ask the running system rather than the file you think it loaded:⁸

systemctl show perception.service -p OOMPolicy -p Restart -p RestartUSec

The new process, pid 3398, was sampled at 412 MiB a second after it started.

Observed, and still a hypothesis

Together, the kernel’s report and systemd’s lines prove a machine-wide shortage, a victim chosen by score and a unit that failed and restarted. They do not prove why perception_node grew. The companion’s journal points one way: at 14:13:53.118 the process logged “map tile cache: cache_max_mb not set; eviction disabled”.

At 14:32:03.412, 0.706 s before the kill, it reported “tile cache: 4,679 tiles, 5,849 MiB, eviction off”. An unbounded cache fits the numbers, but the kernel counts anonymous pages, not tiles. A heap profile, or a bench run with a cache limit set, would turn that into a finding.

The same care applies to the last second. The process samples read 6,402 MiB at 14:32:02.204 and 6,655 MiB at 14:32:03.204, a climb of 253 MiB. The kill line, 0.914 s later, shows only 18.6 MiB more.

The reviewer on this example read that as allocations stalling in reclaim before the kill. It fits, and the report’s next step tests it: record /proc/pressure/memory at 10 Hz during a bench repeat.

Pull it from your own journal

Two commands recover everything above. Pin the boot ID from the export, so a reboot cannot shift what you read:

# The kernel's report: find its first and last lines, with microsecond times
journalctl -k -b 9b2e4c1d0f8a4e57b3c2a1d9e8f7c6b5 -o short-precise -g 'invoked oom-killer|killed process'
# systemd's lines about the unit, one JSON object per entry
journalctl -b 9b2e4c1d0f8a4e57b3c2a1d9e8f7c6b5 -u perception.service -o json

-k adds the match _TRANSPORT=kernel. -u matches the unit’s own messages and systemd’s messages about it, and an all-lowercase -g pattern ignores case.⁹

In JSON, each entry carries __REALTIME_TIMESTAMP and __MONOTONIC_TIMESTAMP in microseconds.¹¹ Both mark when journald received the entry, not when the kernel wrote it.¹⁰ The monotonic timestamps give the same 16 ms from kill to failure: 1,152,920,000 minus 1,152,904,000 µs.

What to write down

The kernel’s report is strong evidence about memory and weak evidence about cause. Write the finding the way the report supports it.