とあるサーバで妙にシステムCPUの使用率が高い現象が置きておりました。
そこで、まずはざっくりとperf top
でプロファイルをとってみると、以下のようになっていました。
22.38% [kernel] [k] copy_pte_range
18.44% [kernel] [k] zap_pte_range
11.13% [kernel] [k] change_pte_range
3.58% [kernel] [k] page_fault
3.32% [kernel] [k] page_remove_rmap
また、各プロセスのstraceを眺めていると、cloneで0.05秒とかなり時間がかかっているようです。これだと単純計算で1コアで秒間20回のcloneでコア100%占有してしまう程度の非常に低速な処理しかできないことになります。
sudo strace -T -o/dev/stdout -p pid | perl -ane '/<([\d\.]+)>/; print $_ if $1 > 0.01;'
...
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f97ea77ea10) = 7333 <0.051777>
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f97ea77ea10) = 7334 <0.053510>
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f97ea77ea10) = 7335 <0.053426>
...
このサーバはforkを沢山するサーバで、そのfork元のプロセスはRSSが2GBとかなりメモリ多めのプロセスとなっていました。単純にはこの時点で、fork時の中で呼ばれるclone(2)から何らかの形でcopy_pte_range
などが呼ばれ、そこで処理に時間がかかって、clone自体が時間がかかっている、と予想できます。
しかしなんだろこれ、ということでKernelのコードからその原因を調査していきました。
続きを読む