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

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

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

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

• コンパイル時に -pg をo付けてコンパイルする．
• 実行形式を実行すると，どの関数が何回呼ばれたとか，どの関数がどれくらい 時間をくっているかといったデータがとれる．

-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

        .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)

つぎに -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

        .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)

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

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

実際に埋め込まれた _mcount() 呼び出し処理をよくみてみよう． LRの値をGPR1 ＋ ４の位置に保存してから _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

問題はレジスタの退避なのだけど，厳密にいえば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;
  }
}

で，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;

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
> 

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

% readelf -a sample | grep FUNC | sort -k 2

    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

000430e4 → cons_checkintr()
00043268 → cons_command()
00043508 → extintr_handler()
000430e4 → cons_checkintr()
0004314c → cons_intr()
000430e4 → cons_checkintr()
00043268 → cons_command()
00043508 → extintr_handler()

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

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

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

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

• 戻る
• トップページに戻る