のぴぴのメモ

自分用のLinuxとかの技術メモ

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

はじめに

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

FlameScopeとは

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

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

  • 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コマンドをインストールしてください。

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

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

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

  • pipインストール

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

/* 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で測定する

負荷は、作成したツールを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
  • ブラウザで、http://127.0.0.1:5000/にアクセスする。
  • stack.log.gzを選択する
  • 右上のRawsから、perfの分解能度に合わせた行数を選択する(49を選択)

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

FladeScopeでドリルダウン分析してみる

上記の赤い濃淡の図の中から気になる部分があったら、その部分をFlameGraphでドリルダウン分析します。例えば最初の赤い時間帯の開始タイミングと終了タイミングで2回クリックするとその範囲が選択され、下記のFlameGraphで詳細分析することができます。
f:id:nopipi:20180411015940p:plain

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()の半分の処理時間割合であることから、システムコールによるユーザ空間からカーネル空間へのコンテキストスイッチは相当のオーバーヘッドがあることが伺えます。
f:id:nopipi:20180411023148p:plain

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

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

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

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
xen tsc hpet acpi_pm 
  • (2)カレントのクロックソース

xenですね。

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

subprocessでコマンド実行し、例外処理でOSErrorとコマンドのリターンコードの非ゼロ(エラー)をそれぞれハンドルするサンプル

サンプルコード

私自身の勉強用です。コードは、python2.7ベースです。

#!/usr/bin/env python
# -*- coding: utf-8 -*-
import sys
import subprocess

def call_subprocess(cmd):
    try:
        r = subprocess.check_output(
            cmd,
            stderr=subprocess.STDOUT
            )
        sys.stdout.write(r+'\n')
    except OSError as e:
        sys.stderr.write('file ='+str(e.filename)+'\n')
        sys.stderr.write('errno='+str(e.errno)+'\n')
        sys.stderr.write('error='+e.strerror+'\n')
        return(1)
    except subprocess.CalledProcessError as e:
        sys.stderr.write('ret='+str(e.returncode)+'\n')
        sys.stderr.write('cmd='+str(e.cmd)+'\n')
        sys.stderr.write('output='+e.output+'\n')
        return(1)
    return(0)

#test1 a command is success
print('<<<<<test1>>>> a command is success.' )
cmd = [ 'echo','hoge hoge' ]
ret = call_subprocess(cmd)
print('function return = '+str(ret) )

#test2 command is failed
print('<<<<<test2>>>> a command is failed.' )
cmd = [ 'cat','hoge hoge' ]
ret = call_subprocess(cmd)
print('function return = '+str(ret) )

#test3 OS error
print('<<<<<test3>>>> OS Error.' )
cmd = [ 'NonexistingFile','hoge hoge' ]
ret = call_subprocess(cmd)
print('function return = '+str(ret) )

プロセスのVSZ,RSSとfree,meminfoの関係を実機で確認する

1.はじめに

1-1.この記事の要旨

psコマンドのVSZ(仮想メモリ)、RSS(物理メモリ)の挙動について質問を受けたので、簡単な検証プログラムを作ってmalloc/freeのメモリ確保/解放や、データの読み込み・書き込みとVSZ/RSSの関係性及び、freeコマンドとmeminfo情報でシステムワイドなメモリの挙動について確認しました。
検証結果から以下の挙動を実機で確認しました。

  • 検証結果
    1. malloc()の時点では、VSZのみ増加し、RSSやfreeコマンドのusedは増加しない
    2. データreadでは、物理メモリの割り当てが発生しないため、RSSとfreeコマンドのusedは増加しない(COW(Copy-On-Write)実装によるもの)
    3. データwriteして初めて、物理メモリの割り当てが発生し、RSSとfreeコマンドのusedが増加する

f:id:nopipi:20171115024528p:plain
psコマンドのVSZ/RSS挙動
f:id:nopipi:20171115024541p:plain
freeコマンドのused, free,availableの挙動
f:id:nopipi:20171115024535p:plain
meminfoの挙動*1

1-2.(予習)メモリに関する指標とlinuxのメモリ挙動について

この記事に出てくる、メモリに関する指標値の説明です。

  • psコマンド
    • VSZ : プロセスが確保している仮想メモリサイズ
    • RSS : プロセスが確保している物理メモリサイズ
  • freeコマンド
    • used : カーネルや各プロセスが利用しているメモリの総量です。*2
    • buffer /cache: キャッシュやバッファとして利用されいるメモリ量です。(この記事では、単にbufferと記載しています)
    • free : 未使用のメモリ総量です。
  • meminfo
    • MemFree : 未使用のメモリ量です。freeコマンドの"free値"の元になっています。
    • AnonymousPage(無名ページ): swapアウト対象となるページ。ざっくりというとプロセスが普通使っているメモリ。
    • FilePage(ファイルページ):メモリ不足時、解放されるページ。ざっくりいうとファイルキャッシュのメモリ。
    • active: AnonymousPage/FilePageのうち、比較的最近アクセス(read or write)されたページ。swapアウトや解放されないページではない。*3
    • inactive:AnonymousPage/FilePageのうち、しばらくアクセスされていないページ

2.検証環境と検証方法

2-1.検証環境

検証環境は以下の通りです。

  • RHEL7.4(3.10.0-693.el7.x86_64)
  • サーバ構成: CPU 1core、メモリ 2GB(VirtualBox利用)

2-2.検証方法

下記動作を行う検証プログラムを作成し実行します。なお検証をわかりやすくするために、動作の間に10秒のsleepをかけています。

  1. malloc()で512MBのメモリを確保する
  2. 確保した512MBのメモリ領域を20秒かけてreadする(1秒間隔で1/20のサイズずつ20回readする)
  3. 同じ領域に、20秒かけてデータを書き込む
  4. もう一度同じ領域を、20秒かけて読み込む
  5. free()で確保したメモリを解放する

プログラムは以下のリンク先にありますので、これをgccで"gcc verifying_memory.c"とかしてビルドします。
Verifying on Memory behavior · GitHub
ちなみにglibcmalloc()は、サイズが128kb(変更可)より大きい場合はmmap()取得になります。*4
ですので512MB確保している今回の検証は、必ずmmap()になります。

2-3.測定方法

(1)psコマンドによるVSZ,RSS情報の取得

簡単ですが、下記のワンライナーコマンドで1秒間隔で取得しました。(検証プログラムのファイル名は、"a.out")

echo -n 'DATE               '; ps -aux|head -n 1;while true;do printf '%s ' "`env LANG=C date '+%X.%N'`";env LANG=C ps -aux|grep -e a.out|grep -v grep;sleep 1;done
(2)freeコマンドとmeminfo情報の取得

こちらの記事のシェルで取得しました。
freeコマンドとmeminfoを取得してCSV形式で保存するシェルスクリプト - のぴぴのメモ

3.結果

3-1.全体の結果

psコマンドのVSZ/RSS、freeコマンド、meminfoの推移を並べると以下のようになります。

f:id:nopipi:20171115024528p:plain
psコマンドのVSZ/RSS挙動
f:id:nopipi:20171115024541p:plain
freeコマンドのused, free,availableの挙動
f:id:nopipi:20171115024535p:plain
meminfoの挙動

3-2.プロセスのVSZ/RSS挙動

f:id:nopipi:20171115024528p:plain
psコマンドのVSZ/RSS挙動

ポイント① malloc()した時の挙動→VSZのみ増加

malloc()で512MBを取得したタイミングで、VSZが増加しているのがわかると思います。
一方RSSは、malloc()しただけでは増えてなく、このタイミングでは物理メモリの割り当てが発生していないことがわかります。(次のfreeコマンドやmeminfoの結果と照らし合わせて見るとよりわかりやすいです。)

ポイント② 1回目のデータread時→RSSは増えない

malloc()した後、そのデータをreadしても、物理メモリの割り当ては発生しません。そのため、RSSも増加しません。
実はプロセスがカーネルからメモリ確保したタイミングでは、確保した仮想メモリのページは、”zero page”という1ページがすべて0データで埋められた特殊なページにマッピングされており、データをreadした時は、その"zero page"の値を参照するためです。*5

ポイント③ データwrite→RSSが増加する

データのwriteが発生した時点で、RSSが増加していることがわかります。つまりデータへのwriteのタイミングで、そのwriteした仮想メモリのページに、晴れて物理メモリが割り当てられたということです。
これはカーネルのCOW(Copy-On-Write)という手法で、mallocなどでメモリを確保したタイミングでは実際には物理メモリの割り当てはせず、必要になったタイミングで初めて物理メモリを割り当ているからです。*6
もう少し詳しく書くと、先ほど説明したzero pageは書き込み禁止設定がされており、そこにデータを書こうとするとページフォルトが発生します。ページフォルトが発生すると、ページフォルトの割り込み処理の中にあるCOWの実装で、zero pageの内容を新しいページにコピーしして、そのページを改めて仮想ページとマッピングします。その時にRSSが+1ページ加算されます。

3-3.システムワイドな挙動(freeコマンド/meminfo)

f:id:nopipi:20171115024541p:plain
freeコマンドのused, free,availableの挙動
f:id:nopipi:20171115024535p:plain
meminfoの挙動

ポイント① malloc()した時の挙動→usedもAnonymousPageも増えない

malloc()した時には、RSSが増えてない、つまり物理メモリへのマッピングがされていないため、freeコマンドやmeminfoでシステムワイドで見た物理メモリの利用状況でも、変化はありません。

ポイント②1回目のデータread時→変化しない。

同じですね。物理メモリの割り当てが発生しないため、freeコマンドやmeminfoも変化はありません。

ポイント③ データwrite→used上昇、AnonymousPage上昇

Writeするタイミングで、物理メモリの割り当てが発生するため、Usedが上昇します。meminfoでさらに詳しく見るとその上昇しているところが、AnonymousPage(無名ページ)であることが確認できます。

*1:kernelは、”MemTotal - MemFree - AnonymousePage(Active/InActive) - FilePage(Active/InActive) - Unevictable+Mlocked”で算出しています。

*2:"total - free - buffers - cache"で計算された値になります。RHEL6まではbuffer/cacheを含んでいましたが、RHEL7からはbuffer/cacheが含まれない値になりました。

*3:/proc/meminfo の Inactive は利用可能なメモリ領域ではない - ablog

*4:glibcmalloc()は、指定するメモリサイズが小さい場合(閾値MMAP_THRESHOLDで設定されており、デフォルトは128kb)は、Java vmのヒープのように、カーネルから取得済みで未使用となったメモリ領域をglibc内で保持して再利用する実装があるため、malloc()により必ずしもVSZが増加するとは限りません。詳しくはmalloc()のmanの注意(NOTES)を参照。

*5:memory management - Linux kernel: Role of zero page allocation at paging_init time - Stack Overflow

*6:コピーオンライト - Wikipedia