delay accounting を使ってみる

この記事は Linux Advent Calendar 2021の8日目の記事です。

delay accouting は、プロセスやスレッドグループが、どれだけカーネルに待たされたかを測定できる仕組み。 たとえばプロセスの動作が遅い原因がカーネルにあるのか・あるとしたらどの処理か?の切り分けで使えると思う。 あとはカーネルにどれくらい待たされてるのか分かって「ふーん」って気持ちになる。

利用条件

次のオプションでカーネルがビルドされていれば、delay accounting が利用できる。 (EC2 の Ubuntu 20.04LTS の場合は、どちらのオプションも設定されている)

$ cat /boot/config-5.4.0-1045-aws | grep -E "DELAY_ACCT|TASKSTATS"
CONFIG_TASKSTATS=y
CONFIG_TASK_DELAY_ACCT=y

boot option でも無効/有効を切り替えられる。カーネルバージョンごとにデフォルトが異なる。 (Ubuntu 20.04 LTS ではデフォルトで有効になっている)

使ってみる

delay accounting は netlink API で情報を公開している。 カーネルソースコード(kernel/tools/accouting)で、この API を利用したツールが用意されている。

今回はこのツールを利用してみる。

$ sudo apt-get source linux-image-$(uname -r)
$ sudo make -C linux-aws-5.4.0/tools/accounting/
make: Entering directory '/home/ubuntu/linux-aws-5.4.0/tools/accounting'
gcc -I../../usr/include    getdelays.c   -o getdelays
make: Leaving directory '/home/ubuntu/linux-aws-5.4.0/tools/accounting'

CPU 負荷をかけると、CPU の項目が上昇するのが分かる。

$ yes > /dev/null
$ ps -ef | grep yes
ubuntu      2104    1001 99 14:02 pts/1    00:00:03 yes
ubuntu      2106     896  0 14:02 pts/0    00:00:00 grep --color=auto yes

$ sudo ./linux-aws-5.4.0/tools/accounting/getdelays -d -p 2104
print delayacct stats ON
PID     2104


CPU             count     real total  virtual total    delay total  delay average
                   85    14683315605    14685896473        1422676          0.017ms
IO              count    delay total  delay average
                    0              0              0ms
SWAP            count    delay total  delay average
                    0              0              0ms
RECLAIM         count    delay total  delay average
                    0              0              0ms
THRASHING       count    delay total  delay average
                    0              0              0ms

IO 負荷をかけると、 IO の項目が上昇するのが分かる。

$ dd if=/dev/zero of=./large count=20 bs=100M
^C13+0 records in
13+0 records out
1363148800 bytes (1.4 GB, 1.3 GiB) copied, 20.5719 s, 66.3 MB/s

$ sudo ./linux-aws-5.4.0/tools/accounting/getdelays -d -p 2137
print delayacct stats ON
PID     2137


CPU             count     real total  virtual total    delay total  delay average
                  449      751849990     1141729647        2777742          0.006ms
IO              count    delay total  delay average
                  417     5069923370             12ms
SWAP            count    delay total  delay average
                    0              0              0ms
RECLAIM         count    delay total  delay average
                    0              0              0ms
THRASHING       count    delay total  delay average
                    0              0              0ms

スワップアウトを発生させると、RECLAIM が上昇するのが分かる。SWAP じゃないんだな?と思って include/linux/taskstats.h を読むと、 SWAP はスワップイン時にカウントするらしい。そして RECLAIM はメモリ獲得時の遅延をカウントするらしい(direct reclaim とかで使う reclaim ですね)。スワップアウトはプロセスがメモリを要求したけど足りなかった→使わないメモリをディスクに書き出してメモリを空ける、という処理が発生するため RECLAIM が上昇した、ということっぽい。

$ stress-ng -m 1 --vm-bytes 5G --timeout 100
stress-ng: info:  [2530] dispatching hogs: 1 vm

$ vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0  92796 3891172   1740  46236    3  267    68   582   58   43  1  1 97  1  0
 0  0  92796 3891112   1740  46228    0    0     0     0   37   24  0  0 100  0  0
 0  0  92796 3891112   1740  46228    0    0     0     0   21   24  0  0 100  0  0
 0  0  92796 3891112   1740  46228    0    0     0     0   37   41  0  0 100  0  0
 0  0  92796 3891112   1740  46228    0    0     0     0   28   35  0  0 100  0  0
 1  0  92540 3287572   2148  53720  740    0  6484     0  508  427 24 12 59  5  0
 1  0  92540 2436256   2148  53804    0    0     0     0  283   32 34 17 50  0  0

$ sudo ./linux-aws-5.4.0/tools/accounting/getdelays -d -p 2532
print delayacct stats ON
PID     2532


CPU             count     real total  virtual total    delay total  delay average
                 5668     6338352936     6513845196       70262862          0.012ms
IO              count    delay total  delay average
                 2426    18685653543              7ms
SWAP            count    delay total  delay average
                    0              0              0ms
RECLAIM         count    delay total  delay average
                 2476    19191033622              7ms
THRASHING       count    delay total  delay average
                    0              0              0ms

実装をながめる

これらのアカウンティング処理がどうやって実装されているかというと、 愚直にカーネル関数内で start と end の差分を ktime_get_ns() で計測して task_struct の delays に付与している。すごい。 Linux カーネルはプリエンプティブで、なおかつ、割込み禁止区間でもなさそうなので(preempt_disable()を呼んでる気配がないので)、 遅延はカーネルの処理が脱線した場合はそれらも含めてすべてが完了するトータル時間になるっぽい。つまり、ユーザ空間から見た待ち時間。 %user や %sys のアカウンティングは、定期的にタイマ割込みをかけて使用した分だけ増加するので、そういう意味で普通のアカウンティングとは異なっている。

static unsigned long do_try_to_free_pages(struct zonelist *zonelist,
                                          struct scan_control *sc)
{
        int initial_priority = sc->priority;
        pg_data_t *last_pgdat;
        struct zoneref *z;
        struct zone *zone;
retry:
        delayacct_freepages_start();

        if (global_reclaim(sc))
                __count_zid_vm_events(ALLOCSTALL, sc->reclaim_idx, 1);

        do {
                vmpressure_prio(sc->gfp_mask, sc->target_mem_cgroup,
                                sc->priority);
                sc->nr_scanned = 0;
                shrink_zones(zonelist, sc);

                if (sc->nr_reclaimed >= sc->nr_to_reclaim)
                        break;

                if (sc->compaction_ready)
                        break;

                /*
                 * If we're getting trouble reclaiming, start doing
                 * writepage even in laptop mode.
                 */
                if (sc->priority < DEF_PRIORITY - 2)
                        sc->may_writepage = 1;
        } while (--sc->priority >= 0);

        last_pgdat = NULL;
        for_each_zone_zonelist_nodemask(zone, z, zonelist, sc->reclaim_idx,
                                        sc->nodemask) {
                if (zone->zone_pgdat == last_pgdat)
                        continue;
                last_pgdat = zone->zone_pgdat;
                snapshot_refaults(sc->target_mem_cgroup, zone->zone_pgdat);
                set_memcg_congestion(last_pgdat, sc->target_mem_cgroup, false);
        }

        delayacct_freepages_end();