(移植編第6回)プロファイラの機能でログ出力を埋め込んでみる

2009/04/19

あなたは 人目のお客様です.

最近,プロファイラについてちょっとしたアイディアが出たので, 今回はプロファイラの機能を使ってデバッグ用のログ出力の埋め込みというのを やってみよう.

まずはプロファイラの説明だけど,プロファイラって積極的に使っているひとは なにげにあまりいなかったりするものだけど,gccの場合だと簡単にいうとこんな ことができる.

まあ使いかたについては 「UNIX プログラミングの道具箱」 にザックリ書いてあるので,興味のあるかたは参照してほしい.見てわかるとおり, プログラム中で重い部分(ホットスポットという)を見つけてチューニングするための 情報収集につかうものなのだけど,今回はこの -pg の機能を利用して, ちょっと面白いことをやってみよう.

-pgつけてコンパイルすると実際には何が行われるかというと,関数の先頭に必ず 特定の関数呼び出しを行うようなコードが付加される. 実際にプロファイラを動かしたときには,すべての関数の先頭で特定の処理 (統計を記録するような)が行われるわけだ.実際にどんな処理が行われるかは ちょっとよくわかっていないのでここでは説明を省くが,今回利用するのはこの 「関数の先頭に,特定の関数を呼び出すようなコードを付加する」という機能だ.

ためしに -pg をつけてコンパイルしてみよう.

まず,ふつうにコンパイルした場合を見てみる.-S をつけてコンパイルすることで, アセンブラコードとして main.s が作成される.

% /usr/local/powerpc-linux/bin/gcc -c -S main.c -Wall -nostdinc -fno-builtin -msoft-float -I../uboot/u-boot.git/include -g -DKOZOS
これで作成された main.s の中身を見てみる.
        .globl main
        .type   main, @function
main:
.LFB6:
        .loc 1 94 0
        stwu 1,-32(1)
.LCFI13:
        mflr 0
        stw 31,28(1)
.LCFI14:
        stw 0,36(1)
これは main() 関数の先頭部分なのだけど,関数の先頭ではまず mflr で GPR0 にLRの値を保存している.で,stwu で GPR1 の値を減算することで スタックを確保して,スタックに(GPR0にコピーした)LRの値を保存している.

つぎに -pg をつけて同じようにコンパイルしてみよう.

% /usr/local/powerpc-linux/bin/gcc -c -S main.c -Wall -nostdinc -fno-builtin -msoft-float -I../uboot/u-boot.git/include -g -DKOZOS -pg
お尻に -pg がついていることに注目.で,同じように作成された main.s を見てみる.
        .globl main
        .type   main, @function
main:
.LFB6:
        .loc 1 94 0
        .section        ".data"
        .align 2
.LP6:
        .long   0
        .section        ".text"
        mflr 0
        lis 12,.LP6@ha
        stw 0,4(1)
        la 0,.LP6@l(12)
        bl _mcount
        stwu 1,-32(1)
.LCFI16:
        mflr 0
        stw 31,28(1)
.LCFI17:
        stw 0,36(1)
上は同じ main() 関数の先頭部分なのだけど,stwu によるスタック確保の前に, いくつかの命令が追加されている.

まずはスタック確保の直前で _mcount という関数が呼ばれていることに注目して ほしい.これが,プロファイリングを行うための関数呼び出しだ.

で,この _mcount() を自前で用意してやることで,すべての関数呼び出し時に 特定の処理を入れることができる.たとえば関数呼び出しのログを保存するとかだ. これはデバッグに非常に役に立つのではなかろうか.

実際に埋め込まれた _mcount() 呼び出し処理をよくみてみよう. LRの値をGPR1 + 4の位置に保存してから _mcount() を呼んでいる. _mcount() から戻った後は,即座にLRの値をスタックに保存しているから, LRの値はきちんと設定した上で _mcount() から戻ってこないといけないようだ.

なので,_mcount() はこんなふうに書けばいいんではなかろうか.

	.text
	.globl	_mcount
	.type	_mcount,@function
_mcount:
	stwu	1,-48(1)
	stw	 3,16(1)
	stw	 4,20(1)
	stw	 5,24(1)
	stw	 6,28(1)
	stw	 7,32(1)
	stw	 8,36(1)
	stw	 9,40(1)
	stw	10,44(1)
	mflr	3
	stw	3,8(1)
	bl	logging

	lwz	9,8(1)
	mtctr	9
	lwz	10,52(1)
	mtlr	10
	lwz	 3,16(1)
	lwz	 4,20(1)
	lwz	 5,24(1)
	lwz	 6,28(1)
	lwz	 7,32(1)
	lwz	 8,36(1)
	lwz	 9,40(1)
	lwz	10,44(1)
	addi	1,1,48
	bctr
_mcount() ではレジスタの値を一時的にスタックに保存して logging() を呼び出し, レジスタの値を復旧して呼び出し元に戻っている. ちなみに戻るときはLRの値を設定した状態で戻らなければならない (呼び出し元では,LRが差す先に戻ろうとするから)ので,戻るのにblrは使えない. ということで,LRの値を設定した後にbctrで戻っている.

問題はレジスタの退避なのだけど,厳密にいえばlogging()で利用しているレジスタ のみ保存すればよい. というのは,ここで保存しているのは,関数呼び出しの先頭で _mcount() が呼ばれた 際に,_mcount() の処理でレジスタの値が書き変わってしまうと,レジスタ経由で 渡された本来の引数の値が破壊されてしまうからだ.

PowerPCのABIでは,GPR3〜GPR10を引数渡しに利用することになっている. なのでさらに厳密には,logging()内部でGPR3〜GPR10のレジスタを利用している 場合には,それだけ保存すればよい.だけどこれは logging() を書き換えるたびに どのレジスタを利用しているか調べる必要が出てしまって面倒なので, GPR3〜GPR10の全部を保存するようにしている.

で,作成したのが以下のコード.

_mcount() はアセンブラで書く必要があるので,mcount.s というファイルを追加した. あと logging の実体として logging.h, logging.c が追加してある.

logging() は特定メモリ領域に関数のアドレスを保存するように, 以下のような感じで書いてみた.

int logging_disable = 0;
int logging_cur = 0;
int logging_buf[LOGGING_BUF_SIZE];

void logging(int addr)
{
  if (!logging_disable) {
    logging_buf[logging_cur++] = addr;
    if (logging_cur >= LOGGING_BUF_SIZE)
      logging_cur = 0;
  }
}
これで,_mcount() の呼び出しもとのアドレスが logging_buf[] に保存される. _mcount() を呼び出すのは,-pg によって先頭で _mcount() を呼び出すように コード付加された関数なので,-pg つけてコンパイルしたソースコードの関数が 実行されると,ログが logging_buf[] に保存されるということになる.

で,command.c にコマンド追加した.「log」コマンドを実行すると, 現在保存されているログが表示される.

    } else if (!strncmp(buffer, "log", 3)) {
      logging_disable = 1;
      log = logging_cur;
      for (i = 0; i < LOGGING_BUF_SIZE; i++) {
        ub_printf("%d %08x\n", i, logging_buf[log++]);
        if (log >= LOGGING_BUF_SIZE)
          log = 0;
      }
      logging_disable = 0;
Makefile は特定のファイルのみ -pg 付きでコンパイルされるように修正. とりあえず今回は extintr.c を対象にしてみた.
diff -ruN porting05/Makefile porting06/Makefile
--- porting05/Makefile	Sun Apr 12 12:09:59 2009
+++ porting06/Makefile	Sun Apr 19 21:53:32 2009
@@ -6,6 +6,7 @@
 OBJS += extintr.o
 OBJS += kozos.o command.o
 OBJS += stublib.o ppc-stub.o
+OBJS += mcount.o logging.o
 
 LIB = libc.a
 TARGET ?= sample
@@ -26,6 +27,9 @@
 
 $(TARGET) :	$(OBJS) $(LIB)
 		$(CC) $(OBJS) -o $(TARGET) $(CFLAGS) $(LFLAGS)
+
+extintr.o :	extintr.c
+		$(CC) -c $< $(CFLAGS) -pg
 
 .c.o :		$<
 #		$(CC) -S $< $(CFLAGS)

ためしに実行してみよう.まずビルドしてファームをボードにダウンロードする. で,プロンプトでおもむろに log コマンドを実行してみる.

> echo aaa
 aaa
OK
> log
000430e4 00043268 00043508 000430e4 0004314c 000430e4 00043268 00043508
000430e4 0004314c 000430e4 00043268 00043508 000430e4 0004314c 000430e4
00043268 00043508 000430e4 0004314c 000430e4 00043268 00043508 000430e4
0004314c 000430e4 00043268 00043508 000430e4 0004314c 000430e4 00043268
00043508 000430e4 0004314c 000430e4 00043268 00043508 000430e4 0004314c
000430e4 00043268 00043268 00043268 00043508 000430e4 0004314c 000430e4
00043268 00043508 000430e4 0004314c 000430e4 00043268 00043508 000430e4
0004314c 000430e4 00043268 00043508 000430e4 0004314c 000430e4 00043268
OK
> 
これは extintr.c 内の関数が呼び出されたシーケンスになる. なんかそれっぽく表示されている.どうも 0x00043xxx 付近に集中しているようだ.

まあシーケンスとはいっても16進のアドレスだけではわからんので,実際に関数の アドレスを確認してみよう.関数がどのアドレスにマッピングされているかは, readelf で確認できる.

% readelf -a sample | grep FUNC | sort -k 2
で,0x00043xxx 付近を取り出したら以下のようになった.
    90: 00043000   104 FUNC    LOCAL  DEFAULT    1 cons_mask
    91: 00043068   104 FUNC    LOCAL  DEFAULT    1 cons_unmask
    92: 000430d0   104 FUNC    LOCAL  DEFAULT    1 cons_checkintr
    93: 00043138   284 FUNC    LOCAL  DEFAULT    1 cons_intr
    94: 00043254   348 FUNC    LOCAL  DEFAULT    1 cons_command
    95: 000433b0   212 FUNC    LOCAL  DEFAULT    1 cons_init
    96: 00043484   112 FUNC    LOCAL  DEFAULT    1 extintr_intr_regist
    87: 000434f4   208 FUNC    LOCAL  DEFAULT    1 extintr_handler
    97: 000435c4   240 FUNC    LOCAL  DEFAULT    1 extintr_mainloop
   305: 000436b4   148 FUNC    GLOBAL DEFAULT    1 extintr_main
どれも extintr.c の関数なので,どうやらそれっぽく動いているようだ. ログの先頭の8個のアドレスのみ,実際の関数に置き換えてみた.
000430e4 → cons_checkintr()
00043268 → cons_command()
00043508 → extintr_handler()
000430e4 → cons_checkintr()
0004314c → cons_intr()
000430e4 → cons_checkintr()
00043268 → cons_command()
00043508 → extintr_handler()
割り込みが発生して extintr_handler() が呼ばれ,その先で checkintr() と intr() によって実際に割り込み処理が行われているように見える. あと command スレッドからのコマンドを受け付けて cons_command() がときどき 呼ばれているようだ.うーん,まあまともに動いているように思える.

これのいいところは,-pgつけるだけで簡単にプログラム全体に処理を入れられる ことだ.ディレクトリ単位でログを入れたいときも,Makefileの修正で簡単に対応 できる.

あと,_mcount()の処理は所詮関数呼び出しなので,スレッドの動作順番などが 変わるようなことはない.つまり -pg を追加したことで,(処理は多少重くなる だろうが)動作シーケンスが変わってしまうなことはない(はずだ). これはデバッグのときには非常に重要なことた.というのは,実際の現場では, デバッグのためにログ保存を入れたらスレッドの動作順序が変わってしまって バグが発生しなくなってしまう,ということが起こり得る(で,ログ保存を外すと やっぱりバグは起きる).こーいうことを防止するためにも,ログ保存はスレッド動作に 影響を与えないことがのぞましい(関数呼び出しなどで多少処理が重くなるのは しかたがないが).たとえばログ出力用やコンソール出力用に専用のスレッドが あるような場合は要注意だ.ログ出力を行うことでログ出力スレッドが動作して しまい,スレッドのスケジューリング順序が変わってしまうことで, タイミング的なバグなどは発生しなくなったり現象が変わってしまったりすることが 考えられるからだ.

まあただすべての関数に処理が入ってしまうので,mcount()の先でうかつな処理を すると,動作がすげー重くなってしまう可能性はある.

今回はログ保存を実装したけど,他にもアイディア次第で これってけっこういいアイディアだと思うのだけどどうでしょう.


メールは kozos(アットマーク)kozos.jp まで