(注意)このブログは本家のほうの文章部分のみの転載です．ソースコードの配布，画像などについては本家のほうを参照してください．文章中のリンク先は面倒なのですべて本家のほうに変換してしまっているのでご注意ください．
最近，プロファイラについてちょっとしたアイディアが出たので，今回はプロファイラの機能を使ってデバッグ用のログ出力の埋め込みというのをやってみよう．
まずはプロファイラの説明だけど，プロファイラって積極的に使っているひとはなにげにあまりいなかったりするものだけど，gccの場合だと簡単にいうとこんなことができる．
-pgつけてコンパイルすると実際には何が行われるかというと，関数の先頭に必ず特定の関数呼び出しを行うようなコードが付加される．実際にプロファイラを動かしたときには，すべての関数の先頭で特定の処理(統計を記録するような)が行われるわけだ．実際にどんな処理が行われるかはちょっとよくわかっていないのでここでは説明を省くが，今回利用するのはこの「関数の先頭に，特定の関数を呼び出すようなコードを付加する」という機能だ．
ためしに -pg をつけてコンパイルしてみよう．
まず，ふつうにコンパイルした場合を見てみる．-S をつけてコンパイルすることで，アセンブラコードとして main.s が作成される．
これで作成された main.s の中身を見てみる．
これは main() 関数の先頭部分なのだけど，関数の先頭ではまず mflr でGPR0 にLRの値を保存している．で，stwu で GPR1 の値を減算することでスタックを確保して，スタックに(GPR0にコピーした)LRの値を保存している．
つぎに -pg をつけて同じようにコンパイルしてみよう．
お尻に -pg がついていることに注目．で，同じように作成された main.s を見てみる．
上は同じ main() 関数の先頭部分なのだけど，stwu によるスタック確保の前に，いくつかの命令が追加されている．
まずはスタック確保の直前で _mcount という関数が呼ばれていることに注目してほしい．これが，プロファイリングを行うための関数呼び出しだ．
で，この _mcount() を自前で用意してやることで，すべての関数呼び出し時に特定の処理を入れることができる．たとえば関数呼び出しのログを保存するとかだ．これはデバッグに非常に役に立つのではなかろうか．
実際に埋め込まれた _mcount() 呼び出し処理をよくみてみよう．LRの値をGPR1 ＋ ４の位置に保存してから _mcount() を呼んでいる．_mcount() から戻った後は，即座にLRの値をスタックに保存しているから，LRの値はきちんと設定した上で _mcount() から戻ってこないといけないようだ．
なので，_mcount() はこんなふうに書けばいいんではなかろうか．
_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() は特定メモリ領域に関数のアドレスを保存するように，以下のような感じで書いてみた．
これで，_mcount() の呼び出しもとのアドレスが logging_buf[] に保存される．_mcount() を呼び出すのは，-pg によって先頭で _mcount() を呼び出すようにコード付加された関数なので，-pg つけてコンパイルしたソースコードの関数が実行されると，ログが logging_buf[] に保存されるということになる．
で，command.c にコマンド追加した．「log」コマンドを実行すると，現在保存されているログが表示される．
Makefile は特定のファイルのみ -pg 付きでコンパイルされるように修正．とりあえず今回は extintr.c を対象にしてみた．
ためしに実行してみよう．まずビルドしてファームをボードにダウンロードする．で，プロンプトでおもむろに log コマンドを実行してみる．
これは extintr.c 内の関数が呼び出されたシーケンスになる．なんかそれっぽく表示されている．どうも 0x00043xxx 付近に集中しているようだ．
まあシーケンスとはいっても16進のアドレスだけではわからんので，実際に関数のアドレスを確認してみよう．関数がどのアドレスにマッピングされているかは，readelf で確認できる．
で，0x00043xxx 付近を取り出したら以下のようになった．
どれも extintr.c の関数なので，どうやらそれっぽく動いているようだ．ログの先頭の８個のアドレスのみ，実際の関数に置き換えてみた．
割り込みが発生して extintr_handler() が呼ばれ，その先で checkintr() とintr() によって実際に割り込み処理が行われているように見える．あと command スレッドからのコマンドを受け付けて cons_command() がときどき呼ばれているようだ．うーん，まあまともに動いているように思える．
これのいいところは，-pgつけるだけで簡単にプログラム全体に処理を入れられることだ．ディレクトリ単位でログを入れたいときも，Makefileの修正で簡単に対応できる．
あと，_mcount()の処理は所詮関数呼び出しなので，スレッドの動作順番などが変わるようなことはない．つまり -pg を追加したことで，(処理は多少重くなるだろうが)動作シーケンスが変わってしまうなことはない(はずだ)．これはデバッグのときには非常に重要なことた．というのは，実際の現場では，デバッグのためにログ保存を入れたらスレッドの動作順序が変わってしまってバグが発生しなくなってしまう，ということが起こり得る(で，ログ保存を外すとやっぱりバグは起きる)．こーいうことを防止するためにも，ログ保存はスレッド動作に影響を与えないことがのぞましい(関数呼び出しなどで多少処理が重くなるのはしかたがないが)．たとえばログ出力用やコンソール出力用に専用のスレッドがあるような場合は要注意だ．ログ出力を行うことでログ出力スレッドが動作してしまい，スレッドのスケジューリング順序が変わってしまうことで，タイミング的なバグなどは発生しなくなったり現象が変わってしまったりすることが考えられるからだ．
まあただすべての関数に処理が入ってしまうので，mcount()の先でうかつな処理をすると，動作がすげー重くなってしまう可能性はある．
今回はログ保存を実装したけど，他にもアイディア次第でこれってけっこういいアイディアだと思うのだけどどうでしょう．
最近，プロファイラについてちょっとしたアイディアが出たので，今回はプロファイラの機能を使ってデバッグ用のログ出力の埋め込みというのをやってみよう．
まずはプロファイラの説明だけど，プロファイラって積極的に使っているひとはなにげにあまりいなかったりするものだけど，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
これで作成された 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 ＋ ４の位置に保存してから _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 の関数なので，どうやらそれっぽく動いているようだ．ログの先頭の８個のアドレスのみ，実際の関数に置き換えてみた．
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()の先でうかつな処理をすると，動作がすげー重くなってしまう可能性はある．
今回はログ保存を実装したけど，他にもアイディア次第でこれってけっこういいアイディアだと思うのだけどどうでしょう．