この記事は 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 ではデフォルトで有効になっている)
kernel 2.6.18 ~ kernel 5.13 まではデフォルトで有効。nodelayacct で無効化できる。
- https://github.com/torvalds/linux/commit/163ecdff060f2fa9e8f5238882fd0137493556a6
temporarily enable by defaultとコメントついてるのに 10 数年デフォルトだったのが味わい深い
kernel 5.14 ~ は、デフォルトで無効。delayacct で有効化できる。
使ってみる
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();