profile

プロファイラを使おう.

• プロファイラ
• 単純な例
• JITを使うと
• CodeAnalystのAPIを使う
• 再びJIT
• VTuneのAPIを使う
• テストコード

よく「開発者がMac(or Linux)を使う○○の理由」なんてのがありますが, このGUIによるお手軽さは「Windowsを使う理由」(の一つ)になってもいいんじゃないかと思います(まあMacにはXCodeがありますが).

#include <stdio.h>

double s1(int n)
{
    double r = 0;
    for (int i = 0; i < n; i++) {
        r += 1.0 / (i + 1);
    }
    return r;
}

double s2(int n)
{
    double r = 0;
    for (int i = 0; i < n; i++) {
        r += 1.0 / (i * i + 1) + 2.0 / (i + 3);
    }
    return r;
}

int main()
{
    double sum = 0;
    for (int i = 0; i < 20000; i++) {
        sum += s1(i);
        sum += s2(i);
    }
    printf("sum=%f\n", sum);
}

このコードを適当なプロジェクトを作ってReleaseモードでビルドします. そのときプロジェクトのプロパティの[C/C++]→[デバッグ情報の形式]を/Zi, [リンク]→[デバッグ]→[デバッグ情報の生成]をはい(/DEUBG)にする必要があります.

これらのオプションはコード生成には影響を与えませんが, ある程度のデバッグ情報が与えられるので最適化されたコードでもある程度わかるようになります. コマンドラインでなら

cl /EHsc /Zi /Ox /arch:SSE2 t.cpp /link /DEBUG

などとするとよいでしょう. CodeAnalystの設定は[Tools]→[Session Settings]ではProfile Duration Optionsで[Until app exit]とすると便利かと.

プロファイル結果はprof1.pngのようになり, s2という関数がs1の約2倍掛かっていることが分かります.

そしてs1をクリックするとprof2.pngのように, その関数のディスアセンブル結果が表示されてより詳細な結果が分かります.

あくまでサンプリングベースなので命令と時間が完全にマッチしてるわけではないので注意してください. prof2.pngではカーソルセレクトされたfaddが時間を食ってるように見えますが, 実際はその1行上のfdivrpの演算結果を待ってます.

たとえば先程のサンプルに, これまた作為的な次のコードを追加してみましょう.

#include <xbyak/xbyak.h>
struct Code : public Xbyak::CodeGenerator {
    Code()
    {
        mov(eax, 1000000);
    L("@@");
        for (int i = 0; i < 10; i++) {
            sub(eax, 1);
        }
        jg("@b");
        mov(eax, 1);
        ret();
    }
};

struct Code2 : public Xbyak::CodeGenerator {
    Code2()
    {
        mov(eax, 1000000);
    L("@@");
        for (int i = 0; i < 10; i++) {
            xorps(xm0, xm0);
        }
        sub(eax, 1);
        jg("@b");
        mov(eax, 1);
        ret();
    }
};

int main()
{
    Code c;
    Code2 c2;
    int (*f)() = (int (*)())c.getCode();
    int (*g)() = (int (*)())c2.getCode();
    double sum = 0;
    for (int i = 0; i < 20000; i++) {
        sum += s1(i);
        sum += s2(i);
    }
    printf("sum=%f\n", sum);
    for (int i = 0; i < 2000; i++) {
        sum += f();
    }
    printf("f=%f\n", sum);
    for (int i = 0; i < 2000; i++) {
        sum += g();
    }
    printf("g=%f\n", sum);
}

このコードを実行するとprof3.pngのようにt.exeの他にunknown module pid(4972)というなにやら怪しいものが現れています.

その中をクリックしてもprof4.pngのようにNO SYMBOLで時間が食ってるのは分かりますが, 何で食ってるのかは分かりません.

JITコードが増えてくると一体どれが時間を食ってるのかさっぱり分からなくなります(まあ, 慣れていればある程度分かるのですが).

CodeAnalystのインストールディレクトリにはAPIというディレクトリがあり, その中にはbin/にDLL, include/にヘッダ, lib/にライブラリがおかれています. 今回はinclude/CAJITNTFLib.hというヘッダファイルを使ってみましょう.

ところがドキュメントがないのでよく分かりません(汗). ヘッダを見るとCAJIT_Initialize(), CAJIT_CompleteJITLog(), CAJIT_LogJITCode()という関数があるようなので名前から推測してなんとなく使ってみました.

余談ですが, 現時点(2011/9/13)でCAJIT_Initializeをgoogleで検索すると2件しかヒットせず, そのリンク先も存在してません. CAJIT"の"JI"をくっつけて"N"にして"Did you mean: CAN'T Initialize"と聞いてくるgoogleがおちゃめというか余計なお世話です.

まあそれはともかくCAJIT_Initializeを最初に呼び出して, CAJIT_LogJITCodeで関数を登録して, CAJIT_CompleteJITLogで終わればよいのでしょう. CAJIT_LogJITCodeではJITコードのポインタとそのサイズを与えればよさそうです. やってみたらなんとなく動いたのでその方法を書いてみます.

注意点をいくつか. libとDLLには32-bitと64-bitの両方があり, 正しい組み合わせでないと動きません. 更に, 今のところ何が悪いのかわかってないのですが64bitモードではちゃんと動いてくれてません. また調査します. 今回は32-bitモードでやりましょう.

CAJIT_LogJITCodeに渡す関数名はwchar_t*型なのでL"f"のようにします. 表示時に"UnknownClassName::f"と出てしまうのですが, 実害はないので保留します(何か命名ルールがあるのかもしれません. Java用なのかな).

libパスやincludeパスを正しく設定してコンパイルします. 実行時にはDLLも必要かも. 実行時のパスに注意しましょう.

コードはこんな感じ.

#include <stdio.h>
#include <math.h>
#include <xbyak/xbyak.h>
#define USE_CA

#ifdef USE_CA
#ifdef _WIN64
#define AMD64
#endif
#include "CAJITNTFLib.h"
#pragma comment(lib, "CAJitNtfyLib.lib")
#endif

struct Code : public Xbyak::CodeGenerator {
    Code()
    {
        mov(eax, 1000000);
    L("@@");
        for (int i = 0; i < 10; i++) {
            sub(eax, 1);
        }
        jg("@b");
        mov(eax, 1);
        ret();
    }
};

struct Code2 : public Xbyak::CodeGenerator {
    Code2()
    {
        mov(eax, 1000000);
    L("@@");
        for (int i = 0; i < 10; i++) {
            xorps(xm0, xm0);
        }
        sub(eax, 1);
        jg("@b");
        mov(eax, 1);
        ret();
    }
};

double s1(int n)
{
    double r = 0;
    for (int i = 0; i < n; i++) {
        r += 1.0 / (i + 1);
    }
    return r;
}

double s2(int n)
{
    double r = 0;
    for (int i = 0; i < n; i++) {
        r += 1.0 / (i * i + 1) + 2.0 / (i + 3);
    }
    return r;
}

int main()
{
    Code c;
    Code2 c2;
    int (*f)() = (int (*)())c.getCode();
    int (*g)() = (int (*)())c2.getCode();
#ifdef USE_CA
    CAJIT_Initialize();
#endif
    printf("f:%p, %d\n", f, c.getSize());
    printf("g:%p, %d\n", g, c2.getSize());
#ifdef USE_CA
    CAJIT_LogJITCode((size_t)f, c.getSize(), L"f");
    CAJIT_LogJITCode((size_t)g, c2.getSize(), L"g");
#endif

    double sum = 0;
    for (int i = 0; i < 20000; i++) {
        sum += s1(i);
        sum += s2(i);
    }
    printf("sum=%f\n", sum);
    for (int i = 0; i < 2000; i++) {
        sum += f();
    }
    printf("f=%f\n", sum);
    for (int i = 0; i < 2000; i++) {
        sum += g();
    }
    printf("g=%f\n", sum);
#ifdef USE_CA
    CAJIT_CompleteJITLog();
#endif
    puts("end");
}

#ifdef USE_CA ... #endifでくくったところが追加コードです. XbyakではgetSize()で生成コードのサイズを取得できるのでそれを渡してみました.

実行してみるとprof5.pngのようになりました.

t.exeの他に前回はUnknown module...だったところにJITCodeなるものが現れています. クリックしてみるとpro6.pngのようにシンボルfやgが見えてます.

更にクリックするとprof7.pngの用にJITコードの中身まで表示されました.

いつのタイミングのものを取得してるのかわかりませんが, これはすばらしい.

CodeAnalystのAPIよりはやや複雑ですがやはり初期化と関数の登録と終了の3ステップからなります.

インクルードヘッダとライブラリを指定します.

#ifdef USE_VTUNE
#include "jitprofiling.h"
#pragma comment(lib, "libittnotify.lib")
#pragma comment(lib, "jitprofiling.lib")
#endif

関数の登録用にSetJitCodeという関数を作ってみました. iJIT_IsProfilingActiveFlagsはexeがプロファイラから呼ばれたときでないとエラーを返すようです. 害はなさそうなので単独で動かしてもそのまま進めるようにエラーチェックはしていません.

/* 登録関数 */
void SetJitCode(void *ptr, size_t size, const char *name)
{
    iJIT_Method_Load jmethod = {0};
    jmethod.method_id = iJIT_GetNewMethodID();
    jmethod.class_file_name = "";
    jmethod.source_file_name = __FILE__;

    jmethod.method_load_address = ptr;
    jmethod.method_size = size;
    jmethod.line_number_size = 0;

    jmethod.method_name = const_cast<char*>(name);
    int ret = iJIT_NotifyEvent(iJVM_EVENT_TYPE_METHOD_LOAD_FINISHED, (void*)&jmethod);
    printf("iJIT_NotifyEvent ret=%d\n", ret);
}

{ /* 本体 */
    iJIT_IsProfilingActiveFlags agent = iJIT_IsProfilingActive();
    fprintf(stderr, "iJIT_IsProfilingActive ret=%d\n", agent);
    SetJitCode((void*)f, c.getSize(), "f");
    SetJitCode((void*)g, c2.getSize(), "g");
}

終了コードです.

#ifdef USE_VTUNE
    iJIT_NotifyEvent(iJVM_EVENT_TYPE_SHUTDOWN, NULL);
#endif

vtprof1.pngを見るとCodeAnalystと違ってJITと普通のコードは同じところに表示されています.

VTuneでは32bit, 64bitの両環境でJITのプロファイルが動きました. vtprof2.pngは64bit環境で取ったところです.

64bit環境で調べるなら今のところVTuneの方がよさそうですね. ただVTuneはよく落ちますけど.

prof.cppと mkprof.bat. mkprofはデフォルトのインストールディレクトリにあると仮定したCodeAnalystやVTuneのライブラリやインクルードディレクトリを適当に設定してコンパイルするためのバッチファイルです.

mkprof a prof  ; CodeAnalyst用のバイナリ
mkprof i prof  ; VTune用のバイナリ

というように使います. mkprof.batを作るときに苦労したWindowsのバッチファイルのおかしな規則についてはまたいずれ.