2019/09/29

perfを用いたシステムのボトルネック解析方法

背景

システムの処理速度を改善するために、ボトルネック解析を行う必要があった。
ボトルネック解析の方法と、プロファイリングに使用したperfの使用方法に関して調査を行った。

記事の目的

perfを使用し、ボトルネック解析を行う

perf

ここでは、perfの導入方法及び使用方法について記載する。

perfとは

perf(Performance analysis tools for Linux)とはLinuxカーネル2.6.31以降で使用可能なLinuxの性能解析ツールである。
実行されているプロセス毎のCPU使用率やプロセス内で呼ばれている関数の割合などを調査できる。

利点

  • gprofのように、プログラム作成時に専用のライブラリを入れたり、コンパイル時にオプションをつける必要がない
  • フレームグラフにして、ビジュアライズできる

導入方法(Ubuntu編)

Ubuntu16.04へperfを導入する手順について記載する。
  1. OSのカーネルバージョンを調べる
    2. $ uname -a
Linux emptySet 4.4.0-116-generic #140-Ubuntu SMP Mon Feb 12 21:23:04 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
    上記の場合、カーネルバージョンは「4.4.0-116-generic」である。
  2. 上記カーネルバージョンのlinux-toolsパッケージをインストールする
    3. $ sudo apt install linux-tools-<カーネルバージョン>

使用方法

perfの使用方法は、下記の通りである。

  • コマンド内のボトルネック解析を行う場合
    1. perfで記録しながらコマンドを実行する
      2. $ perf record コマンド
      デフォルトで、記録結果ファイル「perf.data」が作成される。(-o [ファイル名.data]オプションでファイル名指定可能)
    2. perfで記録したファイルの内容を表示する(-i [ファイル名.data]オプションでファイル名指定可能)
      3. $ perf report
      例: ring_buffer_sample(l.148をbuf.setBufferSize(1000);に変更した)の場合 
      Samples: 44  of event 'cpu-clock', Event count (approx.): 11000000
Overhead  Command          Shared Object       Symbol
  11.36%  ring_buffer_sam  libc-2.23.so        [.] vfprintf
   9.09%  ring_buffer_sam  libc-2.23.so        [.] __GI___libc_write
   6.82%  ring_buffer_sam  libc-2.23.so        [.] _IO_file_xsputn@@GLIBC_2.2.5
   6.82%  ring_buffer_sam  [unknown]           [k] 0xffffffff8184e9b5
   6.82%  ring_buffer_sam  [unknown]           [k] 0xffffffff8184ef5a
   4.55%  ring_buffer_sam  ring_buffer_sample  [.] std::mutex::unlock
   4.55%  ring_buffer_sam  [unknown]           [k] 0xffffffff81508f2b
   2.27%  ring_buffer_sam  libc-2.23.so        [.] _IO_file_write@@GLIBC_2.2.5
   2.27%  ring_buffer_sam  libc-2.23.so        [.] fprintf
   2.27%  ring_buffer_sam  ring_buffer_sample  [.] RingBuffer::getBufferSize
   2.27%  ring_buffer_sam  ring_buffer_sample  [.] main
   2.27%  ring_buffer_sam  ring_buffer_sample  [.] std::mutex::lock
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff810031e8
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff81087b91
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8109b061
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8109b069
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff811c3b76
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff81213c9a
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff81214ba0
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8140cbaf
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8140cbb3
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8140dee9
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8150410d
   2.27%  ring_buffer_sam  [unknown]           [k] 0xffffffff8150420f
For a higher level overview, try: perf report --sort comm,dso
      上記の例の場合、vfprintf(標準出力)が処理量の11%を占めているため、標準出力を減らすことが高速化に有効であることがわかる。
  • システム全体のボトルネック解析を行う場合
    1. perfで記録する
      2. $ sudo perf record -ag
    2. perfで記録したファイルの内容を表示する
      3. $ perf report
      例: ring_buffer_sample(l.148をbuf.setBufferSize(100000);に変更した)を実行した状態で取得した場合 
      Samples: 181K of event 'cpu-clock', Event count (approx.): 45387500000
Overhead  Command          Shared Object                Symbol
  59.48%  swapper          [kernel.kallsyms]            [k] 0xffffffff810656d6
   1.98%  ring_buffer_sam  [kernel.kallsyms]            [k] 0xffffffff8109b061
   0.91%  compiz           [kernel.kallsyms]            [k] 0xffffffff810031e8
   0.85%  gnome-terminal-  [kernel.kallsyms]            [k] 0xffffffff8109d9e0
   0.83%  gnome-terminal-  libglib-2.0.so.0.4800.2      [.] g_string_insert_uni
   0.80%  gnome-terminal-  [kernel.kallsyms]            [k] 0xffffffff810031e8
   0.76%  compiz           libX11.so.6.3.0              [.] 0x0000000000026e60
   0.65%  gnome-terminal-  libglib-2.0.so.0.4800.2      [.] g_utf8_get_char
   0.57%  compiz           libX11.so.6.3.0              [.] 0x0000000000026e62
   0.57%  compiz           libX11.so.6.3.0              [.] 0x0000000000026f22
   0.57%  kworker/u8:2     [kernel.kallsyms]            [k] 0xffffffff8109c9fa
   0.54%  compiz           libX11.so.6.3.0              [.] 0x0000000000026f20
   0.45%  ring_buffer_sam  [kernel.kallsyms]            [k] 0xffffffff810ac14d
   0.44%  gnome-terminal-  libglib-2.0.so.0.4800.2      [.] g_string_append_uni
   0.42%  ring_buffer_sam  libc-2.23.so                 [.] vfprintf
   0.41%  ring_buffer_sam  [kernel.kallsyms]            [k] 0xffffffff8184ef5a
   0.41%  ring_buffer_sam  [kernel.kallsyms]            [k] 0xffffffff8184e9b5
   0.41%  ring_buffer_sam  libc-2.23.so                 [.] __GI___libc_write
   0.38%  ring_buffer_sam  libc-2.23.so                 [.] _IO_file_xsputn@@GL
   0.37%  kworker/u8:1     [kernel.kallsyms]            [k] 0xffffffff8109c9fa
   0.36%  gnome-terminal-  libvte-2.91.so.0.4200.5      [.] 0x00000000000135b2
For a higher level overview, try: perf report --sort comm,dso
      上記の例の場合、swapper(スワッピング処理)が処理量の60%を占めているため、メモリの利用率をチェックする必要がある。
  • フレームグラフでボトルネック解析結果を可視化する場合
    1. フレームグラフ作成用のスクリプトをダウンロードする
      2. $ wget https://raw.githubusercontent.com/brendangregg/FlameGraph/master/stackcollapse-perf.pl
$ wget https://raw.githubusercontent.com/brendangregg/FlameGraph/master/flamegraph.pl
    2. perfで記録する
      3. $ sudo perf record -ag
    3. perfで記録したファイルからフレームグラフを作成する
      4. $ sudo perf script> perf_data.txt
$ perl stackcollapse-perf.pl perf_data.txt|perl flamegraph.pl > flamegraph.svg
      例: ring_buffer_sample(l.148をbuf.setBufferSize(100000);に変更した)を実行した状態で取得した場合 
      firefox ./flamegraph.svg
      flamegraph
      フレームグラフでは、関数名で左から右にソートされており、コールスタックは上に行くほど深くなる。 一番上で横幅が広い関数がCPUを長く使っているため、ボトルネックになっている。
  • timechartを取得する場合
    1. perfで記録する
      2. $ sudo perf timechart record
    2. perfで記録した結果ファイルをsvgファイル(タイムチャート)として出力する(-p [pid or プロセス名]オプションで特定のプロセスのみを抜き出せる)
      3. $ sudo perf timechart -o timechart.svg
      例: ring_buffer_sample(l.148をbuf.setBufferSize(100000);に変更した)を実行した状態で取得した場合 
      $ firefox ./timechart.svg
      timechart
      上記ファイルの上半分がCPUの情報、下半分が実行されているプロセスの情報である。 各CPUの使用率のタイムチャートや、各プロセスの処理タイミングなどが分かる。 CPUに無駄なアイドル時間(Idle)がある場合や、プロセスにCPU待ち時間(Waiting CPU)や無駄な読み書き待ち時間(Blocked on IO)がある場合、処理系の最適化を図る必要がある。

その他コマンド一覧

  • perf top
    • リアルタイムに関数単位でcpu使用率を閲覧できる 
    $ perf top
---------------------------------------------------------------------------
  PerfTop:     260 irqs/sec  kernel:61.5%  exact:  0.0% [1000Hz
cycles],  (all, 2 CPUs)
---------------------------------------------------------------------------

            samples  pcnt function                       DSO
            _______ _____ ______________________________ __________________

              80.00 23.7% read_hpet                      [kernel.kallsyms]
              14.00  4.2% system_call                    [kernel.kallsyms]
              14.00  4.2% __ticket_spin_lock             [kernel.kallsyms]
              14.00  4.2% __ticket_spin_unlock           [kernel.kallsyms]
               8.00  2.4% hpet_legacy_next_event         [kernel.kallsyms]
               7.00  2.1% i8042_interrupt                [kernel.kallsyms]
               7.00  2.1% strcmp                         [kernel.kallsyms]
               6.00  1.8% _raw_spin_unlock_irqrestore    [kernel.kallsyms]
...
  • perf list
    • 指定可能なイベントの一覧を表示できる 
    $ perf list

List of pre-defined events (to be used in -e):

 cpu-cycles OR cycles                       [Hardware event]
 instructions                               [Hardware event]
 cache-references                           [Hardware event]
 cache-misses                               [Hardware event]
 branch-instructions OR branches            [Hardware event]
 branch-misses                              [Hardware event]
 bus-cycles                                 [Hardware event]
...
  • perf stat
    • 実行したコマンドのパフォーマンスカウンターが閲覧できる 
    $ perf stat - make -j

Performance counter stats for 'make -j':
8117.370256  task clock ticks     #      11.281 CPU utilization factor
        678  context switches     #       0.000 M/sec
        133  CPU migrations       #       0.000 M/sec
     235724  pagefaults           #       0.029 M/sec
24821162526  CPU cycles           #    3057.784 M/sec
18687303457  instructions         #    2302.138 M/sec
  172158895  cache references     #      21.209 M/sec
   27075259  cache misses         #       3.335 M/sec
Wall-clock time elapsed:   719.554352 msecs

備考

  • Symbolが16進数標記で読めない場合、addr2lineコマンドで関数名を確認できる場合もある

まとめ

  • perfを使用し、ボトルネック解析を行う方法について調査、記載した

参考文献


変更履歴

  1. 2019/09/29: 新規作成
  2. 2020/05/04: コマンド一覧追加
時刻:
ラベル: ,

0 件のコメント:

コメントを投稿

登録: コメントの投稿 (Atom)

MQTTの導入

背景 IoTデバイスの接続環境構築のため、MQTT(mosquitto)の導入を行った。 記事の目的 MQTT(mosquitto)をUbuntuに導入する mosquitto ここではmosquittoについて記載する。 MQTT MQTT(Message Qu...