セットアップ手順①(MacにFlameScopeをセットアップする)
基本は、GitHub - Netflix/flamescope: FlameScope is a visualization tool for exploring different time ranges as Flame Graphs.に書いてあります。
基本FrameScopeのgithubに記載されている手順でいけますが、私のMacは前提のツールが何も入っていなかったのでもう一手間かかりました。
(1)前提パッケージのセットアップ
(a)gitコマンドのセットアップ
下のqiita記事を参考にgitコマンドをインストールしてください。
gitはAppleの認証がなくインストールでエラーになる場合がありますが、その場合はエラーになった後に"システム環境設定"->"セキュリティーとプライバシー"からインストールを実行してください。
(b)pipコマンドのセットアップ
pipのセットアップの中でccコマンドでビルドしているようなので、 ccコマンドを使えるようにするためにMacの開発環境であるXcodeを先にインストールします。
インストールは、”AppStore”から”Xcode”で検索してインストールします。
こちらの記事を参考にpipをインストールします。
手順は、
(i)get-pip.pyダウンロード
https://pip.pypa.io/en/stable/installing/ から、get-pip.pyファイルをダウンロードする。
(ii)pipインストール
python get-pip.py --user
export PATH="$HOME/Library/Python/2.7/bin:$PATH"
echo 'export PATH="$HOME/Library/Python/2.7/bin:$PATH"' >> ~/.bash_profile
(iii)既存パッケージのアップデート
pip freeze --local | grep -v '^\-e' | cut -d = -f 1 | xargs pip install -U --user
(2)FlameScopeのセットアップ
FlameScopeのgithubにあるインストール手順をそのまま実行します。
cd ~/
git clone https://github.com/Netflix/flamescope
cd flamescope
pip install -r requirements.txt
セットアップ手順②(測定対象のLinuxにperfをインストールする)
今回はAWSのEC2(t2.micro)のAmazon Linux 2を利用しています。FlameScopeのgithubの説明通りです。
sudo yum install perf
テスト用にワークロードを準備する
負荷がかかってない状態で測定しても何も面白くないので、何からかの負荷がけをします。負荷は何でもよいのですが、今回は時刻取得を約3355万回(2^25)繰り返す負荷ツールを作りました。clock_gettime()を呼び出す部分をアセンブラで書いていますが、ただの趣味です。こんなキモいことしなくても大丈夫です。
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>
#define _GNU_SOURCE
#include <unistd.h>
#include <sys/syscall.h>
#include <sys/types.h>
#define MAX 1LU << 25
int main() {
struct timespec tp;
char *mes;
int ret;
unsigned long loop;
for(loop=0; loop<MAX; loop++){
asm volatile(
"mov %3, %%rsi;"
"mov %2, %%rdi;"
"mov %1, %%rax;"
"syscall;"
"mov %%eax, %%eax;"
"mov %%eax, %0;"
: "=&m"(ret)
: "g"(SYS_clock_gettime),
"g"(CLOCK_REALTIME),
"g"(&tp)
:
);
}
printf("execute %lu times.\n",loop);
return ret;
}
このコードをgccでビルドします。(デフォルトではgccが入っていないのでyumでインストールしてビルドします)
sudo yum install gcc
gcc work.c
負荷は、作成したツールを4回、10秒のインターバルを置いて実行するようにしました。
sleep 15;for i in `seq 1 4`;do time ./a.out;sleep 10;done
それと同時に、別のターミナルでperfでプロファイルの収集を開始します(秒間49回で、120秒間測定)。
sudo perf record -F 49 -a -g -- sleep 120
- -F: 49:秒間49回データ収集を行う。(秒間50回が分析にちょうど良い分解能度で、でも50回だと周期性が出てハマってしまう(lock-step)可能性があるから、周期性が出ないよう半端な49回にするということ?)
- -a: 全てのCPUコアを対象にシステムワイドでプロフィル収集する
- -g: call-graphを有効化する
perfのデータ収集が完了したらレポートを出力しgzip圧縮する
sudo perf script -f --header > stacks.log
gzip stacks.log
FlameScopeで分析する
- 収集し、圧縮したstacks.log.gzファイルをMacに転送します。
- 転送したstacks.log.gzを”flamescope/example”に移動します*1
- FlameScopeを起動します。
cd ~/flamescope
python run.py
すると、こんな感じで見えます。
赤いところがイベントが多数出ている→負荷がかかっている、場所になります。
FladeScopeでドリルダウン分析してみる
上記の赤い濃淡の図の中から気になる部分があったら、その部分をFlameGraphでドリルダウン分析します。例えば最初の赤い時間帯の開始タイミングと終了タイミングで2回クリックするとその範囲が選択され、下記のFlameGraphで詳細分析することができます。
t2.microのクロックソース
上記の図を見ると、
- a.outのmain()から、システムコール呼び出し(entry_SYSCALL_64_after_hwframe)からdo_syscall_64()が呼ばれ、
- そこから、sys_clock_gettime()が呼ばれて以下実行され、
- 最終的に、pvclock_clocksource_read()が呼び出されているのがわかります。
なおpvclock_clocksource_read()のコードがどこにあるかカーネルを別途見ると、arch/x86/kernel/pvclock.cにあるようです*2。pvclockという名前からparavirtualのclocksourceであることが推測でき、コードタイトルにも”paravirtual clock -- common code used by kvm/xen”とあるので、t2.microのクロックソースコードはパラバーチャルであることが裏付けられます。( ちなみに、lvm/xenで共通化されているんですね)
処理負荷が高いポイント
clock_gettimeを回して負荷をかけているので当然、処理時間の大半がシステムコール処理にリソースを費やされています。実際FlameGraphを見るとdo_syscall_64が処理時間全体の7割弱を占めているのがわかります。ただ、実際に時刻取得処理を行うdo_clock_gettime()は、do_syscall_64()の半分の処理時間割合であることから、システムコールによるユーザ空間からカーネル空間へのコンテキストスイッチは相当のオーバーヘッドがあることが伺えます。
(蛇足)/sysからt2.microのクロックソースを確認
蛇足ですが最後に、実機の/sysからカレントのクロックソースを確認します。
kernel的には、xen, tsc, hpet, acpi_pmの4つが選択可能に見えます。
$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
xen tsc hpet acpi_pm
xenですね。
$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
xen
参考
- FlameScope
- perf
- gitコマンド
- pipコマンド