使用 XRay 進行偵錯

本文檔示範如何分析使用 XRay instrumentation 建置的應用程式。在此,我們將嘗試偵錯 llc 編譯器,編譯一些由 Clang 產生的範例 LLVM IR。

使用 XRay 建置

要使用 XRay instrumentation 偵錯應用程式,我們需要使用支援 -fxray-instrument 選項的 Clang 來建置它。有關 XRay 如何運作的更多技術細節,請參閱 XRay 以取得背景資訊。

在我們的範例中,我們需要將 -fxray-instrument 新增到建置二進制檔案時傳遞給 Clang 的旗標列表中。請注意,我們也需要與 Clang 連結,以適當地連結 XRay 執行時期函式庫。對於使用 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 instrumentation 的二進制檔案,我們可以使用 objdump 來尋找 xray_instr_map section。

$ 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 不會寫出追蹤檔案,也不會在 main 函數開始之前修補應用程式。如果我們執行 llc,它的運作方式應該像正常建置的二進制檔案一樣。如果我們想要取得應用程式操作的完整追蹤資料(針對我們最終使用 XRay instrumentation 的函數),那麼我們需要在應用程式啟動時啟用 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 工具

取得追蹤資料後,我們就可以對 instrumentation 的函數進行基本統計,以及我們在程式碼各部分花費的時間。為了理解這些資料,我們使用 llvm-xray 工具,該工具具有一些子命令,可幫助我們理解追蹤資料。

我們可以執行的一件事是對已 instrumentation 的函數進行統計。我們可以透過 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 }

控制精確度

到目前為止,在我們的範例中,我們尚未獲得二進制檔案中函數的完整覆蓋率。為了實現這一點,我們需要修改編譯器旗標,以便我們可以 instrumentation 更多(如果不是全部)二進制檔案中的函數。我們有兩種方法可以做到這一點,我們將在下面探討這兩種方法。

指令閾值

第一種「直接」的方法是將函數主體的最小閾值設定為 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

Instrumentation 屬性

另一種方法是使用配置文件來選擇應始終由編譯器 instrumentation 的函數。這為我們提供了一種確保某些函數始終或永不被 instrumentation 的方法,而無需將屬性新增至原始碼。

要使用此功能,您可以為始終要 instrumentation 的函數定義一個檔案,為永不 instrumentation 的函數定義另一個檔案。這些檔案的格式與 SanitizerLists 檔案完全相同,後者控制 sanitizer 實作的類似事項。例如

# 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 組合到單個列表中。

XRay stack 工具

給定追蹤資料,以及可選的 instrumentation map,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 則合併來自所有線程的相同堆疊。

火焰圖生成

llvm-xray stack 工具也可用於生成火焰圖,以視覺化您的 instrumentation 調用。該工具本身不生成圖形,而是生成一種格式,可以與 Brendan Gregg 的 FlameGraph 工具一起使用,目前可在 github 上取得。

要為火焰圖生成輸出,還需要一些其他選項。

  • --all-stacks - 發出所有堆疊。

  • --stack-format - 選擇火焰圖輸出格式 '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 工具還有一些其他子命令,它們處於不同的開發階段。一個有趣的子命令是 graph 子命令,它可以突顯一些有趣的事情。例如,給定以下我們使用 XRay instrumentation 建置的玩具程式,我們可以了解產生的圖形如何成為應用程式花費時間位置的有用指標。

// 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 instrumentation 建置上述程式

$ 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

然後,我們可以探索由此範例應用程式產生的追蹤資料的圖形渲染。我們假設您的系統中已安裝 graphviz 工具,包括 unflattendot。如果您喜歡使用其他工具渲染或探索圖形,那麼這也應該是可行的。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 追蹤資料中遇到的頻率。