uftrace を使ってプログラムの中身を解析/リバースエンジニアリングする (1) uftrace 紹介編
はじめに
Linuxのuftraceというツールを使うと, あるプログラムを実行している際の関数呼び出しの回数や 呼び出しの履歴(呼び出された順番)を記録, 表示することができます.
この記事では, uftraceの使い方と, それを使って中身のよくわからない プログラムの中身を調査する(リバースエンジニアリングする) 方法を紹介します. 例題として, スプレッドシートプログラムgnumericのセルに 式を入力した際, その中身を読み取っている関数名や, そのソースコードの場所を突き止めることを目標にします (例えばgnumericに新しい関数を付け加えるという変更を したいと想像してください).
このように, あるプログラムの機能変更や拡張をしたいというときに, ある機能を担っているのは, どのソースファイルや関数なのか を調べるという調査がしばしば必要になります. この時, uftraceのプロファイリング機能(具体的には呼び出された 関数を表示してくれる機能)が有用になります.
もともとプロファイリングという機能は各関数の実行時間 を記録するなどして, プログラム最適化の助けとするというのが 普通の使い方ですが, ここで紹介するような, 「ある期間に実行された関数名を列挙したい」というような 目的にも使うことができます.
GCCのプロファイル機能(-pg)と少し似ていますが, GCCのプロファイル機能は, 共有ライブラリ のプロファイリングには対応していないという 致命的な欠点があります. uftraceは共有ライブラリ にも対応していますし, プロファイリングだけでなく, トレーシング(関数が呼び出された順番を全て記録する) も行うことができます. プログラムの一部だけを記録する 方法もしっかり定義されていますし, Pythonスクリプトと組み合わせて表示をカスタマイズする こともできる, 有用なツールです.
uftraceのインストール
- 方法1: パッケージ管理システムで導入
- Ubuntuであれば,
$ sudo apt install uftrace
で導入できます(Ubuntu 17.04で確かめています. 他のバージョンや他のディストロの状況は知りません. 悪しからず). - 方法2: ソースからビルド
-
$ git clone https://github.com/namhyung/uftrace.git (またはgit@github.com:namhyung/uftrace.git) $ cd uftrace $ ./configure --prefix=PREFIX $ make $ make install
make installが成功した時点で PREFIX/bin/uftrace, PREFIX/lib/libmcount.so などのファイルができているはずです.
uftraceの実行
あるプログラムをuftraceで調査するのは簡単で,
- プログラムをコンパイルする際に GCCに-pgオプションを付けてコンパイルする
- できたプログラムを実行する際に,
$ uftrace record コマンドライン
として実行する - 記録を表示するために,
$ uftrace reportとする.
だけです. -pgオプションを付けるところまでは, GCCのプロファイル機能と同じです. uftrace recordは, デフォルトではuftrace.dataという フォルダを作りその中に色々な情報を記録します. uftrace report はそれを読んで表示しています.
実行例
- 例として以下のプログラムを準備
int g() { } int f(int n) { for (int i = 0; i < n; i++) { g(); } } int main() { int n = 100; for (int i = 0; i < n; i++) { f(i); } return 0; } - コンパイル
$ g++ -O0 -g -pg a.c
中身が空の関数呼び出し(g()など) が最適化によって消されないようにするため, -O0をつけています. - 実行
$ uftrace record ./a.out $ ls a.c a.out* uftrace.data/ uftrace.html
実行後, uftrce.dataができていることを確認しています. - 表示
$ uftrace report Total time Self time Calls Function ========== ========== ========== ==================== 747.367 us 8.668 us 1 main 738.699 us 524.547 us 100 f 214.152 us 214.152 us 4950 g 4.657 us 4.657 us 1 __monstartup 0.859 us 0.859 us 1 __cxa_atexitfが100回, gが4950 (= 0 + 1 + 2 + ... + 99)回 実行されていることが確認できました.
トレースの表示
uftraceは, 各関数の呼び出し回数だけでなく, どの関数がどの順番に実行されたか(トレース)までを記録しています. それを表示するには, uftrace replayというコマンドを使います.
$ uftrace replay
4.657 us [ 8756] | __monstartup();
0.859 us [ 8756] | __cxa_atexit();
[ 8756] | main() {
0.074 us [ 8756] | f();
[ 8756] | f() {
0.068 us [ 8756] | g();
0.318 us [ 8756] | } /* f */
[ 8756] | f() {
0.047 us [ 8756] | g();
0.043 us [ 8756] | g();
0.432 us [ 8756] | } /* f */
[ 8756] | f() {
0.046 us [ 8756] | g();
0.053 us [ 8756] | g();
0.045 us [ 8756] | g();
0.598 us [ 8756] | } /* f */
[ 8756] | f() {
0.045 us [ 8756] | g();
0.043 us [ 8756] | g();
0.036 us [ 8756] | g();
0.044 us [ 8756] | g();
0.620 us [ 8756] | } /* f */
... 以下省略 ...
recordとreplayを一回のコマンドで行うコマンド(live)もありますし, 実はそれが省略時の動作です.
関数の定義場所(ソースコードの位置)を取得する
uftraceは呼び出された関数名を表示してくれます. リバースエンジニアリングに使う際は, 関数名を見ただけで 目的の関数の見当がつく場合も有りますが, そのソースコード上の位置(このファイルの何行目)情報も 表示できるとなお有用になります. uftraceにはそのための 組み込みの機能はありませんが, トレース結果をPython scriptに渡してくれるという仕組みがあります.
$ uftrace script -S my_script.py
とすると, uftrace.dataフォルダ内に保存されたトレース記録 (uftrace recordやuftrace replayが参照するのと同じデータ) を, Pythonスクリプトに順々に渡してくれます. その中に, 関数のアドレスが 入っており, それを上手く調理することでソースコード上の位置を取得できます.
なお, uftrace自身を自分でビルドした人は, ビルド時に libpython2.7 というパッケージがないと機能が無効化されていて, libpython2.7がない, みたいなエラーメッセージが出てきます.
$ uftrace script WARN: script command is not supported due to missing libpython2.7.so
uftrace script の詳細は このページ にあります. また, それを使って関数のソースコード上の位置を表示するスクリプト を作りました. この詳細説明は割愛します. uftrace recordの代わりに, uftrace script -S show_src_line.pyとしてください. なおこのスクリプトは, アドレスからソースファイル名+行番号への変更を, binutilsパッケージの addr2lineコマンドを使ってやっていますのでインストールされていなかったらしてください.
$ sudo apt install binutils $ which addr2line /usr/bin/addr2line
$ uftrace record ./a.out $ uftrace script -S show_src_line.py src_file line_no fun_name @ addr count /home/tau/.../blog/a.c 1 start_recording @ 0x7ca 1 /home/tau/.../blog/a.c 2 stop_recording @ 0x7d7 1 /home/tau/.../blog/a.c 6 g @ 0x7e4 4950 /home/tau/.../blog/a.c 8 f @ 0x7f5 100 /home/tau/.../blog/a.c 15 main @ 0x828 1 ?? 0 __cxa_atexit @ 0x628 1 ?? 0 __monstartup @ 0x620 1
(表示のうちのパス名の部分は適当に編集しています). 1カラム目がファイル名, 2カラム目が行番号です. 最後のカラムが呼び出し回数です.
実行の一部だけを記録する
uftraceのデフォルトの動作ではプログラム実行全体に渡り記録がとられますが, 一部の区間だけを記録したいということもしばしばあります. 性能測定であれば特定の関数の実行中だけを記録したいということがあるでしょうし, ある機能を実現している関数を見つける(リバースエンジニアリング)目的では, その機能が呼び出されている間だけを記録したいということになります. uftraceはそのような測定にも対応してくれており,
- --disable :
- プログラム開始時に測定を開始しない
- --trigger=関数名@trace_on, --trigger=関数名@trace_off :
- 指定された関数が呼び出されたところで測定開始
- --trigger=関数名@trace_on :
- 指定された関数が呼び出されたところで測定終了
を組み合わせて使います.
例えば我々の例題プログラムでf(0), f(1), f(2), ..., f(99) とfが100回呼び出されるうちの, f(10)のところだけを 記録したいという場合であれば以下のようにします.
- プログラムを以下のように修正 そしてコンパイル
void start_recording() { } void stop_recording() { } int g() { } int f(int n) { for (int i = 0; i < n; i++) { g(); } } int main() { int n = 100; for (int i = 0; i < n; i++) { if (i == 10) start_recording(); f(i); if (i == 10) stop_recording(); } return 0; }
$ gcc -pg -O0 -g a.c
- uftrace実行時に以下のようにして実行
$ uftrace record --disable --trigger=start_recording@trace_on --trigger=stop_recording@trace_off ./a.out
- すると結果は以下のようになり, たしかにf(10)だけが 記録されているということがわかります.
$ uftrace report Total time Self time Calls Function ========== ========== ========== ==================== 3.514 us 2.651 us 1 f 0.863 us 0.863 us 10 g 0.232 us 0.232 us 1 start_recording$ uftrace replay # DURATION TID FUNCTION 0.232 us [14846] | start_recording(); [14846] | f() { 0.100 us [14846] | g(); 0.101 us [14846] | g(); 0.074 us [14846] | g(); 0.077 us [14846] | g(); 0.089 us [14846] | g(); 0.080 us [14846] | g(); 0.076 us [14846] | g(); 0.094 us [14846] | g(); 0.086 us [14846] | g(); 0.086 us [14846] | g(); 3.514 us [14846] | } /* f */
ここまでのまとめ
- uftraceは偉大な性能測定/リバースエンジニアリングツール
- 対象プログラムを gcc -pg でコンパイル
- 「uftrace record コマンド ... 」で実行
- uftrace report またはuftrace replayで表示
- ソースファイル名や行番号を表示したいなら, script機能を使う
- 一部だけを記録したいなら, uftrace --disable --trigger=F@trace_on --trigger=G@trace_offとして, 記録開始時にF, 記録終了時にGを呼ぶ. 中身はなんでも(空でも)良い.
次回はこれを使って, gnumericをリバース・エンジニアリングします.
