From nakai.norihisa ＠ yes.nttcom.ne.jp  Thu Nov 15 19:25:54 2007
From: nakai.norihisa ＠ yes.nttcom.ne.jp (nakai norihisa)
Date: Thu, 15 Nov 2007 19:25:54 +0900
Subject: [Ultramonkey-l7-develop 75]
	=?iso-2022-jp?b?bG9nGyRCOWJFWTI9JEskKiQxJGtLZCRhOX4kXztYP0sbKEI=?=
Message-ID: <473C1EB2.8090604@yes.nttcom.ne.jp>

TO:皆様

中居です。
お疲れ様です。

さて、logの高度化における埋め込み指針を考慮する必要があると感じております。
#ばらばらでlogの埋め込みを行ってはまずいと思います。
たたき台をディスカッションしていただければ幸いかと思います。

現在logのカテゴリとレベルはenum宣言を予定していて
enum log_level_tag {
	LOG_LV_FATAL,
	LOG_LV_ERROR,
	LOG_LV_WARN,
	LOG_LV_INFO,
	LOG_LV_DEBUG
};
のように定義し、
log_level_tag	get_log_level();
で、現状のログレベルが取得できるようする予定です。

そこでログ出力関数は
void	logput_FATAL( ... );
void	logput_ERROR( ... );
void	logput_WARN( ... );
void	logput_INFO( ... );
void	logput_DEBUG( ... );
見たいに用意しようと思っております。

上記の前提があった上で下記の関数を例題にして見ます。

例:0が入ってきた場合にエラーで-1を返し、それ以外は0を返す関数。

int	foo( int i ){
	if( 0 == i ) return -1;
	return 0;
}

まず一番に考えられるのは、エラーの場合のlog出力です。

int	foo( int i ){
	if( 0 == i ){
		logput_ERROR( "function foo( int i ): parameter i is zero" );
		return -1;
	}
	return 0;
}

WARNやINFO及びFATALはこの関数では必要ないと思いますので、
エラーのログ出力に関しては上記のように今までどおりのlog出力関数のように
振舞ってよいと思います。

で、問題はdebugログです。
debug状態は速度低下は仕方が無いと思いますが、通常状態でのlog関数による
速度低下は最小限に抑えたいところです。
ですが、デバッグ状態ではなるべく多くの情報を出力したいと思います。
これはlog4cxxなどの説明では
「log levelを判断し、不要なコードを極力押さえる」
と、あります。

これを適用すると

int	foo( int i ){
	if( get_log_level() == DEBUG )	logput_DEBUG( "function foo( int i ) in , parameter i is %d", i );
	
	if( 0 == i ){
		logput_ERROR( "function foo( int i ): parameter i is zero" );
		if( get_log_level() == DEBUG )　logput_DEBUG( "function foo( int i ): error return(-1)" );
		return -1;
	}

	if( get_log_level() == DEBUG )	logput_DEBUG( "function foo( int i ): normally return(0)" );
}

こんな感じになりますかね。
この条件を箇条書きにしますと、

1)関数に入ったときにはレベルを確認し、DEBUGレベルならば「関数に入ったこと」と「引数のダンプ」を出力
2)致命的エラーの場合には問答無用でエラーとして出力
3)DEBUGログを関数内で埋め込む場合にはLOGLEVELの確認を行った後、出力する。
4)関数を抜ける場合には、返り値を含めた「関数から抜けた」デバッグログの出力

と、なるかと思います。
このポイントは、log_levelを判断してから出力関数を呼ぶということで、
文字列を作成するような関数では文字列操作のコストを莫大に下げることができます。
#たとえば引数にstruct l7vs_service*が入ってきた場合などは大変なコストになるかと...
また、get_log_level()をインライン展開するようにすると(コンパイラの最適化しだいでは)
1stキャッシュに乗りっぱなしになるかと思います。


上記のようなlog埋め込み指針に関してコメント等をどうぞよろしくお願いいたします。



From takebayashi.shinya ＠ nttcom.co.jp  Thu Nov 15 21:19:15 2007
From: takebayashi.shinya ＠ nttcom.co.jp (Shinya TAKEBAYASHI)
Date: Thu, 15 Nov 2007 21:19:15 +0900
Subject: [Ultramonkey-l7-develop 76] Re:
 =?iso-2022-jp?b?bG9nGyRCOWJFWTI9JEskKiQxJGtLZCRhOX4kXztYGyhC?=
 =?iso-2022-jp?b?GyRCP0sbKEI=?=
In-Reply-To: <473C1EB2.8090604@yes.nttcom.ne.jp>
References: <473C1EB2.8090604@yes.nttcom.ne.jp>
Message-ID: <20071115211915.35c1c5de.takebayashi.shinya@nttcom.co.jp>

中居 様


  竹林です．
  お疲れ様です．

  
> 1)関数に入ったときにはレベルを確認し、DEBUGレベルならば「関数に入ったこと」と「引数のダンプ」を出力
> 2)致命的エラーの場合には問答無用でエラーとして出力
> 3)DEBUGログを関数内で埋め込む場合にはLOGLEVELの確認を行った後、出力する。
> 4)関数を抜ける場合には、返り値を含めた「関数から抜けた」デバッグログの出力
> 
> と、なるかと思います。
> このポイントは、log_levelを判断してから出力関数を呼ぶということで、
> 文字列を作成するような関数では文字列操作のコストを莫大に下げることができます。
> #たとえば引数にstruct l7vs_service*が入ってきた場合などは大変なコストになるかと...
> また、get_log_level()をインライン展開するようにすると(コンパイラの最適化しだいでは)
> 1stキャッシュに乗りっぱなしになるかと思います。

  DEBUG モードでログを吐く場合，中居さんのおっしゃるとおり入出力する
データをダンプするような処理になるため文字列整形が必須になり，
そのコストは馬鹿になりません．
  そのため，DEBUG モード以外の場合は文字列整形すらしない，という考えに
ついてはまさにその通りだと思います．

  ですが，ログレベルを取得する関数を毎回呼ぶとなると，これも相当なコストが
かかると思います．
  確かにインライン化すればそのコストは抑えられますが，バイナリのサイズが
非常に大きくなることが予想されます．


  ログに関する設定を l7vsd が知っているのであれば，グローバル変数あたりで
DEBUG モードかを判定するフラグを持っておき，単純に if でフラグを
判定する方が効率がいいと思います．
  引数を push して call して戻りを cmp するよりは，
数値を mov して cmp した方が，コストは遙かに小さく済みますよね．


  もう少し，この辺りについては検討を重ねる必要がありそうです．

-----------------------------------------------------------
NTT Comware Corporation
Shinya TAKEBAYASHI

E-mail: takebayashi.shinya ＠ nttcom.co.jp
GPG ID: 70298B55
GPG FP: 98C3 25CF 8201 4881 9328 5C91 CBFA DCFC 7029 8B55
-----------------------------------------------------------