ラベル perf の投稿を表示しています。 すべての投稿を表示
ラベル perf の投稿を表示しています。 すべての投稿を表示

2015/09/27

Hadoop : CPU system 使用率高騰 "zone_reclaim_mode = 1" 編

はじめに


 会社で PB 級の Hadoop クラスタを運用していますが、ある日から Datanode の CPU system (Kernel 内での CPU 使用率) が高騰し、Job が遅延するという症状が発現しました。Hadoop で CPU system 高騰というと、 Transparent HugePage 設定が有名ですが、そちらについては既に特定し、対策済みでした。 THP と Hadoop に関係については下記 Blog が詳しいです。
Transparent Huge Pages and Hadoop Workloads

 今回は THP ではなく、 "zone_reclaim_mode" の設定による性能劣化について、現象から原因特定に至るまでの経緯と、推奨する設定について解説します。

現象


 観測された現象について簡単に箇条書きします。
  1. CPU user が 5% 程度の時でも CPU system が30% を超えるなど、 Kernel 内での CPU 使用率が異常に高かった
  2. CPU 使用率高騰により、いくつかの Job 実行時間が、問題発生前と比較して 1.5 倍に増えた
  3. 一部のマシンで発生し、他のモデルのマシンでは発生しなかった

perf による原因調査


Kernel 内での CPU 使用率が高騰した際には perf と呼ばれる Linux Profiling Tool が非常に有用です。特別な準備をする必要なく、簡単に Profiling を取得できます。
 今回は Profiling により、 "どの関数で CPU を使用しているのか" 、 "どの処理で問題の関数が呼ばれるのか(Call Graph)" を調査します。

perf での Profiling 取得

 CPU system が高騰したタイミングを見計らい、下記コマンドでプロファイルを取得します。
perf record -F 99 -a -g -- sleep 30
取得した結果を表示。Call Graph が取得できます。
perf report

結果の一部:
-  33.01%             java  [kernel.kallsyms]                     [k] _spin_lock_irq
   - _spin_lock_irq
      - 98.89% shrink_inactive_list
           shrink_mem_cgroup_zone
           shrink_zone
           zone_reclaim
           get_page_from_freelist
         - __alloc_pages_nodemask
            - 89.56% alloc_pages_current
               - 79.46% __page_cache_alloc
                  - 99.76% grab_cache_page_write_begin
                       ext4_da_write_begin
                       generic_file_buffered_write
                       __generic_file_aio_write
                       generic_file_aio_write
                       ext4_file_write
                       do_sync_write
                       vfs_write
                       sys_write
                       system_call_fastpath
                     + 0x3fda40e6fd
               + 17.54% tcp_sendmsg
               + 1.75% __get_free_pages
               + 1.25% pte_alloc_one
            + 9.29% alloc_pages_vma
            + 1.15% kmem_getpages
+  14.24%             java  [kernel.kallsyms]                     [k] _spin_lock
+   4.75%             java  libjvm.so                             [.] SpinPause
+   4.03%             java  perf-1947.map                         [.] 0x00007fd9550209cd
+   2.64%             java  libsnappy.so.1.1.3                    [.] snappy::internal::CompressFragment(char const*, unsigned long, char*,
+   2.01%             java  libjvm.so                             [.] ParallelTaskTerminator::offer_termination(TerminatorTerminator*)
+   1.84%             java  [kernel.kallsyms]                     [k] __isolate_lru_page
+   1.58%             init  [kernel.kallsyms]                     [k] intel_idle
...

 ちなみに、上記の Call Graph を可視化した FlameGraph の画像は以下です。

perf 結果からわかること

  1. CPU system を高騰させているのは "spin_lock*" 関数であること
  2. "spin_lock*" 関数は "メモリ回収処理" の延長で呼ばれていること

 つまり、メモリが足りなくなったために、メモリ回収処理があまりに頻繁に呼ばれ、spin_lock のオーバヘッドが高騰したことが予想されます。さて、メモリ使用量について改めて観測すると、半分程度しか使用していません。にもかかわらずメモリ回収処理が頻繁に呼ばれるのは何故でしょうか...

 Linux のメモリ解放に関連するパラメータを洗い出してみると、一つの気になるパラメータがありました。"zone_reclaim_mode" です。有効になっている場合、NUMA 環境で zone 毎のメモリ回収が積極的に行われるようになります。デフォルトでは無効のはずですが、今回の該当マシン(CentOS 6系)で調べてみると、なんと有効になっていました。
zone_reclaim_mode について詳細: https://www.kernel.org/doc/Documentation/sysctl/vm.txt

zone_reclaim_mode 無効設定の結果


/proc/sys/vm/zone_reclaim_mode に 0 を設定したところ、問題の CPU system 高騰は収まりました。Job の実行時間も元の水準に戻りました。

なぜ zone_reclaim_mode が有効になっていたか


zone_reclaim_mode は一部のマシンで有効になっており、 CPU system が高騰していない別のマシンでは無効になっていました。同じ OS を使っていたのに、なぜ設定に違いが出たのでしょうか。Kernel のソースコードを読んで調べてみましょう。Kernel の Version は CentOS6(2.6.32-431.11.2.el6) とします。

 zone_reclaim_mode は default = 0 ですが、NUMA 環境における Node 間の距離(RECLAIM_DISTANCE) の値によっては、Kernel 起動時に 1 に修正されてしまうようです。
  mm/pagealloc.c
3096         /*
3097          * If another node is sufficiently far away then it is better
3098          * to reclaim pages in a zone before going off node.
3099          */
3100         if (distance > RECLAIM_DISTANCE)
3101             zone_reclaim_mode = 1;
 その閾値は "20" とあります。
 57 /*       
 58  * If the distance between nodes in a system is larger than RECLAIM_DISTANCE
 59  * (in whatever arch specific measurement units returned by node_distance())
 60  * then switch on zone reclaim on boot.
 61  */      
 62 #define RECLAIM_DISTANCE 20

 有効になっていたマシンの NUMA Node 距離を調べると... 21
$ numactl --hardware
...
node distances:
node   0   1 
  0:  10  21
  1:  21  10 

 無効になっていたマシンでは 20 でした。
 要するに、ハードウェア構成によっては zone_reclaim_mode が自動的に有効になってしまう様です。

最新の Kernel ではどうなっているか


ちなみに最新の Kernel では 下記 Commit により、 "ハードウェア構成によっては zone_reclaim_mode を自動で有効とする" 挙動が無効に変更されています。
http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=4f9b16a64753d0bb607454347036dc997fd03b82

他のソフトウェアでの推奨値


メモリを大量に使う DB 等のソフトウェアでの推奨値はやはり "無効" のようです。

まとめ

  • Hadoop Datanode での CPU system 高騰原因を perf を使って調査した
  • 原因: zone_reclaim_mode = 1 によるメモリ回収処理多発
  • ハードウェア構成によってい zone_reclaim_mode のデフォルト設定は変わる
  • Hadoop 含め、NUMA 環境でメモリを大量に使うソフトウェアで CPU system が高騰していた場合、 zone_reclaim_mode 設定を確認する

2013/10/29

トレースデータを可視化する d3js_trace をつくりました

はじめに

ソフトウェアの性能解析をしている時、どこにCPUボトルネックがあるのか知りたくなることがあります。そういった場合、プロファイリングツールを使ってスタックトレースを採取し、CPUを消費している場所や割合に関する統計情報を解析するのが有効です。しかし、一般的に採取するデータ量は膨大になってしまい、欲しい情報を解析するのはなかなか骨の折れる作業です。
そこで、今回はトレース情報を可視化するツール:d3js_trace を作ってみました。d3js_trace は、perf で取得したスタックトレース情報を、JavaScript ライブラリ : D3js を用いて可視化します。可視化により、人間が解析しやすい形で表現することで、より容易にトレースデータを解析できるようになります。

コードについては GitHub に公開しています: Etsukata/d3js_trace



以下に掲載した画像は、perf でシステム全体のプロファイリングをとったものです。コマンドは "perf record -a -g fp sleep 3 "。どこでどのくらいCPUを消費したかが、階層を組んだ放射型のグラフにより表現されています。
画像をみるだけよりは、インタラクティブなデモをご覧いただけるほうが、理解しやすいと思います⇛デモ
図にカーソルを合わせると、CPU使用割合とコールスタックが表示されます。

使い方

d3js_trace は上記デモのような解析ページを生成します。その使い方をご紹介します。

まず git clone します。
# git clone https://github.com/Etsukata/d3js_trace.git
# cd d3js_trace

perf でスタックトレースを収集します。今回は例として、-a でシステム全体を対象に収集しています。
# perf record -g fp -a sleep 3

perf script コマンドでテキストデータで出力し、それを python スクリプトで d3js で読む JSON 形式に変換します。
# perf script | ./d3trace.py > trace_json.js

WEBブラウザで置いてある index.html を開きます。
# firefox index.html

すると、デモのようなページが表示されます。

TODO

d3js_trace は作ってみたばかりなので、色々と改良したいことがあります。

  • 色付け
  • ズーム可能にする
  • d3jsの他のExampleを使えるようにする
  • ftrace のトレース情報などを利用し、レイテンシトレースを可視化できるようにする

...などなど

Thanks to

d3js_trace は Brendan Gregg さんの FlameGraph を参考につくりました。また、データ可視化部には d3js の Sequence Sunburst を使っています。
素晴らしいツールを開発された方々に感謝します。