とあるサーバで妙にシステム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のコードからその原因を調査していきました。
clone時のpteコピーの実装
さらにperf reportでより詳細なコールグラフを見てみると、以下のようになります。
perf record -ag perf report --call-graph --stdio -G
上記のコマンドでコールグラフを確認すると、
# Overhead Command Shared Object Symbol
# ........ ............. ............................ .........................................................................
#
6.99% httpd [kernel.kallsyms] [k] copy_pte_range
|
|--97.70%-- 0x6365786575732f6e
| apr_proc_create
| __libc_fork
| entry_SYSCALL_64_fastpath
| SyS_clone
| _do_fork
| copy_process
| dup_mm
| dup_mmap
| copy_page_range
| copy_pte_range
|
|--1.23%-- 0x9500000090
| 0x7f6535c729ae
| __libc_fork
| entry_SYSCALL_64_fastpath
| SyS_clone
| _do_fork
| copy_process
| dup_mm
| dup_mmap
| copy_page_range
| copy_pte_range
|
--1.06%-- 0x900000007a
0x7f6535c729ae
__libc_fork
entry_SYSCALL_64_fastpath
SyS_clone
_do_fork
copy_process
dup_mm
dup_mmap
copy_page_range
copy_pte_range
ふむふむなるほど、やはりclone時に呼ばれるcopy_pte_rangeの処理が支配的に見えます。
そこで、まずはfork時と関係があって、かつ、copy_pte_rangeでCPU食いそうな所を見ると、以下のコードが該当します。
linux-4.3.3/mm/memory.c
do { /* * We are holding two locks at this point - either of them * could generate latencies in another task on another CPU. */ if (progress >= 32) { progress = 0; if (need_resched() || spin_needbreak(src_ptl) || spin_needbreak(dst_ptl)) break; } if (pte_none(*src_pte)) { progress++; continue; } entry.val = copy_one_pte(dst_mm, src_mm, dst_pte, src_pte, vma, addr, rss); if (entry.val) break; progress += 8; } while (dst_pte++, src_pte++, addr += PAGE_SIZE, addr != end);
となっており、ループの条件でendまでループするのですがが、このcopy_pte_rangeは、linux-4.3.3/kernel/fork.cに実装されているdo_forkがsys_cloneから呼び出され、do_fork->_do_fork->copy_process->copy_mm->dup_mm->dup_mmapと呼ばれ、そこからさらにdup_mmap->copy_page_range ->copy_pud_range->copy_pmd_range->copy_pte_rangeという順でそれぞれrangeを舐めるループが呼ばれていきます。
以下の記事の図にあるように、細分化されたrangeをループでたどっていくイメージです。
ref: http://www.reqtc.com/column/linux-hugepage4.html
つまり、始まりのcopy_page_rangeでのend条件は、 unsigned long end = vma->vm_end;であり、これは即ちVMM memory areaの終端となります。
これにより、プロセスが確保するページの量が多いと、ページテーブルサイズが大きくなり、そこに含まれるpteのエントリ数は同様に大きくなるため、このループは基本的には線形に計算量が増加し、それによってclone時のCPU使用時間が高くなっていると考えられます。
pte数を減らしてcloneが速くなるか確認する
となると、この特定条件下でプロセスのメモリ量やその上のレイヤーのアプリやミドルウェア実装を変えることなくOSのみの設定でcloneを速くするためには、pteの数を少なくすれば良いという話になります。
Kernelのコードから、pteの構造体のサイズは、以下のようにunsigned long、即ち8byteであることがわかりますので、
typedef struct { unsigned long pte; } pte_t;
VmRSSが1.5GBのプロセスの場合は、ページサイズは通常4KBなので、pteの数は1.5*1024*1024/4の約384000となり、ページテーブルが占めるサイズは384000*8で約3MBぐらいになります。厳密にはpteを512byteで詰めたりするので誤差はありますが、概ねこの計算で/proc/pid/statsuで得られる値と近い数値が計算できます。
そこで、簡単にpte数を減らして性能を確認するために、HugePagesを使ってみます。HugePagesはページサイズを4KBから2MB、または、1GBに拡張できるので、まずは512倍の2MBにして性能を確認してみることにしました。
十分にpte数が大きい場合は、cloneのpteのコピーループが支配的にCPU使用時間使うと仮定して、上記の計算式でいくと、例えばページサイズが4倍になるとpteの数が1/4になるので、単純計算だとcloneが4倍近く早くなると予想できます。しかし、今回は局所最適であったり、その他の影響もあってオーバーヘッドが遷移していくだろうということで、512倍速くなるわけではなさそうに推測できます。さて、それではどれぐらい改善するのでしょうか。
そこで、以下のようにHugePagesをアプリ・ミドルウェア上でも簡単に使うべく、そこで使われているmallocをHugePagesに割り当てたメモリ領域を使うようにフックして使うことにしました。
- HugePagesの設定
2MBのページサイズのページを10000個確保します。つまり20GB分です。
sudo sysctl -w vm.nr_hugepages=10000
続いて、mallocをフックするために、libhugetlbfsのインタフェースを使ってHugeTable上でmallocを動かすようにLD_PRELOADしてからhttpdを実行します。
- hugetlbfsのインストール
sudo yum install libhugetlbfs.x86_64
- hugetlbfsのmount
mkdir /hugetblfs mount -t hugetlbfs hugetlbfs none /hugetblfs
そして、下記コマンドでLD_PRELOADによりhttpdを起動しましょう。ここで、httpdが4GBぐらいメモリを使うようにするため、VirtualHostの設定を10万個dummyで設定しました。
HUGETLB_MORECORE=yes LD_PRELOAD=/usr/lib64/libhugetlbfs.so /usr/sbin/httpd
すると以下のように、通常起動時は4GBぐらRSSを食っていたのが、以下のように見た目上5MBで起動します。
apache 15640 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15641 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15642 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15643 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15644 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15645 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15646 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd apache 15647 0.0 0.0 4506924 5812 ? S 17:49 0:00 \_ /usr/sbin/httpd
また、HugePagesも5GB程度使っている事がわかります
# cat /proc/meminfo | grep -i huge AnonHugePages: 163840 kB HugePages_Total: 10000 HugePages_Free: 7234 HugePages_Rsvd: 0 HugePages_Surp: 0 Hugepagesize: 2048 kB
この状態で、HugePagesを使う前後でcloneの速度を比較しましょう。前述したとおり、HugePagesはページサイズが2MBでデフォルトのサイズ4KBの4倍なので、pteのエントリ数が25%になり、コピーコストが25%となって4倍高速になるはずです。普通に計算ミスしていて、HugePagesのページサイズはデフォルト4KBの512倍ですね。なので、pteのコピーが支配的であれば概ね512倍近く改善するでしょうが、局所最適やその他のHugePagesを使う影響などにより、結果的にどれほど速くなるかを確認します。
実際にこれも同様にstraceでトレースしてみると、
- HugePages利用時
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f3b2d0c8a10) = 25844 <0.017654>
- デフォルトページサイズ時
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f219b92aa10) = 27592 <0.069164>
結果から、0.069164secかかっていたcloneが、HugePages使用時は0.017654secと4倍早くなっているのが確認できました。
これにより、特定条件下のclone(2)を4倍速くすることができました、わーい。
512倍速くなればわかりやすいのですが、おそらくHugePagesを使うことによってpteの数は減ったものの、別のオーバーヘッドに遷移したのだと予想できますので、そこもまた本記事では深入りせずに今後調査したいと思います。
ページサイズを1GBにしてみる
上記の検証で、結果的にforkが早くなりましたし、例えばCGIを実行するサーバへのApacheベンチ的にもrequest/secは数倍早くなりました。でも、もうちょっと大きなページサイズで試してみたくなりますよね。
ということで、ページサイズを1GBにするとどうなるか試してみました。
そのためには、bootオプションでhugepagesz=1GB default_hugepagesz=1GBを指定してやる必要があります。
kernel /vmlinuz-4.3.3 ro root= (snip) hugepagesz=1GB default_hugepagesz=1GB
これでrebootすると以下のようにHugePagesのsizeが1GBとなっています。事前にページ数は20個にsysctlから設定しています。
# cat /proc/meminfo | grep ^Huge HugePages_Total: 20 HugePages_Free: 20 HugePages_Rsvd: 0 HugePages_Surp: 0 Hugepagesize: 1048576 kB
これで同様にlibhugetlbfsでmountした領域をhttpdのmallocをフックして起動してみましょう。mountオプションにも以下のようにpagesizeを渡してやります。
mount -t hugetlbfs -o pagesize=1G none /hugetblfs
そして、httpdを同様に起動します。
HUGETLB_MORECORE=yes LD_PRELOAD=/usr/lib64/libhugetlbfs.so /usr/sbin/httpd
すると、数GBHugePagesのメモリを使っているようです。
# cat /proc/meminfo | grep Huge AnonHugePages: 73728 kB HugePages_Total: 20 HugePages_Free: 16 HugePages_Rsvd: 0 HugePages_Surp: 0 Hugepagesize: 1048576 kB
しかし、ページサイズがでかすぎるのかプロセスが変な動きをしだして、まともに起動しませんでした。
root 8513 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8514 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8515 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8516 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8517 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8518 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8519 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8520 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8521 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8522 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8523 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8524 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct> root 8525 0.0 0.0 0 0 ? Z 17:45 0:00 \_ [httpd] <defunct>
ここでの深追いは本エントリでは一旦おいておいて（今後調査予定）、とりあえず引き続きの検証を2MBぐらいでまずは試していきます。
また、bootオプションで2MBか1GB以外の値を設定すると、勝手に2MBに変更されてそもそも他の値は使えないことは確認済みです。
HugePagesで割り当てているメモリ領域を超えるとどうなるか
引き続き2MBでの検証を続けましょう。
例えば、HugePages領域のメモリがたりない状態（nr_hugepagesが少ない設定）でhttpdを起動すると、
libhugetlbfs: WARNING: New heap segment map at 0x56551d200000 failed: Cannot allocate memory libhugetlbfs: WARNING: New heap segment map at 0x56551d200000 failed: Cannot allocate memory libhugetlbfs: WARNING: New heap segment map at 0x56551d200000 failed: Cannot allocate memory libhugetlbfs: WARNING: New heap segment map at 0x56551d200000 failed: Cannot allocate memory libhugetlbfs: WARNING: New heap segment map at 0x56551d200000 failed: Cannot allocate memory libhugetlbfs: WARNING: New heap segment map at 0x56551d200000 failed: Cannot allocate memory
普通にメモリ割り当てできなくて起動できません。この辺りの扱いは概ね通常のメモリ管理と同じようです。
また、起動時は起動できるけど、処理する中でメモリ量を超えた場合の挙動も確認してみました。
sysctl -w vm.nr_hugepages=3000
これで、約6GB程度HugePages領域を確保したことになります。
これは、httpdの起動時はなんとかしのげるが、リクエストを処理する中で割り当てたメモリを超えるはずです。一旦起動してみると、以下のようにほとんどのメモリ領域を使用している模様です。
# cat /proc/meminfo | grep ^Huge HugePages_Total: 3000 HugePages_Free: 101 HugePages_Rsvd: 0 HugePages_Surp: 0 Hugepagesize: 2048 kB
そこで、さらにここあらベンチマークをかけてみました。すると、その場合は以下のように普通にメモリ割り当て失敗して死ぬ模様です。
Apacheのエラーログには以下のようなログが出力されました。
[Wed Jul 13 18:05:05.604823 2016] [cgid:error] [pid 11701] (3)No such process: AH01258: cgid daemon is gone; is Apache terminating?: ... php5.6.cgi
libhugetlbfs: WARNING: New heap segment map at 0x55e8a5800000 failed: Cannot allocate memory
[Wed Jul 13 18:03:39.888625 2016] [core:notice] [pid 11690] AH00052: child pid 11744 exit signal Bus error (7)
またdmesgのkernelログにも以下のようなエラーがでていました。
[ 415.458627] PID 10072 killed due to inadequate hugepage pool
ということで、通常のメモリ管理と同様、HugePagesで静的に割り当てているメモリを超えると、allocateに失敗するので、使う場合は例えばhttpdが使用する十分なメモリ領域を確保して使う必要がありそうです。
まとめ
ということで、メモリを多く確保しているプロセスのcloneが遅かったので、その原因をperfやstraceから特定しつつ、その周辺のkernelコードを読むことで遅くなっている原因を仮定し、それを検証によって確認してみました。デバッグのツールやソースコードがすべて公開されているのはやはり最高ですね。
結果的にページサイズを大きくするだけ、という対応ではありますが、ある意味シンプルでわかりやすくて、特定条件下におけるチューニングとしては良いように思いました。
ということで、今後はこの方法が例えばそのままプロダクション環境で安定的に使えるのか、とか、細かい挙動
- RSSが減っているのはなぜか
- libhugetlbのメモリの使い方
- ページサイズ1GBでだめな原因
- コールグラフ的にはcopy_pte_rangeがかなり支配的であったが、4倍程度に収まった理由（オーバーヘッドの遷移）
についてソースからより深く追求していこうかと思っています。
