象と戯れ

 | 

2009-07-29

DIY trace

01:09 | DIY trace - 象と戯れ を含むブックマーク はてなブックマーク - DIY trace - 象と戯れ

ほんの一息の隙をついてPostgreSQL Hack.

集約関数をウィンドウ関数で呼び出した時に思ったより遅い、という指摘があり、元々nodeWindowAggのプロファイルを取りたいなと思っていたので、いくつかテストをしました。

oprofileやgprofなどの既存のツールを試したのですが、どれもいまいち。いまいちというのは、PostgreSQLがサーバデーモンでforkしたりする上に自分が見たい箇所がプロセスの処理全体にくらべて非常にミクロだったため、全ての関数の処理時間や呼出し回数に対する割合などを出されても全く役に立たなかった、ということです。ちょっとしたプログラムのベンチマークにはいいのでしょうが、相手が複雑すぎました。

というわけで、自前でプロファイル用共有ライブラリをでっちあげ。

  • 特定の関数の呼出し回数、及びその関数内での総実行時間を調べる
  • その関数の中で呼び出している関数にも同様のことを調べる
  • ソースコードには手を入れない(コンパイルオプションは変える)

というような代物です。同関数がネストしたりすると破綻するのですが、とりあえず今はこれでOK.

仕組みとしては、GCC拡張の-finstrument-functionsオプションを使って対象となるモジュール(今回の場合はsrc/backend/executor及びsrc/backend/utils/sort)をコンパイル。__cyg_profile_func_enter()/__cyg_profile_func_exit()を実装した共有ライブラリを作成し、LD_PRELOAD環境変数で指定、ターゲットとなる関数の呼出しとその関数から呼ばれた関数をフックして実行時間と呼出し回数を保存します。全てCで書くので関数毎に回数や時間を保存しておくためのデータ構造を用意する必要がありメンドクサイと思いましたが、tokyocabinetのTCMAPがかなり便利なのでまるでLLを書くようにデータ構造の問題はクリア。

あとのハマリどころは__cyg_profile系の第二引数が呼出し元関数のアドレスではなくリターンアドレスだったということ。何気に呼出し元関数のアドレスを取得するのは厄介のようでWebを漁っても出てきません。GDBとにらめっこすること数時間、ようやくたどり着いた結論は、

  • __builtin_return_address(2)で呼出し元関数のリターンアドレスを取得。
  • このアドレスはさらに一つ上位のcall funcの次のプログラムアドレスを指している
  • よってアドレスから4引くことでcallのオペランドを取得
  • call命令が"e8(=相対アドレス指定)"なら上記リターンアドレスにcallオペランドを足して関数アドレスを取得

という泥臭い話になっています(しかもx86GCC限定。)が、コードとしては至って単純。

static void *
get_calladdr(void *ret_addr)
{
	void *caller_address = NULL;

	if(*((unsigned char *) ret_addr - 5) == 0xe8)
	{
		caller_address = (void *) ((char *) ret_addr + (int) (*(int *) ((char *) ret_addr - 4)));
	}

	return caller_address;
}

これを、

void __cyg_profile_func_enter( void *this, void *callsite )
{
	void *caller_address = get_calladdr(__builtin_return_address(2));
...
}

というように呼び出します。あとは適当にgettimeofday()で時間を計測したりbfd_asymbol_name()でアドレスから関数名を取得したりして一丁あがり。gettimeofday()を呼出し過ぎてこの処理時間が支配的になってしまったのでgettimeofday()一回当たりの処理時間×実行回数をトータルから引いたりして微調整。

結果。

$ bin/psql regression -c 'explain analyze select count(*) over(order by a) from x'
                                                          QUERY PLAN            
                                               
--------------------------------------------------------------------------------
-----------------------------------------------
 WindowAgg  (cost=0.00..4378.26 rows=100000 width=4) (actual time=712.050..7419.
178 rows=100000 loops=1)
   ->  Index Scan using x_pkey on x  (cost=0.00..2878.26 rows=100000 width=4) (a
ctual time=0.391..390.013 rows=100000 loops=1)
 Total runtime: 7694.722 ms
(3 rows)

eval_windowaggregates:

Count 100000

Elapse 1.093243

AddressNameCountElapse(Total)
0x8204067initialize_windowaggregate10.000448
0x8204d4aspool_tuples2000010.749114
0x83dcd08tuplestore_select_read_pointer1000010.023247
0x83dda2ftuplestore_gettupleslot1000010.058987
0x8204fddrow_is_in_frame1999990.082544
0x8204168advance_windowaggregate1000000.036538
0x81ead8aExecClearTuple1000000.025007
0x8204462finalize_windowaggregate1000000.044233
0x8204120MemoryContextSwitchTo2000000.035016


$ bin/psql regression -c 'explain analyze select count(*) over() from x'
                                                   QUERY PLAN                   
                                
--------------------------------------------------------------------------------
--------------------------------
 WindowAgg  (cost=0.00..2741.00 rows=100000 width=0) (actual time=3725.294..4559
.828 rows=100000 loops=1)
   ->  Seq Scan on x  (cost=0.00..1491.00 rows=100000 width=0) (actual time=0.11
2..310.349 rows=100000 loops=1)
 Total runtime: 4811.115 ms
(3 rows)

eval_windowaggregates:

Count 100000

Elapse 0.588426

AddressNameCountElapse(Total)
0x8204067initialize_windowaggregate10.000277
0x8204d4aspool_tuples1000020.620092
0x83dcd08tuplestore_select_read_pointer1000010.011080
0x83dda2ftuplestore_gettupleslot1000010.049005
0x8204fddrow_is_in_frame1000000.014978
0x8204168advance_windowaggregate1000000.025675
0x81ead8aExecClearTuple1000000.022105
0x8204462finalize_windowaggregate10.000015
0x8204120MemoryContextSwitchTo20.000000

予想通りspool_tuples()が支配的ですが、どのぐらい支配的なのかという肌感がつかめそうです。ORDER BY付ではMemoryContextSwitchToの呼出しが200000回あってびっくりしたり。

どう考えてもcount(*)でtuplestoreに行を丸ごとコピーしていくのはアホらしいので、最適化するならばspoolを回避するなどの方法が考えられますね。しかし最近のnodeAgg.cの修正でTome Laneが「nodeAggは既に十分複雑すぎる。。。」というようなことも言っていて、nodeWindowAggはこれからFRAME句の追加とかしなきゃなんないのにこれ以上の最適化のための場合分けとかやってる場合なんだろうか・・・

というわけで、暫くはいろんなプロファイルを取ってみることにします。それにしても、こういうツールを自分で作ってみるとgcc拡張やらbfdやらアセンブラやらgdbやら使うことになるので色々と勉強になりますね。

 |