XRay を使用したデバッグ¶
このドキュメントでは、XRay インストルメンテーションを使用してビルドされたアプリケーションを分析する方法の例を示します。ここでは、Clang が生成したサンプル LLVM IR をコンパイルするllcのデバッグを試みます。
XRay を使用したビルド¶
XRay インストルメンテーションを使用してアプリケーションをデバッグするには、-fxray-instrumentオプションをサポートするClangを使用してビルドする必要があります。背景情報として、XRay の動作に関するより技術的な詳細については、XRayを参照してください。
この例では、バイナリをビルドする際にClangに渡されるフラグのリストに-fxray-instrumentを追加する必要があります。XRay ランタイムを適切にリンクするには、Clang ともリンクする必要があることに注意してください。XRay を使用して llc をビルドするには、LLVM ビルドで以下に示すような同様の処理を行います。
$ mkdir -p llvm-build && cd llvm-build
# Assume that the LLVM sources are at ../llvm
$ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \
-DCMAKE_C_FLAGS_RELEASE="-fxray-instrument" -DCMAKE_CXX_FLAGS="-fxray-instrument" \
# Once this finishes, we should build llc
$ ninja llc
XRay インストルメント化されたバイナリを持っていることを確認するには、objdumpを使用してxray_instr_mapセクションを探します。
$ objdump -h -j xray_instr_map ./bin/llc
./bin/llc: file format elf64-x86-64
Sections:
Idx Name Size VMA LMA File off Algn
14 xray_instr_map 00002fc0 00000000041516c6 00000000041516c6 03d516c6 2**0
CONTENTS, ALLOC, LOAD, READONLY, DATA
トレースの取得¶
デフォルトでは、XRay はメインが開始する前にトレースファイルを出力したり、アプリケーションにパッチを当てたりしません。llcを実行すると、通常ビルドされたバイナリのように動作するはずです。アプリケーションの動作の完全なトレース（XRay でインストルメント化された関数のトレース）を取得する場合は、アプリケーションの開始時に XRay を有効にする必要があります。これを行うために、XRay はXRAY_OPTIONS環境変数を確認します。
# The following doesn't create an XRay trace by default.
$ ./bin/llc input.ll
# We need to set the XRAY_OPTIONS to enable some features.
$ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic verbosity=1" ./bin/llc input.ll
==69819==XRay: Log file in 'xray-log.llc.m35qPB'
この時点で、分析を開始できる XRay トレースができました。
llvm-xrayツール¶
トレースがあれば、インストルメント化された関数の基本的なアカウンティングと、コードの一部で費やされた時間量を把握できます。このデータの意味を理解するために、llvm-xrayツールを使用します。このツールには、トレースの理解に役立ついくつかのサブコマンドがあります。
できることの1つは、インストルメント化された関数のアカウンティングを取得することです。llvm-xray accountを使用して、アカウンティングの例を確認できます。
$ llvm-xray account xray-log.llc.m35qPB --top=10 --sort=sum --sortorder=dsc --instr_map=./bin/llc
Functions with latencies: 29
funcid count [ min, med, 90p, 99p, max] sum function
187 360 [ 0.000000, 0.000001, 0.000014, 0.000032, 0.000075] 0.001596 LLLexer.cpp:446:0: llvm::LLLexer::LexIdentifier()
85 130 [ 0.000000, 0.000000, 0.000018, 0.000023, 0.000156] 0.000799 X86ISelDAGToDAG.cpp:1984:0: (anonymous namespace)::X86DAGToDAGISel::Select(llvm::SDNode*)
138 130 [ 0.000000, 0.000000, 0.000017, 0.000155, 0.000155] 0.000774 SelectionDAGISel.cpp:2963:0: llvm::SelectionDAGISel::SelectCodeCommon(llvm::SDNode*, unsigned char const*, unsigned int)
188 103 [ 0.000000, 0.000000, 0.000003, 0.000123, 0.000214] 0.000737 LLParser.cpp:2692:0: llvm::LLParser::ParseValID(llvm::ValID&, llvm::LLParser::PerFunctionState*)
88 1 [ 0.000562, 0.000562, 0.000562, 0.000562, 0.000562] 0.000562 X86ISelLowering.cpp:83:0: llvm::X86TargetLowering::X86TargetLowering(llvm::X86TargetMachine const&, llvm::X86Subtarget const&)
125 102 [ 0.000001, 0.000003, 0.000010, 0.000017, 0.000049] 0.000471 Verifier.cpp:3714:0: (anonymous namespace)::Verifier::visitInstruction(llvm::Instruction&)
90 8 [ 0.000023, 0.000035, 0.000106, 0.000106, 0.000106] 0.000342 X86ISelLowering.cpp:3363:0: llvm::X86TargetLowering::LowerCall(llvm::TargetLowering::CallLoweringInfo&, llvm::SmallVectorImpl<llvm::SDValue>&) const
124 32 [ 0.000003, 0.000007, 0.000016, 0.000041, 0.000041] 0.000310 Verifier.cpp:1967:0: (anonymous namespace)::Verifier::visitFunction(llvm::Function const&)
123 1 [ 0.000302, 0.000302, 0.000302, 0.000302, 0.000302] 0.000302 LLVMContextImpl.cpp:54:0: llvm::LLVMContextImpl::~LLVMContextImpl()
139 46 [ 0.000000, 0.000002, 0.000006, 0.000008, 0.000019] 0.000138 TargetLowering.cpp:506:0: llvm::TargetLowering::SimplifyDemandedBits(llvm::SDValue, llvm::APInt const&, llvm::APInt&, llvm::APInt&, llvm::TargetLowering::TargetLoweringOpt&, unsigned int, bool) const
これにより、入力ファイルに対してllcが累積時間で最も多くの時間をレキサーに費やしたことがわかります（合計1ミリ秒）。たとえば、スプレッドシートでこのデータを使用したい場合は、-format=csvオプションをコマンドに追加してCSVとして結果を出力し、さらに分析できます。
生のトレースのテキスト表現を取得する場合は、llvm-xray convertツールを使用してYAML出力できます。例として、トレースの先頭数行は次のようになります。
$ llvm-xray convert -f yaml --symbolize --instr_map=./bin/llc xray-log.llc.m35qPB
---
header:
version: 1
type: 0
constant-tsc: true
nonstop-tsc: true
cycle-frequency: 2601000000
records:
- { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426023268520 }
- { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426023523052 }
- { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426029925386 }
- { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426030031128 }
- { type: 0, func-id: 142, function: '(anonymous namespace)::CommandLineParser::ParseCommandLineOptions(int, char const* const*, llvm::StringRef, llvm::raw_ostream*)', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426046951388 }
- { type: 0, func-id: 142, function: '(anonymous namespace)::CommandLineParser::ParseCommandLineOptions(int, char const* const*, llvm::StringRef, llvm::raw_ostream*)', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426047282020 }
- { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426047857332 }
- { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426047984152 }
- { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048036584 }
- { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048042292 }
- { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048055056 }
- { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048067316 }
忠実度の制御¶
これまでの例では、バイナリにある関数の完全なカバレッジを取得していません。それを取得するには、コンパイラフラグを変更して、バイナリにある関数（すべてではないにしても）をより多くインストルメント化できるようにする必要があります。これを行うには2つのオプションがあり、以下ではその両方を探ります。
命令のしきい値¶
これを行う最初の「直接的な」方法は、関数の本体の最小しきい値を1に設定することです。これは、バイナリをビルドする際に-fxray-instruction-threshold=Nフラグを使用して行うことができます。llcをこのオプションで再構築し、結果を確認します。
$ rm CMakeCache.txt
$ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \
-DCMAKE_C_FLAGS_RELEASE="-fxray-instrument -fxray-instruction-threshold=1" \
-DCMAKE_CXX_FLAGS="-fxray-instrument -fxray-instruction-threshold=1"
$ ninja llc
$ XRAY_OPTIONS="patch_premain=true" ./bin/llc input.ll
==69819==XRay: Log file in 'xray-log.llc.5rqxkU'
$ llvm-xray account xray-log.llc.5rqxkU --top=10 --sort=sum --sortorder=dsc --instr_map=./bin/llc
Functions with latencies: 36652
funcid count [ min, med, 90p, 99p, max] sum function
75 1 [ 0.672368, 0.672368, 0.672368, 0.672368, 0.672368] 0.672368 llc.cpp:271:0: main
78 1 [ 0.626455, 0.626455, 0.626455, 0.626455, 0.626455] 0.626455 llc.cpp:381:0: compileModule(char**, llvm::LLVMContext&)
139617 1 [ 0.472618, 0.472618, 0.472618, 0.472618, 0.472618] 0.472618 LegacyPassManager.cpp:1723:0: llvm::legacy::PassManager::run(llvm::Module&)
139610 1 [ 0.472618, 0.472618, 0.472618, 0.472618, 0.472618] 0.472618 LegacyPassManager.cpp:1681:0: llvm::legacy::PassManagerImpl::run(llvm::Module&)
139612 1 [ 0.470948, 0.470948, 0.470948, 0.470948, 0.470948] 0.470948 LegacyPassManager.cpp:1564:0: (anonymous namespace)::MPPassManager::runOnModule(llvm::Module&)
139607 2 [ 0.147345, 0.315994, 0.315994, 0.315994, 0.315994] 0.463340 LegacyPassManager.cpp:1530:0: llvm::FPPassManager::runOnModule(llvm::Module&)
139605 21 [ 0.000002, 0.000002, 0.102593, 0.213336, 0.213336] 0.463331 LegacyPassManager.cpp:1491:0: llvm::FPPassManager::runOnFunction(llvm::Function&)
139563 26096 [ 0.000002, 0.000002, 0.000037, 0.000063, 0.000215] 0.225708 LegacyPassManager.cpp:1083:0: llvm::PMDataManager::findAnalysisPass(void const*, bool)
108055 188 [ 0.000002, 0.000120, 0.001375, 0.004523, 0.062624] 0.159279 MachineFunctionPass.cpp:38:0: llvm::MachineFunctionPass::runOnFunction(llvm::Function&)
62635 22 [ 0.000041, 0.000046, 0.000050, 0.126744, 0.126744] 0.127715 X86TargetMachine.cpp:242:0: llvm::X86TargetMachine::getSubtargetImpl(llvm::Function const&) const
インストルメンテーション属性¶
もう1つの方法は、コンパイラが常にインストルメント化する関数を選択するための構成ファイルを使用することです。これにより、ソースに属性を追加しなくても、特定の関数を常に、または決してインストルメント化しないようにすることができます。
この機能を使用するには、常にインストルメント化する関数のファイルと、決してインストルメント化しない関数のファイルを定義できます。これらのファイルの形式は、サニタイザの実装で同様のことを制御するSanitizerListsファイルとまったく同じです。例を挙げると
# xray-attr-list.txt
# always instrument functions that match the following filters:
[always]
fun:main
# never instrument functions that match the following filters:
[never]
fun:__cxx_*
上記のファイルを使用して、それをClangの-fxray-attr-list=フラグに渡して再構築できます。それぞれ異なる属性セットを定義する複数のファイルを持ち、Clangによって1つのリストにまとめることができます。
XRay スタックツール¶
トレースと、オプションでインストルメンテーションマップがあると、llvm-xray stackコマンドを使用して、関数呼び出しタイムラインから構築されたコールスタックグラフを分析できます。
このコマンドを使用する方法は、呼び出し回数と費やされた時間によって上位のスタックを出力することです。
$ llvm-xray stack xray-log.llc.5rqxkU --instr_map=./bin/llc
Unique Stacks: 3069
Top 10 Stacks by leaf sum:
Sum: 9633790
lvl function count sum
#0 main 1 58421550
#1 compileModule(char**, llvm::LLVMContext&) 1 51440360
#2 llvm::legacy::PassManagerImpl::run(llvm::Module&) 1 40535375
#3 llvm::FPPassManager::runOnModule(llvm::Module&) 2 39337525
#4 llvm::FPPassManager::runOnFunction(llvm::Function&) 6 39331465
#5 llvm::PMDataManager::verifyPreservedAnalysis(llvm::Pass*) 399 16628590
#6 llvm::PMTopLevelManager::findAnalysisPass(void const*) 4584 15155600
#7 llvm::PMDataManager::findAnalysisPass(void const*, bool) 32088 9633790
..etc..
デフォルトモードでは、異なるスレッド上の同一のスタックは個別に集計されます。マルチスレッドプログラムでは、同一のコールスタックが上位呼び出しのリストを埋めることになります。
これに対処するために、--aggregate-threadsまたは--per-thread-stacksフラグを指定できます。--per-thread-stacksは、スレッドIDを各コールスタックツリーの暗黙的なルートとして扱い、--aggregate-threadsはすべてのスレッドからの同一のスタックを組み合わせます。
Flame Graph の生成¶
llvm-xray stackツールは、インストルメント化された呼び出しを視覚化するためのFlameGraphを生成するためにも使用できます。このツール自体はグラフを生成しませんが、現在githubで利用可能なBrendan GreggのFlameGraphツールで使用できる形式を生成します。
FlameGraphの出力を作成するには、さらにいくつかのオプションが必要です。
--all-stacks- すべてのスタックを出力します。--stack-format- FlameGraph出力形式「flame」を選択します。--aggregation-type- グラフ化するメトリックを選択します。
コマンドの出力をFlameGraphツールに直接パイプして、svgファイルを取得できます。
$ llvm-xray stack xray-log.llc.5rqxkU --instr_map=./bin/llc --stack-format=flame --aggregation-type=time --all-stacks | \
/path/to/FlameGraph/flamegraph.pl > flamegraph.svg
ブラウザでsvgを開くと、マウスイベントを使用してコールスタックを探索できます。
Chrome Trace Viewer による可視化¶
同じ生成されたトレースから、Chrome Trace Viewerでロードできるトレースを生成することもできます。
$ llvm-xray convert --symbolize --instr_map=./bin/llc \
--output-format=trace_event xray-log.llc.5rqxkU \
| gzip > llc-trace.txt.gz
Chromeブラウザでchrome:///tracingに移動すると、sample-trace.txt.gzファイルを読み込んで実行トレースを視覚化できます。
さらなる調査¶
llvm-xrayツールには、開発のさまざまな段階にある他のいくつかのサブコマンドがあります。いくつかの興味深い点を強調できる興味深いサブコマンドの1つは、graphサブコマンドです。たとえば、XRayインストルメンテーションでビルドした次のトイプログラムを考えると、生成されたグラフがアプリケーションで時間が費やされている場所を示すのに役立つ指標になり得る方法を確認できます。
// sample.cc
#include <iostream>
#include <thread>
[[clang::xray_always_instrument]] void f() {
std::cerr << '.';
}
[[clang::xray_always_instrument]] void g() {
for (int i = 0; i < 1 << 10; ++i) {
std::cerr << '-';
}
}
int main(int argc, char* argv[]) {
std::thread t1([] {
for (int i = 0; i < 1 << 10; ++i)
f();
});
std::thread t2([] {
g();
});
t1.join();
t2.join();
std::cerr << '\n';
}
次に、上記のものをXRayインストルメンテーションでビルドします。
$ clang++ -o sample -O3 sample.cc -std=c++11 -fxray-instrument -fxray-instruction-threshold=1
$ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic" ./sample
次に、このサンプルアプリケーションによって生成されたトレースのグラフレンダリングを調べることができます。unflattenとdotの両方を含む、システムにgraphvizツールが利用可能であると仮定します。別のツールを使用してグラフをレンダリングまたは調査したい場合は、それも可能です。llvm-xray graphはDOT形式のグラフを作成し、ほとんどのグラフレンダリングアプリケーションで使用できます。llvm-xray graphコマンドの呼び出し例は、C++アプリケーションの動作に関するいくつかの興味深い洞察をもたらします。
$ llvm-xray graph xray-log.sample.* -m sample --color-edges=sum --edge-label=sum \
| unflatten -f -l10 | dot -Tsvg -o sample.svg
次のステップ¶
llvm-xrayツールの機能として実装したい興味深い分析がある場合は、llvm-dev@メーリングリストで提案してください。以下は、参加し、状況を改善する上で役立つアイデアです。
XRayトレースのパターンを見つけることができるクエリ/フィルタリングライブラリを実装します。
関数呼び出しスタックと、XRayトレースで遭遇する頻度を収集します。