Processor Trace を使ってデバッグ時に詳細なトレースを取得する

Broadwell 世代から、いくつかのCPUではProcessor Traceと呼ばれる機能が付いています。簡単に使いかたを説明します。

Intel Processor Trace

それなりの規模のCPUにはプロセッサ内で発生したイベントを収集する仕組みがあります。よく使うものだと、パフォーマンスカウンタのイベント等ですね。

Haswell以前では、これらのイベントは割り込みを経由して収集されていました。ただ、割り込み経由だと、それなりにオーバーヘッドが大きくなってしまうので、
全てのイベントを収集することは難しく、サンプリングベースのものが主流でした。

Intel Processor Trace は、メモリ経由で、CPU内のイベントを収集する仕組みです。
これを使うと、メモリ経由で大量のイベントを受け取れるようになるので、イベントをサンプリングではなく、全て収集することが可能になります。
また、トレース一個あたりのオーバーヘッドが少ないので、実行中に発生する分岐の履歴なども取得できるようになっており、これをデバッグに活用することも可能です。

今回は、gdb 経由で、このProcessor Traceを使ってみます。
あわせて、 IDF2015の資料一覧から、SPCS012 Zoom in on Your Code with Intel(R) Processor Trace and Supporting Tools も参照するとよいかもしれません。

環境

Linux 4.2 以降、 GDB 7.10 以降の比較的新しい環境が必要です。

GDB でProcessor Traceを有効にするには、GDBのビルド時にintel-pt.hがincludeできる必要があります。(“internal-error: Unexpected branch trace format.”と出るときは有効になっていません)

intel-pt.h は https://github.com/01org/processor-trace に含まれているので、先にビルドしておきます。

使いかた

以下で使っているコードを https://bitbucket.org/fixstars/blog/src/master/small_test/processor-trace.c に置いておきます。最適化で消えないようにするため少し無理な処理が入っていますが、関数の深くでSEGVする処理です。

まずビルドします。事前準備は必要ありません。いつもどおりにビルドすれば良いです。シンボルが必要なら -g を付けましょう。

 $ gcc -O2 -g processor-trace.c

GDB を起動します。

 $ gdb a.out

実行を開始し、トレースを取得したい箇所まで進めます。今回は main から全部取ってもよいので start します。

GNU gdb (GDB) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-unknown-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from a.out...done.
(gdb) start
Temporary breakpoint 1 at 0x4004d0: file processor-trace.c, line 42.
Starting program: /home/w0/src/blog/small_test/a.out 

Temporary breakpoint 1, main () at processor-trace.c:42
42      {

目的のところまで実行が進んだら record pt を実行します。record はレコード開始コマンド、pt は Intel Processor Traceでレコードを取得するという意味です。

(gdb) record pt

これで準備終わりです。実行を続けます。

(gdb) continue
Continuing.

Program received signal SIGSEGV, Segmentation fault.
test0 (n=n@entry=0) at processor-trace.c:10
10                  *(int*)0 = 0;

SEGV しました。この時点で、ここまでの実行履歴がメモリに置かれています。

“record function-call-history” で、関数呼び出しの履歴がとれます。引数に /c を付けると、呼び出し履歴をツリーにして表示できます。

(gdb) record function-call-history /c -
67          test0
68            test0
69              test0
70                test0
71                  test0
72                    test0
73                      test0
74                        test0
75                          test0
76                            test0

表示するカーソルがあり、 /c のあとに – を付けると逆方向に、+を付ける(もしくは何も付けない)と、順方向にカーソルが進みます。 45,55のようにすると、45〜55番目の履歴を表示できます

(gdb) record function-call-history /c 45,55
45                          _IO_default_xsputn
46                            _IO_file_overflow
47                          _IO_default_xsputn
48                            _IO_file_overflow
49                          _IO_default_xsputn
50                            _IO_file_overflow
51                          _IO_default_xsputn
52                            _IO_file_overflow
53                          _IO_default_xsputn
54                        _IO_file_xsputn
55                      puts

“record instruction-history” で、実行した命令の履歴がとれます。reverse-step すると、この履歴を逆方向に辿っていけます。
(副作用は保存されていないので、既存のGDBのReverse Debugのように、変数の状態が復元されるわけではないです

比較

トレースの機能自体はそれほど新しいものではなく、GDBにもこの機能はありました。また、組み込みCPUにも似たような機能はあります。

これらと比較した時の利点は

• 今のデスクトップCPUの速さでトレースが収集できる
• ハードウェア実装なのでデバッグシンボルが無くても呼び出し履歴が取れる

と、いったところでしょうか。

今回使った例では、SEGVする前に10万回ほどループを回しているのですが、これは GDB のソフトウェア実装のトレースだと、15秒ぐらいかかります。
一方、Processor Traceだと、これは一瞬で終わります。

シンボル情報を必要としないので、”gcc -O2 processor-trace.c -s -fno-asynchronous-unwind-tables”のようにコンパイルされたバイナリでも、いくらかの情報が得られるようになります。

(gdb) record function-call-history /ic 65,76
65                    ??        inst 122901,122902
66                      ??      inst 122903,122907
67                        ??    inst 122908,122912
68                          ??  inst 122913,122917
69                            ??        inst 122918,122922
70                              ??      inst 122923,122927
71                                ??    inst 122928,122932
72                                  ??  inst 122933,122937
73                                    ??        inst 122938,122942
74                                      ??      inst 122943,122947
75                                        ??    inst 122948,122952
76                                          ??  inst 122953,122957
(gdb) record instruction-history 122901,122902
122901     0x0000000000400474:  mov    $0xa,%edi
122902     0x0000000000400479:  callq  0x400590

/i を付けると、対応するinstruction history の範囲を取得できます。 record instruction-history でその範囲を指定すると対応する命令が取得できます

この機能は、JITコンパイルして出した機械語をデバッグする時などに有効かもしれません。

まとめ

Processor Trace の紹介と GDB から使う方法でした。

まあ、デバッグ時にぱっと適切に使うのも難しい気もしますが、よくわからない理由でシンボルが見えなくてバックトレース表示できないとかそういう時に思い出すと何かの役に立つかもしれないです。

このサイトはスパムを低減するために Akismet を使っています。コメントデータの処理方法の詳細はこちらをご覧ください。