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のカーネルバージョンを調べる
    1. $ uname -a
    2. 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パッケージをインストールする
    1. $ sudo apt install linux-tools-<カーネルバージョン>

使用方法

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

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

その他コマンド一覧

  • perf top
    • リアルタイムに関数単位でcpu使用率を閲覧できる 
    1. $ perf top
    2. ---------------------------------------------------------------------------
    3.   PerfTop:     260 irqs/sec  kernel:61.5%  exact:  0.0% [1000Hz
    4. cycles],  (all, 2 CPUs)
    5. ---------------------------------------------------------------------------
    6.  
    7.             samples  pcnt function                       DSO
    8.             _______ _____ ______________________________ __________________
    9.  
    10.               80.00 23.7% read_hpet                      [kernel.kallsyms]
    11.               14.00  4.2% system_call                    [kernel.kallsyms]
    12.               14.00  4.2% __ticket_spin_lock             [kernel.kallsyms]
    13.               14.00  4.2% __ticket_spin_unlock           [kernel.kallsyms]
    14.                8.00  2.4% hpet_legacy_next_event         [kernel.kallsyms]
    15.                7.00  2.1% i8042_interrupt                [kernel.kallsyms]
    16.                7.00  2.1% strcmp                         [kernel.kallsyms]
    17.                6.00  1.8% _raw_spin_unlock_irqrestore    [kernel.kallsyms]
    18. ...
  • perf list
    • 指定可能なイベントの一覧を表示できる 
    1. $ perf list
    2.  
    3. List of pre-defined events (to be used in -e):
    4.  
    5.  cpu-cycles OR cycles                       [Hardware event]
    6.  instructions                               [Hardware event]
    7.  cache-references                           [Hardware event]
    8.  cache-misses                               [Hardware event]
    9.  branch-instructions OR branches            [Hardware event]
    10.  branch-misses                              [Hardware event]
    11.  bus-cycles                                 [Hardware event]
    12. ...
  • perf stat
    • 実行したコマンドのパフォーマンスカウンターが閲覧できる 
    1. $ perf stat - make -j
    2.  
    3. Performance counter stats for 'make -j':
    4. 8117.370256  task clock ticks     #      11.281 CPU utilization factor
    5.         678  context switches     #       0.000 M/sec
    6.         133  CPU migrations       #       0.000 M/sec
    7.      235724  pagefaults           #       0.029 M/sec
    8. 24821162526  CPU cycles           #    3057.784 M/sec
    9. 18687303457  instructions         #    2302.138 M/sec
    10.   172158895  cache references     #      21.209 M/sec
    11.    27075259  cache misses         #       3.335 M/sec
    12. 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...