tom__bo’s Blog

MySQL!! MySQL!! @tom__bo

Systems Performance 読んでいく (6章 その4)

Systems Performance: Enterprise and Cloudを読んでいく。

前回の続き。
6章6節分析のみ。

6.6 Analysis

この説ではLinuxSolaris based OSでのCPUのパフォーマンス分析ツールを紹介する(Solarisはほとんど省略)
この節で紹介するツールを以下に示す。

f:id:tom__bo:20161210182802p:plain

これらのツールはCPUの統計情報に始まり、コードパスのプロファイリングや、CPUサイクルの分析へと掘り下げていく。

6.6.1 uptime

uptime(1)はロードアベレージを表示するいくつかのツールの一つである。
(例省略)

[Load Average]

ロードアベレージはCPUリソースへの要求を示し、実行中のスレッド(利用率)や実行待ちのキューのサチュレーションを集計している。 新しいロードアベレージの計算方法では、利用率に加えてスケジューラレイテンシを使っている。これにより精度が増している。

ロードアベレージは、CPUの数よりも多ければ、CPUが足りていない状況で、CPUの数より少なければ十分である。
例えば、64CPUのシステムでロードアベレージが128であれば、64スレッドが実行中で、残りの64スレッドがそれぞれのCPUで1つずつ実行待ちということがわかる。 また、Linuxでは現在ロードアベレージに割り込み不可のディスクI/Oのタスクを加えている。これはロードアベレージの値からではCPUのサチュレーションや空きを単純に理解できないということである。 そのためLinuxではvmstatやmpstat(1)を使うのがベストな方法である。

6.6.2 vmstat

仮想メモリの統計情報を表示するコマンドvmstat(8)はシステム全体のCPU平均を、最後の数カラムに実行可能なスレッドを最初のカラムに示してくれる。
Linuxバージョンの例を以下に示す。

f:id:tom__bo:20161210183014p:plain

Linuxでは最初の項目の"r"がシステム全体での実行中と実行待ちの合計である。

6.6.3 mpstat

マルチプロセスの統計情報ツールmpstatはCPUごとの情報を示す。
Linuxバージョンの例を以下に示す。

f:id:tom__bo:20161210183230p:plain

"-P ALL"オプションをつけることでCPUごとの情報を出している。カラムの意味は以下である。

重要なカラムは%user, %sys, %idleである。この3つでCPUごとのCPU使用率と、ユーザ時間/カーネル時間の割合を特定することができる。また%user+%sysを見ることで利用率を知ることができる。

6.6.4 sar

system activity reporter, sar(1)は現在のアクティビティや統計情報を見ることができる。

6.6.5 ps

process statusコマンドps(1)は全てのプロセスの詳細情報を見ることができる。
CPU使用率に重要なのは、TIMEと%CPUカラムだ。 %CPUカラムは前の1秒間CPU使用率の合計を示し、その全ての合計は1スレッドのCPUバウンドなプロセスでは100%, 2スレッドであれば200%となる。 TIMEカラムはあるプロセスが(user+system)作られてから消費したCPU時間である。

6.6.6 top

top(1)コマンドはトップで実行中のコマンドを見ることができる。
上部には%us, %sy, %ni, %id, %waa,%hi, %si, %stが並んでいて、これはmpstat(1)と同じものである。
top(1)コマンドは/proc以下を全てのプロセスごとに見ていくので、非常に重い。また、一瞬だけ存在するようなプロセスを見逃すこともあり、これらについてはatop(1)コマンドを使うこともできる。

6.6.8 pidstat

pidstat(1)はCPU使用率をプロセス/スレッド、ユーザ/システムごとに表示してくれる。
デフォルトでは稼働中のプロセスを表示する。
例を以下に示す。

f:id:tom__bo:20161210183302p:plain

6.6.9 time, ptime

time(1)コマンドは実行したコマンドのCPU使用率をレポートする。
以下に大きいファイルをcksumするのをtimeコマンドで見た例を示す。

f:id:tom__bo:20161210183316p:plain

1回目の実行では全体で5.105sかかり、ユーザレベルで2.8s, カーネルレベルで0.3sかかったことがわかる。ここで消えている2.0s(=5.1-2.8-0.3)は、おそらくディスクI/Oのブロックだろう。 2回目の実行ではここがメモリに乗っているため早くなっている。

"-v"オプションをつけることで更に詳細を見ることができる。

6.6.10 DTrace

DTraceコマンドでもCPUのプロファイルやトレースなど様々な情報を取得することができる。
これ以降ではDTraceを使ったCPU分析方法を紹介していく。

[kernel profiling]

まずSolarisベースのシステムで996Hzでカーネルスタックトレースを取るワンライナーを以下に示す。

f:id:tom__bo:20161210183357p:plain

ここで、最も実行されるコマンドは一番下にあり、それはidleスレッドの23,083回である。

[User Profiling]

ユーザレベルで消費したCPU時間を見ることもできる。以下にmysqldという名前のプロセスのユーザレベルコードでのプロファイルを示す。

f:id:tom__bo:20161210183410p:plain

[Function Tracking]

CPUプロファイリングが関数ごとのCPU消費時間を示す一方で、実行時の分散は見ることが出来ない。 これを見るためにはvtimestampビルトインを使う必要がある。 関数の実行時間を知るには、その入り口と出口部分を計測し、vtimestampの増分を計算する。
例えば、カーネルZFSのzio_checksum_generate()関数が使った時間を図るために、fbtプロバイダによって動的トレーシングした例を以下に示す。

f:id:tom__bo:20161210185807p:plain

これにより大半は65us~131usかかっていることがわかる。 この特殊なプロファイリングはオーバーヘッドが大きいので、呼び出し頻度の高い関数では気をつける。 こうしたfbtやpidプロバイダを使った動的トレーシングではリリース感で関数が変わるので安定でないとされている。一方で安定したインタフェースを提供するものとして、"cross calls", "interrupts", "scheduler activity"がある。

[CPU Cross Calls]

過剰なクロスコールはCPUのパフォーマンスを下げてしまう。黒スコールの原因を見つけるのは難しいので、クロスコール自体と呼び出し元のコードパスをワンライナーで見つける。

f:id:tom__bo:20161210185833p:plain

これはSolarisベースのシステムでsysinfoを使った例である。

[Interupts]

DTraceはトレースや調整をされるために割り込みを許可している。Solarisベースでは"intrstat"によって行える。 一方Linuxにはないので、割り込みは動的な関数トレーシングによって行う。

[Schedular Tracing]

スケジューラプロバイダーはカーネルのCPUスケジューラの操作をトレーシングするためのプローブを提供している。
プローブのリストを以下に示す

f:id:tom__bo:20161210182838p:plain

この多くはスレッドコンテキストで発火されるので、スレッドローカルな変数を使うことになる。

f:id:tom__bo:20161210185851p:plain

ここでは、"sshd"という名前のプロセスのon-CPUの実行時間をトレースしている。 殆どの時間で32~65usという短い間でしかon-CPUでないことがわかる。

6.6.11 System Tap

SystemTapLinuxシステムでスケジューライベントをトレースできるツールである。
これについては4.4節と付録Eを見るように。

6.6.12 perf

もともと"Performance Counters for Linux(PCL)"と呼ばれていたperf(1)コマンドはプロファイリングとトレーシングのあtめのツールに貼って飲した。今では"Linux Performance Events(LPE)"とも呼ばれる。
それぞれのツールはサブコマンドとして選択される。
以下に代表的なコマンドを示す。

f:id:tom__bo:20161210182856p:plain

重要なコマンドについては以降で示す。

[System Profiling]

perf(1)コマンドではCPUのコールパスをプロファイルし、カーネルとユーザ空間それぞれで実行にかかった時間を集計できる。これはrecordコマンドによって一定の間隔でサンプリングした結果をperf.dataでファイルに書き出し、同じrecordコマンドによって見ることができる。

以下に全てのCPUを(-a)、997Hzで(-F 997)、10秒間(sleep 10)サンプリングした結果のコールスタック(-g)を出力(--stidio)した例を示す。

f:id:tom__bo:20161210185920p:plain

実際の結果は非常に長いので、CPUの実行にかかった順にソートされて表示される。
この例では、72.98%がidleで、9.43%がddプロセスだったことがわかる。 さらにddプロセスの9.43%の内、87.5%はext4_file_write()だったこともわかる。

これらのカーネル等のプロセスのシンボル情報はdebuginfoファイルが利用可能なときに表示可能で、そうでなければ16進数のアドレスが表示される。

[Process Profiling]

CPU全体のプロファイリングから離れて、1つのコマンドに注目して、perf.dataファイルを作ることもできる。

perf record -g command

[Scheduler Latency]

schedコマンドによってスケジューラの統計情報を見ることができる。

f:id:tom__bo:20161210185936p:plain

これはトレース中の平均と最大のスケジューラレイテンシを示している。 スケジューライベントは頻繁に発生するので、CPUとストレージオーバヘッドがかかる。 この10秒の例でも、1.7GBのファイルができる。 こういった点ではフィルタリングと集計ができるDTraceに利点がある。

[stat]

statコマンドは高レベルのCPUサイクルの振る舞いのまとめを提供してくれる。
以下の例はgzip(1)コマンドのstatである。

f:id:tom__bo:20161210185949p:plain

この情報にはサイクルや命令数、IPCが含まれている。これはどのくらいのサイクルが発生していて、何サイクルがストールしているのかを知る高ベレルのメトリクスとして非常に便利である。

プロセッサアーキテクチャによるが、"-e"オプションを使うことでハードウェアイベントやハードウェアキャッシュイベントを計測することもできる。

  • L1-dcache-load-misses: L1レベルのキャッシュミス
  • LLC-load-misses: Last level キャッシュミス、メインメモリへのアクセスになる。
  • dTLB-load-misses: Data translation looking bufferのミス。MMUが効果的にページマッピングを行えているかを示す

[Software Tracing]

perf record -eは様々なソフトウェアの命令ポイントをつかてtカーネルスケジューラの実行をトレースできる。
例えば、以下ではコンテキストスイッチイベントをトレースした結果を示している。

f:id:tom__bo:20161210190003p:plain

個々では2つのアプリケーションperlとtarがあり、コンテキストスイッチが起きた時のコールスタックが見られる。 これを見ると、tarプログラムはext4の読み出しで、sleepしていて、perlのプログラムは強制的にコンテキストスイッチされていることがわかる。一方で、なぜそうなったかは、これだけではわからない。さらなる情報はschedトレースポイントイベントを使うとわかる。
perf(1)を使った他の例は9章Diskや10章Networkでも扱う。

6.6.13 cpustat

省略

6.6.14 Other Tools

この他のツールとしてLinuxでは以下などがある。

  • oprofile
  • htop
  • atop
  • /proc/cpuinfo
  • getdelays.c
  • valgrind

6.6.15 Visualizations

CPU使用率稼働率ロードアベレージを線グラフで示すことで可視化されてきた。
これらはX11負荷ツール(xload(1))を使っていた。しかし、線グラフは今日我々が利用する数のCPU数ほどスケールしない。また、平均や標準偏差でこれらを見るのはCPUの稼働率が"bimodal"であるという性質にそぐわない。
それらはヒートマップで見るほうが適している。 以降ではCPU稼働率のヒートマップによる可視化と、筆者が作ったフレームグラフについて見ていく。

[Utilization Heat Map]

この例ではあるデータセンタの物理サーバ300台(5312CPU)のヒートマップである。これを見ると0~30%の稼働率のサーバが多い一方、常に複数のCPUがほぼ100%に張り付いていることもわかる。

[Subsecond-Offset Heat Map]

このヒートマップは"subsecond offset"をY軸に、時間をX軸に示している

[Flame Graphs]

CPUの使用率を効率的に調べる方法としてスタックトレースは効率的だ。しかし、これは大量のアウトプットとなることもある。フレームグラフを見ることで一瞬でこれらを理解できる。
フレームグラフはDTrace, perf, SystemTapといったツールのデータから組み立てられる。

f:id:tom__bo:20161210182917p:plain

このグラフには以下の特徴がある。

  • それぞれの四角はスタック内の関数を示す
  • Y軸はスタックの深さを示し、下の層は祖先(呼び出し元)である。
  • X軸は量を示すが、左右の順序や量に意味はない
  • 四角の大きさは実行時間の長さを示す
  • サンプルカウントは並列処理をしているものでは計測時間全体を上回ることもある。