ns3でロギング

【　ns-3.30の使い方 → 1 → 2 → 3 → 4 → 5 → 6 → 7　】

ネットワークシミュレータであるns3の説明をいくつかにわけて投稿しています．この投稿は「5. ロギング」です．

5. ロギング

ns3では，シミュレーションによって発生するログ（標準出力）をinfoやerrorなどのレベルに分け，特定のレベル以上を出力したり，特定のコンポネントに関するログのみを出力したりすることができます．直感的な仕組みなため，さくっと説明します．

• デバッグオプション
• ログの種類
• ログの有効化
• ログの記述
• 時間と一緒にログを出力
• まとめ

文献

• https://www.nsnam.org/docs/release/3.30/tutorial/html/tweaking.html
• https://www.nsnam.org/docs/release/3.30/manual/html/logging.html
• https://gitlab.com/nsnam/ns-3-dev/blob/ns-3.30/src/core/examples/sample-log-time-format.cc

デバッグオプション

ロギングはns3のデバッグオプションがdebugのときのみ有効です．releaseやoptimizedになっている場合は利用できません．

$ ./waf --check-profile
Waf: Entering directory `/home/ns3/workspace/ns-3-allinone/ns-3.30/build'
Build profile: debug

ログの種類

ns3のログにはERRORからLOGICまで6段階のレベルが存在します．デフォルトはLOG_NONEで，ログは何も出力されません．

6種類の使い分けですが，厳密な定義はないため，使用者の裁量に任せられています．DEBUG, INFO, LOGICなんかの使い分けは微妙なところです．

ログの有効化

ログの有効化方法には2種類あります．

• シナリオファイル内でLogComponentEnable ()
• 環境変数NS_LOGにログレベルを指定

LogComponentEnable

LogComponentEnable()の方法はfirst.ccなどでも登場しました．

first.cc

  LogComponentEnable ("UdpEchoClientApplication", LOG_LEVEL_INFO);

ここで，ログコンポネントUdpEchoClientApplicationのLOG_INFO以上の4レベルを有効化しています．ログコンポネント名は，API DocumentationのAll LogComponentsに全て列挙されていますが，基本的にそのモデルと同じ名前です．モデル名はわからないが，読んでいるソースコードのログを有効化したくなった時は，インクルード文の下にログコンポネント名がNS_LOG_COMPONENT_DEFINE()によって定義されています．

環境変数NS_LOG

シェル変数からもログを有効化できます．上の例の場合，以下と同じです．

$ NS_LOG=UdpEchoClientApplication=level_info ./waf --run first

この実行はその場限りの変更なため，永続化したい場合はexportコマンドで環境変数に入れます．

$ export NS_LOG=UdpEchoClientApplication=level_info
$ echo $NS_LOG
UdpEchoClientApplication=level_info
$ ./waf --run first

この例では，first.cc内のLogComponentEnableと同じことを繰り返しているだけなので出力は変わりません．例えばLOG_LEVEL_FUNCTIONとすると，実行された関数に関する出力が増えます．

$ NS_LOG=UdpEchoClientApplication=level_function ./waf --run first
UdpEchoClientApplication:UdpEchoClient(0x55e41fc051b0)
UdpEchoClientApplication:SetDataSize(0x55e41fc051b0, 1024)
UdpEchoClientApplication:StartApplication(0x55e41fc051b0)
UdpEchoClientApplication:ScheduleTransmit(0x55e41fc051b0, +0.0ns)
UdpEchoClientApplication:Send(0x55e41fc051b0)
At time 2s client sent 1024 bytes to 10.1.1.2 port 9
At time 2.00369s server received 1024 bytes from 10.1.1.1 port 49153
At time 2.00369s server sent 1024 bytes to 10.1.1.1 port 49153
UdpEchoClientApplication:HandleRead(0x55e41fc051b0, 0x55e41fc12520)
At time 2.00737s client received 1024 bytes from 10.1.1.2 port 9
UdpEchoClientApplication:StopApplication(0x55e41fc051b0)
UdpEchoClientApplication:DoDispose(0x55e41fc051b0)
UdpEchoClientApplication:~UdpEchoClient(0x55e41fc051b0)

使わなくなった環境変数NS_LOGはunsetコマンドで削除してください．エラーの原因になります．

$ unset NS_LOG

ログの記述

first.ccを実行した時のAt time 2s client sentで始まるログはudp-echo-client.ccの以下の行によってなされたものです．

udp-echo-client.cc

       NS_LOG_INFO ("At time " << Simulator::Now ().GetSeconds () << "s client sent " << m_size << " bytes to " <<
                    Ipv4Address::ConvertFrom (m_peerAddress) << " port " << m_peerPort);

お察しの通り，NS_LOG_INFOというマクロに文字列を与えると，ログレベルがLOG_INFOのときにその文字列が出力されます．同様に，NS_LOG_ERRORやNS_LOG_WARNといったマクロがあり，ログの記述にはこれらを使います．レベルによらず（LOG_NONEでも）常に出力するNS_LOG_UNCONDというマクロもあります．

時間と一緒にログを出力

src/core/examples/sample-log-time-format.ccが参考になります．

sample-log-time-format.cc

  LogComponentEnable ("RandomVariableStream", LOG_LEVEL_ALL);
  LogComponentEnableAll (LOG_PREFIX_TIME);

LogComponentEnableAll (LOG_PREFIX_TIME);によってログのプレフィックスとして時間情報がつきます．実行結果は以下です．

$ ./waf --run sample-log-time-format
RandomVariableStream:RandomVariableStream(0x558deb34a290)
RandomVariableStream:UniformRandomVariable(0x558deb34a290)
RandomVariableStream:SetStream(0x558deb34a290, -1)
RandomVariableStream:SetAntithetic(0x558deb34a290, 0)
+0.000000001s RandomVariableStream:SetAntithetic(0x558deb34a290, 0)
+0.000000123s RandomVariableStream:SetAntithetic(0x558deb34a290, 0)
+0.000123456s RandomVariableStream:SetAntithetic(0x558deb34a290, 0)
+0.123456789s RandomVariableStream:SetAntithetic(0x558deb34a290, 0)
RandomVariableStream:~RandomVariableStream(0x558deb34a290)

シナリオがSimulator::Run()されている間のログに時間が付加されました．ここでの時間とはシミュレーションを走らせてからの実行時間なため，シミュレーション実行前のログには時間がつきません．

LOG_PREFIX_TIME以外にもプレフィックはあります．

• LOG_PREFIX_FUNC
• LOG_PREFIX_NODE
• LOG_PREFIX_LEVEL
• LOG_PREFIX_ALL

詳細はドキュメントを参照してください．

まとめ

ロギングを使うことで，コードを毎回書き換えずに情報を出力させたりさせなかったりできます．std::coutデバックはもうやめて，NS_LOG_DEBUG()に切り替えましょう．

シミュレーションをしたらデータを取る必要があります．例えば，動くモバイルノードの座標情報を逐一ファイルに出力するにはどうすればいいでしょうか．次の記事ではns3のトレーシングシステムを扱います．