clock_gettime()で負荷をかけたEC2をNetflix FlameScopeでのぞいてみた

はじめに

ablogさんのこちらの記事=>Netflix のオープンソース可視化ツール FlameScope を使ってみた - ablogの二番煎じですが、FlameScopeを教えてもらったので使ってみました。

FlameScopeとは

Netflixのパフォーマンスエンジニアチームがリリースしたperfで取得した性能情報をブラウザでビジュアルに分析できるツールです。詳しくはNetflixのblogやablogの記事を参照してください。

この記事で書いていること

• MacにFlameScopeをセットアップする時の注意事項
• AWS EC2のt2.microインスタンス場で、clock_gettime(gettimeofdayを実行した時に叩かれるkernelのAPI)で負荷をかけた時のサンプル

セットアップ手順①(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コマンドをインストールしてください。

• https://qiita.com/furusin_oriver/items/974a7b7fb8c56ad88d6e
• https://git-scm.com/downloads

gitはAppleの認証がなくインストールでエラーになる場合がありますが、その場合はエラーになった後に"システム環境設定"->"セキュリティーとプライバシー"からインストールを実行してください。

(b)pipコマンドのセットアップ

• Xcodeのセットアップ

pipのセットアップの中でccコマンドでビルドしているようなので、 ccコマンドを使えるようにするためにMacの開発環境であるXcodeを先にインストールします。
インストールは、”AppStore”から”Xcode”で検索してインストールします。

• pipインストール

こちらの記事を参考にpipをインストールします。

• macOSのデフォルトPythonでpipを使う - Qiita

手順は、
(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()を呼び出す部分をアセンブラで書いていますが、ただの趣味です。こんなキモいことしなくても大丈夫です。

/* work.c */
#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   /* MAX = 2^25  */

int main() {
    struct timespec tp;
    char *mes;
    int  ret;
    unsigned long loop;
 
    for(loop=0; loop<MAX; loop++){ 
        asm volatile(
            /* call clocl_gettime api */
            "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

linuxで測定する

負荷は、作成したツールを４回、１０秒のインターバルを置いて実行するようにしました。

sleep 15;for i in `seq 1 4`;do time ./a.out;sleep 10;done

それと同時に、別のターミナルでperfでプロファイルの収集を開始します(秒間49回で、１２０秒間測定)。

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

• ブラウザで、http://127.0.0.1:5000/にアクセスする。
• stack.log.gzを選択する
• 右上のRawsから、perfの分解能度に合わせた行数を選択する(49を選択)

すると、こんな感じで見えます。
赤いところがイベントが多数出ている→負荷がかかっている、場所になります。

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が処理時間全体の７割弱を占めているのがわかります。ただ、実際に時刻取得処理を行うdo_clock_gettime()は、do_syscall_64()の半分の処理時間割合であることから、システムコールによるユーザ空間からカーネル空間へのコンテキストスイッチは相当のオーバーヘッドがあることが伺えます。

(蛇足)/sysからt2.microのクロックソースを確認

蛇足ですが最後に、実機の/sysからカレントのクロックソースを確認します。

• (1)利用可能なソースコード一覧

kernel的には、xen, tsc, hpet, acpi_pmの４つが選択可能に見えます。

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
xen tsc hpet acpi_pm 

• (2)カレントのクロックソース

xenですね。

$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource 
xen

参考

• FlameScope
  • Netflix のオープンソース可視化ツール FlameScope を使ってみた - ablog
  • Netflix FlameScope – Netflix TechBlog – Medium
  • GitHub - Netflix/flamescope: FlameScope is a visualization tool for exploring different time ranges as Flame Graphs.
• perf
  • Chapter 25. Performance Counters for Linux (PCL) Tools and perf - Red Hat Customer Portal
  • perf-record(1) - Linux man page
• gitコマンド
  • https://qiita.com/furusin_oriver/items/974a7b7fb8c56ad88d6e
  • https://git-scm.com/downloads
• pipコマンド
  • macOSのデフォルトPythonでpipを使う - Qiita

*1:ディレクトリは、app/config.pyで変更可能

*2:https://elixir.bootlin.com/linux/v4.3/source/arch/x86/kernel/pvclock.c#L74