Zenn
🦔

OOM-Killerの「<プロセス名> invoked oom-killer:」というログ出力を実装から読み解く

2022/01/26に公開
Linux
kernel
oom
tech

はじめに

Linuxを触っていると遭遇するOOM-Killer。OOM-Killerの結果はシステムログに出力されます。その出力をしっかり見たことはあるでしょうか?先日、 OOM-Killerが発動した際にKillされたというログ出力以外に「<プロセス名> invoked oom-killer:」という出力もあることに気が付きました。そのまま読めば、プロセスによってoom-killerが発動されたと読めますが、実際にはどうなっているでしょうか?これを確かめるためにこの記事ではOOM-Killerはどのようなログ出力をしているのかをその実装から読み解いていきます。

OOM-Killerとは

現実のシステムはメモリに限りがあります。メモリを使い果たしてしまうと、システムが正常に動作しなくなってしまいます。そのような最悪の事態を避け、影響を最小化するための機能がOOM-Killerです。具体的にはOOM-Killerはメモリ残容量確保に有効なプロセスを選び、停止(kill)することによりメモリ残容量の健全化を図ります。

実験

まずは実際にOOM-Killerを発生させます。なお今回使った環境は下記です。

[root@ip-10-0-1-43 ~]# uname -a
Linux ip-10-0-1-43.ap-northeast-1.compute.internal 4.14.173-137.229.amzn2.x86_64 #1 SMP Wed Apr 1 18:06:08 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
[root@ip-10-0-1-43 ~]# free -h
              total        used        free      shared  buff/cache   available
Mem:           479M        154M        222M        500K        102M        312M
Swap:            0B          0B          0B

まずはstressコマンドで250 MBのメモリを確保します。

stress --vm 1 --vm-bytes 250M --vm-hang 0

つぎに下記のperlスクリプト[1]により徐々にメモリを確保していきます。

perl -wE 'my @xs; for (1..2**20) { push @xs, q{a} x 2**20 }; say scalar @xs;'

以上を実行した結果、"/var/log/messages"に出力されたログ(の一部)は下記となります。以降はこの出力がどのようになされるかをLinuxの実装を読むことで把握していきます。

Jan 25 12:18:47 ip-10-0-1-43 kernel: perl invoked oom-killer: gfp_mask=0x14201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=(null),  order=0, oom_score_adj=0
Jan 25 12:18:47 ip-10-0-1-43 kernel: perl cpuset=/ mems_allowed=0
(中略)
Jan 25 12:18:47 ip-10-0-1-43 kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Jan 25 12:18:47 ip-10-0-1-43 kernel: [ 2262]     0  2262    11458      166      26       3        0         -1000 systemd-udevd
(中略)
Jan 25 12:18:50 ip-10-0-1-43 kernel: [11104]     0 11104     1893       20       9       3        0             0 stress
Jan 25 12:18:50 ip-10-0-1-43 kernel: [11105]     0 11105    65894    63968     134       3        0             0 stress
Jan 25 12:18:50 ip-10-0-1-43 kernel: [11106]     0 11106    45467    11929      42       3        0             0 perl
(中略)
Jan 25 12:18:50 ip-10-0-1-43 kernel: Out of memory: Kill process 11105 (stress) score 506 or sacrifice child
Jan 25 12:18:50 ip-10-0-1-43 kernel: Killed process 11105 (stress) total-vm:263576kB, anon-rss:255872kB, file-rss:0kB, shmem-rss:0kB

実装を読む

今回参照したソースコードは下記となります。

以降のソースコードは特に断りがない限りmm/oom_kill.cから抜粋しています。

OOMが発動するとまずout_of_memory関数が呼ばれます[2](下記)。

bool out_of_memory(struct oom_control *oc)
 (中略)
        select_bad_process(oc);
 (中略)
                oom_kill_process(oc, !is_memcg_oom(oc) ? "Out of memory" :
                                 "Memory cgroup out of memory");

select_bad_process関数を呼んで"悪い"プロセスを選んだ後、oom_kill_process関数によって対象プロセスをkillしています。

oom_kill_process関数の実装は下記となります。

static void oom_kill_process(struct oom_control *oc, const char *message)
{
        struct task_struct *p = oc->chosen;
    unsigned int points = oc->chosen_points;
    (中略)
                dump_header(oc, p);

        pr_err("%s: Kill process %d (%s) score %u or sacrifice child\n",
                message, task_pid_nr(p), p->comm, points);

    (中略)
                do_send_sig_info(SIGKILL, SEND_SIG_FORCED, p, true);

dump_headerしたあと、pr_errでkillするプロセスを表示し、そのあとdo_send_sig_infoにて実際のkillを実行しています。pr_errで表示されている部分は実験のログ出力の下記に対応します。

Jan 25 12:18:50 ip-10-0-1-43 kernel: Out of memory: Kill process 11105 (stress) score 506 or sacrifice child

次はpがselect_bad_processによって選ばれたプロセスとなることを踏まえて次はdump_headerの実装を見てみましょう。

dump_header関数の実装は下記となります。

static void dump_header(struct oom_control *oc, struct task_struct *p)
{
        pr_warn("%s invoked oom-killer: gfp_mask=%#x(%pGg), nodemask=",
                current->comm, oc->gfp_mask, &oc->gfp_mask);
(中略)
                dump_tasks(oc->memcg, oc->nodemask);
}

pr_warnで表示されている「invoked oom-killer」の前の部分は、p由来ではなくcurrent由来です。currentは現在処理されているプロセスを指しているtask_struct構造体へのポインタです[3]。つまりここではoom-killerを呼び出したプロセスが表示されるようになっています。実験のログ出力の下記に対応します。

Jan 25 12:18:47 ip-10-0-1-43 kernel: perl invoked oom-killer: gfp_mask=0x14201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=(null),  order=0, oom_score_adj=0

次はdump_tasks関数を見ていきます。この関数の実装は下記です。

static void dump_tasks(struct mem_cgroup *memcg, const nodemask_t *nodemask)
{
        struct task_struct *p;
        struct task_struct *task;

        pr_info("[ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name\n");
        rcu_read_lock();
        for_each_process(p) {
                if (oom_unkillable_task(p, memcg, nodemask))
                        continue;

                task = find_lock_task_mm(p);
                if (!task) {
                        /*
                         * This is a kthread or all of p's threads have already
                         * detached their mm's.  There's no need to report
                         * them; they can't be oom killed anyway.
                         */
                        continue;
                }

                pr_info("[%5d] %5d %5d %8lu %8lu %7ld %7ld %8lu         %5hd %s\n",
                        task->pid, from_kuid(&init_user_ns, task_uid(task)),
                        task->tgid, task->mm->total_vm, get_mm_rss(task->mm),
                        atomic_long_read(&task->mm->nr_ptes),
                        mm_nr_pmds(task->mm),
                        get_mm_counter(task->mm, MM_SWAPENTS),
                        task->signal->oom_score_adj, task->comm);
                task_unlock(task);
        }
        rcu_read_unlock();
}

この部分で出力しているのは実験のログ出力の下記以下に対応します。

Jan 25 12:18:47 ip-10-0-1-43 kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name

以上をまとめると実験のログ出力を読み解くとperlによってOOM-Killerが発動し、そのあと各プロセスの状態を表示し、最終的にstressがkillされたことを読み解けます。

まとめ

今回は「<プロセス名> invoked oom-killer:」という出力に疑問を持ち、LinuxのソースコードからOOM-Killerがどのようなログ出力をしているのかを読み解きました。結果、このプロセス名というのはそのとおりOOM-Killerを呼び出したプロセスでした。このプロセスは必ずしもkillされたプロセスとは必ずしも一致しません。上記を踏まえOOM-Killerのログ出力を見るときは正しくkillされたプロセスを読み取りましょう。

脚注

  1. https://isolution.pro/q/au14185822/komando-rain-kara-oom-killer-o-tesutosuru-hoho より ↩︎

  2. 本当はもうひとつcgroupに属していた場合のものもありますが、今回は省略します。 ↩︎

  3. 例えば https://stackoverflow.com/questions/22346545/current-in-linux-kernel-code ↩︎

Discussion