CentOS7.5 の fsnotify がレースコンディションを起こすバグを nginx + td-agent + in_tail プラグインで踏む

2018/7/18 追記 3.10.0-862.9.1.el7 で fix されました

hiboma.hatenadiary.jp

2018/7/4 追記 最新の情報はこちらにまとめています

hiboma.hatenadiary.jp

2018/6/16 追記 CentOS Plus の kernel-plus では修正が入っています. 詳しくはこちらをご覧ください

hiboma.hatenadiary.jp

エントリの概要

CentOS7.5 の fsnotify() がレースコンディションを起こすバグを、 nginx + td-agent (fluentd) + in_tail プラグインで踏んだ際の調査内容を記していきます.

イントロダクション

このエントリを書いた時点では、CentOS 7.5.1804 以降でリリースされているカーネルは 3つありますが、カーネルの fsnotify() がレースコンディションを起こすバグを抱えています

  • kernel-3.10.0-862.el7.x86_64
  • kernel-3.10.0-862.2.3.el7.x86_64
  • kernel-3.10.0-862.3.2.el7.x86_64

レースコンディションの修正パッチ

mainline では修正済みです。詳細と修正パッチは以下のコミットで確かめられます

github.com

v4.17-rc3 でパッチがマージされており、 stable にもバックポートされています

CentOS / RHEL は?

CentOS (というか RHEL) で問題は修正されていません.

下記のリンクを見るに、RHEL では問題を認識済みであるようです (サブスクリプションがないので詳細はわかりません)

Soft lockups occur in fsnotify() after updating to RHEL 7.5 - Red Hat Customer Portal

CentOSのバグトラッキングシステムでも把握されているようです

0014823: 3.10.0-862.2.3.el7.x86_64 kernel panic and crash under Xen PV with NMI watchdog: BUG: soft lockup - CPU#2 - CentOS Bug Tracker

2018/6/7 13:50 追記

0006828: Tracking for centosplus kernels for CentOS-7 - CentOS Bug Tracker

f:id:hiboma:20180607135306p:plain

次のリリースで修正が入らない場合に CentOS 側で修正パッチを含めたカーネルを出すようですね. (注意 : distro kernelRHEL を指すのか CentOS を指すのか? CentOS Plus として出すのかな? )

レースコンディションの詳細

コミットログに詳細が記してある のですが ... SRCU という仕組みが関連するあたりが難しくてワカリマセン

勉強中です


カーネル内部で何が起こるには目をつぶり、ユーザランドで「どういう条件が重なる」と「どんなことが起こってしまう」のかでレースコンディションの問題を見ていきましょう.

弊社 GMO ペパボ では、 nginx のログを td-agent + in_tail プラグイン で扱う構成でレースコンディションを踏んでしまう ことを確認しましたので、その事を辿るようにエントリを書いていきます

なお、上記の構成はレースコンディションを踏みうる一例です。問題となるシステムコールを呼び出しをするプロセスがいれば 他の構成でも同じ問題は発生しえます. nginx と td-agent 自体に問題があることを主張するための文章でもありません

レースコンディションの再現コード

nginx + td-agent の話に入る前に、https://bugzilla.kernel.org に再現用のコードが投稿されていたので 先に内容を確かめておきます

199437 – fsnotify: Race between fsnotify() and fsnotify_put_mark() causing kernel panic

inotify.c

#include <sys/inotify.h>
#include <stdio.h>
#include <unistd.h>

/*
 * Calls inotify_rm_watch in a loop.
 */
int main(int argc, char **argv)
{
        if (argc < 2)
        {
                printf("Usage: %s <file_path>\n", argv[0]);
                printf("file_path: the file to watch\n");
                return 0;
        }
        int fd = inotify_init();
        while (1)
        {
                int wd = inotify_add_watch(fd, argv[1], IN_MODIFY);
                inotify_rm_watch(fd, wd);
        }
        close(fd);
}

test.c

#include <stdio.h>
#include <unistd.h>

/*
 * Calls fwrite in a loop.
 */
int main(int argc, char **argv)
{
        if (argc < 2)
        {
                printf("Usage: %s <file_path>\n", argv[0]);
                printf("file_path: the file to write to.\n");
                return 0;
        }
        FILE *f = fopen(argv[1], "w+");
        char s[200] = {[0 ... 199]'a'};
        while(1)
        {
                fwrite(s, sizeof(char), 200, f);
                usleep(1);
        }
        fclose(f);
        return 0;
}

再現用コードには上記をコンパイルして並列実行するシェルスクリプトも添付されています.

シェルスクリプトを実行すると

  • test.c: test-filewrite(2) しまくるプロセス
  • inotify.c: test-fileinofity_add_watch(2), inotify_rm_watch(2) しまくるプロセス

という二つのプロセスを作りレースコンディションを再現しようとします

nginx と td-agent+ in_tail プラグイン でバグを踏むのはなぜ?

再現用コードで呼び出されるシステムコールの組み合わせは、nginx のログを td-agent + in_tail プラグインで扱うと ちょうど同じように呼び出しされます.

  • write(2)
  • inotify_add_watch(2)
  • inotify_rm_watch(2)

の三つです

nginx をトレースしてシステムコールを確かめる

下記は nginx に ab コマンドでリクエストを送っている状態をトレースしたものです. fd 5 = アクセスログwrite(2) しています

-bash-4.2$ sudo strace -e write -p $(pgrep -n -f nginx)
strace: Process 1860 attached
write(5, "vhost:localhost\ttime_local:05/Ju"..., 171) = 171
write(5, "vhost:localhost\ttime_local:05/Ju"..., 171) = 171
write(5, "vhost:localhost\ttime_local:05/Ju"..., 171) = 171
write(5, "vhost:localhost\ttime_local:05/Ju"..., 171) = 171
write(5, "vhost:localhost\ttime_local:05/Ju"..., 171) = 171
write(5, "vhost:localhost\ttime_local:05/Ju"..., 171) = 171

td-agent をトレースしてシステムコールを確かめる

nginx がアクセスログに write(2) し続ける一方で、 td-agent の in_tail プラグインが同じアクセスログinotify_rm_watch(2) , inotify_add_watch(2) しています

-bash-4.2$ sudo strace -fe inotify_rm_watch,inotify_add_watch -p $(pgrep -n -f td-agent)
strace: Process 2180 attached with 3 threads
[pid  2201] inotify_rm_watch(13, 147989) = 0
[pid  2201] inotify_add_watch(13, "/var/log/nginx/access.log", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 147990
[pid  2201] inotify_rm_watch(13, 147990) = 0
[pid  2201] inotify_add_watch(13, "/var/log/nginx/access.log", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 147991
[pid  2201] inotify_rm_watch(13, 147991) = 0
[pid  2201] inotify_add_watch(13, "/var/log/nginx/access.log", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 147992
[pid  2201] inotify_rm_watch(13, 147992) = 0
[pid  2201] inotify_add_watch(13, "/var/log/nginx/access.log", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 147993

nginx + td-agent + in_tail プラグインで再現するには?

nginx + td-agent + in_tail プラグインの構成を作り ab コマンドで並列リクエストを続けることで冒頭のレースコンディションを起こすことを VirtualBox 上の VM で再現をとり確認しています.

再現を取った際の nginx と td-agent の設定ファイルと手順は ここにメモ してあります. 簡易の記述なのはご了承ください

このレースコンディションは 2つのプロセスのシステムコール実行タイミングに依存するので、すぐに再現することもあれば、数十分〜小一時間 再現しなかったりと偶発的なものです. (再現用のコードだと、比較的短時間で再現します).

再現した状態を観察する

何度か試験を繰り返しましたが、

というケースとがあるようです

即座にカーネルパニックする場合

BUG: unable to handle kernel paging request atgeneral prorection fault が出たケースもありました。おそらく、同じバグを踏んでいると思われるのですが、目に見える症状の出方がマチマチです.

BUG: unable to handle kernel paging request at を起こして oops するケース

CentOS Linux 7 (Core)
Kernel 3.10.0-862.2.3.el7.x86_64 on an x86_64

localhost login: [   23.367864] BUG: unable to handle kernel paging request at ffff899600000000
[   23.384008] IP: [<ffffffff9c3f7254>] kmem_cache_alloc+0x74/0x1f0
[   23.398402] PGD 51a2e067 PUD 0                                                                                                                                                                          [   23.408557] Oops: 0000 [#1] SMP                                                                                                                                                                          [   23.417362] Modules linked in: vboxsf(OE) vboxvideo(OE) snd_intel8x0 iosf_mbi crc32_pclmul snd_ac97_codec ghash_clmulni_intel ac97_bus ttm aesni_intel snd_seq drm_kms_helper lrw snd_seq_device gf128mul vboxguest(OE) glue_helper snd_pcm ablk_helper syscopyarea ppdev cryptd sysfillrect sysimgblt fb_sys_fops snd_timer drm snd sg soundcore i2c_piix4 parport_pc video parport i2c_core pcspkr nfsd auth_rpcgss
 nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sd_mod crc_t10dif crct10dif_generic ata_generic pata_acpi ata_piix libata crct10dif_pclmul crct10dif_common e1000 crc32c_intel serio_raw dm_mirror dm_re
gion_hash dm_log dm_mod
[   23.569498] CPU: 1 PID: 1597 Comm: inotify Kdump: loaded Tainted: G           OE  ------------   3.10.0-862.2.3.el7.x86_64 #1
[   23.600439] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[   23.624401] task: ffff899676090000 ti: ffff8996b7240000 task.ti: ffff8996b7240000
[   23.644411] RIP: 0010:[<ffffffff9c3f7254>]  [<ffffffff9c3f7254>] kmem_cache_alloc+0x74/0x1f0
[   23.667427] RSP: 0018:ffff8996b7243e48  EFLAGS: 00010286
[   23.680400] RAX: 0000000000000000 RBX: ffff8996b670e910 RCX: 00000000000cbca4
[   23.698373] RDX: 00000000000cbca3 RSI: 00000000000000d0 RDI: ffff8996b907f800
[   23.716493] RBP: ffff8996b7243e78 R08: 000000000001cdd0 R09: ffffffff9c462dcd
[   23.743627] R10: 0000000000000010 R11: ffffffffffffffe2 R12: ffff899600000000
[   23.763329] R13: 00000000000000d0 R14: ffff8996b907f800 R15: ffff8996b907f800
[   23.792629] FS:  00007f4130049740(0000) GS:ffff8996bcc80000
[   23.822428] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[   23.837351] CR2: ffff899600000000 CR3: 0000000076e26000 CR4: 00000000000606e0
[   23.855582] Call Trace:
[   23.871459]  [<ffffffff9c462dcd>] ? fsnotify_add_mark_locked+0x12d/0x300
[   23.889065]  [<ffffffff9c462dcd>] fsnotify_add_mark_locked+0x12d/0x300
[   23.897725]  [<ffffffff9c464d97>] SyS_inotify_add_watch+0x2f7/0x370
[   23.903972]  [<ffffffff9c91f795>] system_call_fastpath+0x1c/0x21
[   23.911874]  [<ffffffff9c91f6e1>] ? system_call_after_swapgs+0xae/0x146
[   23.919095] Code: 9f c1 63 49 8b 50 08 4d 8b 20 49 8b 40 10 4d 85 e4 0f 84 28 01 00 00 48 85 c0 0f 84 1f 01 00 00 49 63 46 20 48 8d 4a 01 4d 8b 06 <49> 8b 1c 04 4c 89 e0 65 49 0f c7 08 0f 94 c0 84 c0 74 ba 49 63
[   23.942834] RIP  [<ffffffff9c3f7254>] kmem_cache_alloc+0x74/0x1f0
[   23.950611]  RSP <ffff8996b7243e48>
[   23.956812] CR2: ffff899600000000
[   .487196 me:Unletoint eve evmclog (rc: -5)

kdump: dump target is /dev/mapper/VolGroup00-LogVol00
kdump: saving to /sysroot//var/crash/127.0.0.1-2018-06-04-23:48:29/
kdump: saving vmcore-dmesg.txt
kdump: saving vmcore-dmesg.txt complete
kdump: saving vmcore
Copying data                       : [100.0 %] /
kdump: saving vmcore complete

general protection fault を起こすケース

localhost login: [ 6052.280624] general protection fault: 0000 [#1] SMP
[ 6052.284624] Modules linked in: vboxsf(OE) iosf_mbi crc32_pclmul vboxvideo(OE) vboxguest(OE) snd_intel8x0 ghash_clmulni_intel aesni_intel snd_ac97_codec lrw ac97_bus gf128mul snd_seq glue_helper ablk_helper cryptd snd_seq_device snd_pcm ttm snd_timer drm_kms_helper snd
ppdev syscopyarea soundcore sg sysfillrect sysimgblt fb_sys_fops drm i2c_piix4 parport_pc parport video pcspkr i2c_core nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sd_mod crc_t10dif crct10dif_generic ata_generic pata_acpi ata_piix crct10dif_pclmul
crct10dif_common crc32c_intel libata serio_raw e1000 dm_mirror dm_region_hash dm_log dm_mod
[ 6052.317759] CPU: 1 PID: 2577 Comm: inotify Kdump: loaded Tainted: G           OE  ------------   3.10.0-862.2.3.el7.x86_64 #1
[ 6052.325267] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[ 6052.331247] task: ffff883835cbaf70 ti: ffff883800170000 task.ti: ffff883800170000
[ 6052.337337] RIP: 0010:[<ffffffff8fff7254>]  [<ffffffff8fff7254>] kmem_cache_alloc+0x74/0x1f0
[ 6052.344573] RSP: 0018:ffff883800173e48  EFLAGS: 00010282
[ 6052.349713] RAX: 0000000000000000 RBX: ffff88380e53e550 RCX: 0000000000042d7b
[ 6052.354680] RDX: 0000000000042d7a RSI: 00000000000000d0 RDI: ffff88387907f800
[ 6052.359544] RBP: ffff883800173e78 R08: 000000000001cdd0 R09: ffffffff90062dcd
[ 6052.365360] R10: 0000000000000012 R11: ffffffffffffffe2 R12: f000ff53f000ff53
[ 6052.370592] R13: 00000000000000d0 R14: ffff88387907f800 R15: ffff88387907f800
[ 6052.375995] FS:  00007f6235739740(0000) GS:ffff88387cc80000(0000) knlGS:0000000000000000
[ 6052.382505] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 6052.387956] CR2: 00007fd9d8183000 CR3: 0000000075df0000 CR4: 00000000000606e0
[ 6052.393395] Call Trace:
[ 6052.394867]  [<ffffffff90062dcd>] ? fsnotify_add_mark_locked+0x12d/0x300
[ 6052.401130]  [<ffffffff90062dcd>] fsnotify_add_mark_locked+0x12d/0x300
[ 6052.405794]  [<ffffffff90064d97>] SyS_inotify_add_watch+0x2f7/0x370
[ 6052.410556]  [<ffffffff9051f795>] system_call_fastpath+0x1c/0x21
[ 6052.414487]  [<ffffffff9051f6e1>] ? system_call_after_swapgs+0xae/0x146
[ 6052.421338] Code: 9f 01 70 49 8b 50 08 4d 8b 20 49 8b 40 10 4d 85 e4 0f 84 28 01 00 00 48 85 c0 0f 84 1f 01 00 00 49 63 46 20 48 8d 4a 01 4d 8b 06 <49> 8b 1c 04 4c 89 e0 65 49 0f c7 08 0f 94 c0 84 c0 74 ba 49 63
[ 6052.444423] RIP  [<ffffffff8fff7254>] kmem_cache_alloc+0x74/0x1f0
[ 6052.451100]  RSP <ffff883800173e48>
[   .8688]ce Ubl to init devic /ev/mceg rc: -5)

NMI watchdog: BUG: soft lockup - CPU#? stuck for ?s が出る場合

弊社のサービスでは、 production 環境でこのケースを踏んだホストを確認しています. ssh でログインして 下記のような dmesg が採取できます

Jun  5 04:46:22 localhost kernel: INFO: rcu_sched self-detected stall on CPU
Jun  5 04:46:22 localhost kernel: INFO: rcu_sched detected stalls on CPUs/tasks:
Jun  5 04:46:22 localhost kernel: {
Jun  5 04:46:22 localhost kernel: 3
Jun  5 04:46:22 localhost kernel: }
Jun  5 04:46:22 localhost kernel: (detected by 1, t=780019 jiffies, g=69761, c=69760, q=1411242)
Jun  5 04:46:22 localhost kernel: Task dump for CPU 3:
Jun  5 04:46:22 localhost kernel: nginx           R
Jun  5 04:46:22 localhost kernel:  running task
Jun  5 04:46:22 localhost kernel:    0  1242   1240 0x00000088
Jun  5 04:46:22 localhost kernel: Call Trace:
Jun  5 04:46:22 localhost kernel: [<ffffffff82c84a28>] ? iomap_write_end+0x38/0x80
Jun  5 04:46:22 localhost kernel: [<ffffffff82c84bd1>] ? iomap_write_actor+0x161/0x1d0
Jun  5 04:46:22 localhost kernel: [<ffffffffc04f12c2>] ? xfs_file_iomap_end+0x32/0x150 [xfs]
Jun  5 04:46:22 localhost kernel: [<ffffffff82c85177>] ? iomap_apply+0xe7/0x150
Jun  5 04:46:22 localhost kernel: [<ffffffff82c85281>] ? iomap_file_buffered_write+0xa1/0xe0
Jun  5 04:46:22 localhost kernel: [<ffffffff82c84a70>] ? iomap_write_end+0x80/0x80
Jun  5 04:46:22 localhost kernel: [<ffffffffc04f5bec>] ? xfs_iunlock+0xec/0x130 [xfs]
Jun  5 04:46:22 localhost kernel: [<ffffffffc04e93c8>] ? xfs_file_buffered_aio_write+0x298/0x2c0 [xfs]
Jun  5 04:46:22 localhost kernel: [<ffffffff82c619b0>] ? fsnotify+0x3f0/0x510
Jun  5 04:46:22 localhost kernel: [<ffffffff82c1a193>] ? do_sync_write+0x93/0xe0
Jun  5 04:46:22 localhost kernel: [<ffffffff82c1ad18>] ? vfs_write+0x168/0x1f0
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:22 localhost kernel: [<ffffffff82c1ba9f>] ? SyS_write+0x7f/0xf0
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f795>] ? system_call_fastpath+0x1c/0x21
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:22 localhost kernel: {
Jun  5 04:46:22 localhost kernel: 3}  (t=780019 jiffies g=69761 c=69760 q=1411242)
Jun  5 04:46:22 localhost kernel: Task dump for CPU 3:
Jun  5 04:46:22 localhost kernel: nginx           R  running task        0  1242   1240 0x00000088
Jun  5 04:46:22 localhost kernel: Call Trace:
Jun  5 04:46:22 localhost kernel: <IRQ>  [<ffffffff82ace0d8>] sched_show_task+0xa8/0x110
Jun  5 04:46:22 localhost kernel: [<ffffffff82ad1ca9>] dump_cpu_task+0x39/0x70
Jun  5 04:46:22 localhost kernel: [<ffffffff82b487a0>] rcu_dump_cpu_stacks+0x90/0xd0
Jun  5 04:46:22 localhost kernel: [<ffffffff82b4be42>] rcu_check_callbacks+0x442/0x730
Jun  5 04:46:22 localhost kernel: [<ffffffff82b01420>] ? tick_sched_do_timer+0x50/0x50
Jun  5 04:46:22 localhost kernel: [<ffffffff82aa4806>] update_process_times+0x46/0x80
Jun  5 04:46:22 localhost kernel: [<ffffffff82b01220>] tick_sched_handle+0x30/0x70
Jun  5 04:46:22 localhost kernel: [<ffffffff82b01459>] tick_sched_timer+0x39/0x80
Jun  5 04:46:22 localhost kernel: [<ffffffff82abeff6>] __hrtimer_run_queues+0xd6/0x260
Jun  5 04:46:22 localhost kernel: [<ffffffff82abf58f>] hrtimer_interrupt+0xaf/0x1d0
Jun  5 04:46:22 localhost kernel: [<ffffffff82a577fb>] local_apic_timer_interrupt+0x3b/0x60
Jun  5 04:46:22 localhost kernel: [<ffffffff83124063>] smp_apic_timer_interrupt+0x43/0x60
Jun  5 04:46:22 localhost kernel: [<ffffffff831207b2>] apic_timer_interrupt+0x162/0x170
Jun  5 04:46:22 localhost kernel: <EOI>  [<ffffffff82c619b0>] ? fsnotify+0x3f0/0x510
Jun  5 04:46:22 localhost kernel: [<ffffffff82c1a193>] ? do_sync_write+0x93/0xe0
Jun  5 04:46:22 localhost kernel: [<ffffffff82c1ad18>] vfs_write+0x168/0x1f0
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:22 localhost kernel: [<ffffffff82c1ba9f>] SyS_write+0x7f/0xf0
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f795>] system_call_fastpath+0x1c/0x21
Jun  5 04:46:22 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:47 localhost kernel: NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [nginx:1242]
Jun  5 04:46:47 localhost kernel: Modules linked in: vboxsf(OE) vboxvideo(OE) iosf_mbi crc32_pclmul ghash_clmulni_intel snd_intel8x0 ttm snd_ac97_codec drm_kms_helper aesni_intel ac97_bus lrw snd_seq gf128mul syscopyarea glue_helper snd_seq_device ablk_helper sysfillrect cryptd vboxguest(OE) ppdev snd_pcm sysimgblt fb_sys_fops drm snd_timer sg i2c_piix4 snd parport_pc pcspkr soundcore i2c_core parport video nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sd_mod crc_t10dif crct10dif_generic ata_generic pata_acpi ata_piix crct10dif_pclmul crct10dif_common crc32c_intel libata e1000 serio_raw dm_mirror dm_region_hash dm_log dm_mod
Jun  5 04:46:47 localhost kernel: CPU: 3 PID: 1242 Comm: nginx Kdump: loaded Tainted: G           OEL ------------   3.10.0-862.2.3.el7.x86_64 #1
Jun  5 04:46:47 localhost kernel: Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
Jun  5 04:46:47 localhost kernel: task: ffff9666f6018000 ti: ffff966735ef8000 task.ti: ffff966735ef8000
Jun  5 04:46:47 localhost kernel: RIP: 0010:[<ffffffff82c61834>]  [<ffffffff82c61834>] fsnotify+0x274/0x510
Jun  5 04:46:47 localhost kernel: RSP: 0018:ffff966735efbdf0  EFLAGS: 00000246
Jun  5 04:46:47 localhost kernel: RAX: ffff9666f5d6c330 RBX: ffff966735efbe08 RCX: 0000000000000002
Jun  5 04:46:47 localhost kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffffff83be7a40
Jun  5 04:46:47 localhost kernel: RBP: ffff966735efbec0 R08: 0000000000000000 R09: 0000000000000000
Jun  5 04:46:47 localhost kernel: R10: 0000000000000000 R11: 0000000000000000 R12: 00000000dd91595f
Jun  5 04:46:47 localhost kernel: R13: ffff9666c0026c00 R14: 00000000dd91595f R15: 0000000000000000
Jun  5 04:46:47 localhost kernel: FS:  00007ff878468880(0000) GS:ffff96673cd80000(0000) knlGS:0000000000000000
Jun  5 04:46:47 localhost kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun  5 04:46:47 localhost kernel: CR2: 00007f74bf5465f0 CR3: 0000000075f28000 CR4: 00000000000606e0
Jun  5 04:46:47 localhost kernel: Call Trace:
Jun  5 04:46:47 localhost kernel: [<ffffffff82c1a193>] ? do_sync_write+0x93/0xe0
Jun  5 04:46:47 localhost kernel: [<ffffffff82c1ad18>] vfs_write+0x168/0x1f0
Jun  5 04:46:47 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:47 localhost kernel: [<ffffffff82c1ba9f>] SyS_write+0x7f/0xf0
Jun  5 04:46:47 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:47 localhost kernel: [<ffffffff8311f795>] system_call_fastpath+0x1c/0x21
Jun  5 04:46:47 localhost kernel: [<ffffffff8311f6e1>] ? system_call_after_swapgs+0xae/0x146
Jun  5 04:46:47 localhost kernel: Code: 75 a4 4d 85 ed 0f 84 8c 01 00 00 45 8b 65 40 4d 8b 5d 08 41 f7 d4 45 23 65 00 44 23 65 a4 48 85 db 74 08 8b 43 40 f7 d0 41 21 c4 <f6> 05 af 14 ac 00 04 0f 85 08 02 00 00 45 09 f4 0f 84 e6 fe ff

ps でプロセスの様子を見てみました

root      1859  0.0  0.1 122920  2108 ?        Ss   06:08   0:00 nginx: master process /usr/sbin/nginx
nginx     1860 78.4  0.1 123384  3596 ?        R    06:08  12:54  \_ nginx: worker process
td-agent  2177  0.0  1.3 222980 24292 ?        Sl   06:13   0:00 /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --use-v1-config --group td-agent --daemon /var/run/td-agent/td-agent.pid
td-agent  2180 80.3  2.9 256884 53556 ?        Sl   06:13   9:05  \_ /opt/td-agent/embedded/bin/ruby /usr/sbin/td-agent --log /var/log/td-agent/td-agent.log --use-v1-config --group td-agent --daemon /var/run/td-agent/td-agent.pid

nginx はカーネルモードで CPU を掴みっぱなしになっています

-bash-4.2$ sudo cat /proc/1860/stack
[<ffffffffffffffff>] 0xffffffffffffffff

nginx がカーネルモードなので、%system 時間が 100% で張り付きます.

top - 06:26:38 up 24 min,  3 users,  load average: 6.84, 4.25, 2.54
Tasks: 132 total,   6 running, 126 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu2  :  0.0 us,100.0 sy 👈,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu3  :  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  1833256 total,    87336 free,   480728 used,  1265192 buff/cache
KiB Swap:  1572860 total,  1571572 free,     1288 used.  1124856 avail Mem

production のメトリクスでは以下のように system CPU が張り付いていました

f:id:hiboma:20180606110828p:plain

この状態になっても数時間経過するか、あるいは nginx を reload することでリカバリできるようです.

解決策・ワークアラウンドは?

CentOS のバグトラッキングシステム でも同じ問題と思われるレポートがあがっていますが

You have to downgrade to a Centos 7.4 kernel or wait for next Redhat/CentOS kernel update.

とのことです. CentOS7.4 ベースのカーネルを使っていればレースコンディションを踏まないのはソースをみたり、弊社サービスでも確認済み

他に手は?

inotify を使わない手もありそうですが、動かしているシステムや、変更の手間やコストを比較しての手段となるかと思います.

in_tail プラグインの場合 : enable_stat_watcher を false にすることで inotify を使わない方法を選択できます

# lib/fluent/plugin/in_tail.rb

    desc 'Enable the stat watcher based on inotify.'
    config_param :enable_stat_watcher, :bool, default: true

カーネルをダウングレードしてパッチを待つ方が手軽な場合もありそうですね

CentOS 以外は?

4.17-rc3 で取り込まれたパッチなので、他のディストリビューションでも踏む可能性があります. Ubuntu が対応しているのを確認した以外は調べていません

謝辞

弊社サービスでバグを踏んで一時対応をしていた + 調査の際に情報提供をしていただいた id:yano3 さんに感謝かんから