Boost.Asio 非同期ハンドラのデバッグ支援

Boost 1.47.0から、Boost.AsioにBOOST_ASIO_ENABLE_HANDLER_TRACKINGという、非同期ハンドラのデバッグ支援用マクロが提供されるようになりました。これをdefineしておくと、非同期ハンドラの呼び出しを標準出力に出力してくれるようになります。


たとえば、「Boost.Asio ゲームループで非同期操作を行う」のクライアントプログラムの先頭に

#define BOOST_ASIO_ENABLE_HANDLER_TRACKING

を書いて実行すると、以下のように出力されます:

@asio|1310697299.008735|0*1|socket@0012FE5C.async_send
@asio|1310697299.008735|0*2|socket@0012FE5C.async_receive
@asio|1310697299.008735|>1|ec=system:0,bytes_transferred=8
request : request

@asio|1310697299.008735|<1|
@asio|1310697299.039985|>2|ec=system:0,bytes_transferred=9
response : response

@asio|1310697299.039985|<2|
@asio|1310697300.039985|0*3|socket@0012FE5C.async_send
@asio|1310697300.039985|0*4|socket@0012FE5C.async_receive
@asio|1310697300.039985|>3|ec=system:0,bytes_transferred=8
request : request

@asio|1310697300.039985|<3|
@asio|1310697300.039985|>4|ec=system:0,bytes_transferred=9
response : response

@asio|1310697300.039985|<4|
@asio|1310697301.039985|0*5|socket@0012FE5C.async_send
@asio|1310697301.039985|0*6|socket@0012FE5C.async_receive
@asio|1310697301.039985|>5|ec=system:0,bytes_transferred=8
request : request
...

出力構文の規則は以下:

<tag>|<timestamp>|<action>|<description>

<tag>は常に@asioになります。この行はトラッキングメッセージですよ、という目印です。
<timestamp>はUNIX時間です。1970年1月1日からの経過時間の、秒とミリ秒が出力されます。

<action>の規則は以下:

>n : プログラムは番号nのハンドラを開始した
<n : プログラムは番号nのハンドラを終了した
!n : プログラムは番号nのハンドラを例外によって終了した
~n : 番号nのハンドラが、呼び出されることなく破棄された。これは、io_serviceが破棄されるときの、終了していない非同期操作のために有用である。
n*m : ハンドラ番号nは新しい非同期処理を完了ハンドラ番号mで作成した
n : 番号nのハンドラがその他の操作を行った。<decription>は、どの関数が呼び出されたかを示している。現在は、保留中の非同期操作の状態に影響を与える可能性があるclose()とcancel()のみをロギングする。

<description>は、どの同期 or 非同期操作が実行されたかを出力します。形式は「@.」です。ハンドラの引数はカンマ区切りのリストとして出力されます。


参照:
Handler Tracking

Using Boost.Asio(BOOST_ASIO_ENABLE_BUFFER_DEBUGGING)の解説


修正履歴:
2012/11/16 : の誤訳を修正。指摘内容はコメント欄を参照。