読者です 読者をやめる 読者になる 読者になる

人間とウェブの未来

「ウェブの歴史は人類の歴史の繰り返し」という観点から色々勉強しています。

特定条件下のclone(2)を4倍速くする

運用 Webサーバ

とあるサーバで妙にシステム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_forksys_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倍程度に収まった理由(オーバーヘッドの遷移)

についてソースからより深く追求していこうかと思っています。