第10回~今回はDPDKアプリケーションのログを出力する方法について解説します。2019年11月19日公開はじめにこんにちは、NTTテクノクロス株式会社の寺尾です。今回はアプリケーションのデバッグなどで利用するログ出力の機能を解説します。DPDKのログ機能についてアプリケーションのデバック方法として、プログラムの「ログ」から処理内容を確認する方法をよく使います。「ログ」とはプログラムの活動記録のようなもので、開発者では解析する情報として重要なものとして取り扱われています。DPDKではログ出力の便利なAPIが用意されていますので、そのAPIを説明します。紹介したDPDKアプリケーションに対して、ログを出力する機能を便利に使えるような処理を追加します。DPDKのログ出力のAPIでは、ログのカテゴリ(ログの出力元情報)や優先度の条件を設定し、その条件によってログの出力要否を選ぶことができます。このログのカテゴリを「ログ種別」、優先度を「ログレベル」として今後説明していきます。ログの出力を行うAPIはrte_log()で例えば以下のようにして使います。この例では、ログのカテゴリとして「app_main」を1つ定義し、ログの優先度を「DEBUG」として定義しました。このように定義をすることで、例えばapp_mainのカテゴリは普段の運用では出力したくないなどの設定ができるようになります。上記のようにrte_log()の関数を使えばログを出力することができますが、今回はこの方法よりも手軽にログを出力できるマクロがDPDKで用意されていますので、その方法を紹介します。DPDKではRTE_LOG()とRTE_LOG_DP()の2つのマクロが用意されており、以下のように使い分けます。ログを出力する基本のマクロ。ログの出力要否をDPDKライブラリのconfigファイルで指定することができる特殊なマクロ。ログに出力しない場合は、ログの出力処理自体のステップをコンパイルしないようにして、性能を損なわないよう考慮することができる。DPDKではログを出力すること自体が重い処理になるので、性能を意識する場合は配慮が必要。rte_log()関数を直接使ってもログ出力は可能ですが、上記のように性能を意識することは手間がかかりますので、RTE_LOG()やRTE_LOG_DP()のマクロを最初から利用していくと良いかと思います。ログ機能の利用する時のシーケンスイメージは以下となります。ログ初期化まずログ種別の定義をrte_log_register()の関数で設定します。今回は初期化処理に"app_main"、パケット処理に"app_fwd"というログ種別を使います。rte_log_register()でログ種別を設定すると返り値でログ種別のIDが払い出されるので、このIDをログ機能の各種APIで利用していくことになります。今回紹介するログ出力のマクロRTE_LOG()では、ログ種別のIDを"RTE_LOGTYPE_"というプレフィックスでのマクロ名称で使用することが条件になりますので、その条件に従った命名で定義を行います。プレフィックス以外の命名規則は特にありませんが、分かりやすいように"app_main"で設定したログ種別のIDは"RTE_LOGTYPE_APP_MAIN"と命名すると良いかと思います。ログ種別の命名にこだわりが無ければ、DPDKでデフォルトで用意されているRTE_LOGTYPE_USER1~RTE_LOGTYPE_USER8というログ種別のIDが用意されているので、こちらを使っても構いません。その場合はrte_log_register()の処理や特殊なプレフィックスを使ったマクロ定義が不要です。rte_log_register("app_forward")次にログレベルを設定します。ログ出力処理には必ずログレベルを指定しますが、実際に出力するかどうかはシステムのログ出力の優先度と比較し、その優先度より高ければログ出力するようになります。ログ出力処理でログレベルを「INFO」と設定した場合、システムのログ出力の優先度が「INFO」よりも高いレベルで設定されていた場合はログが出力されません。DPDKで指定可能なログレベルを以下に示します。デバック用の情報であることを示すログログ出力の優先度は全体に1つ設定すれば良いですが、必要に応じて「ログ種別」毎に設定することもできます。DPDKでは全体に設定するログ出力の優先度を「グローバル」の「ログレベル」と表現しています。「グローバル」の設定と「ログ種別」毎の優先度の判定は以下のイメージとなります。「ログ種別」毎の設定が特にない場合は判定自体スキップされます。グローバルのログレベルの設定にはrte_log_set_global_level()、ログ種別ごとのログレベル設定にはrte_log_set_level()を使います。今回は、グローバルのログレベルを「RTE_LOG_INFO」に、ログ種別(app_main)のログレベルを「RTE_LOG_ERROR」に設定しました。することで、app_mainのログはERRORレベル未満のものは出力を抑止できるとともに、他のログ種別はINFOレベルで出力することができます。rte_log.h初期化処理のログ出力それでは、サンプルプログラムの初期化処理にRTE_LOG()を埋め込みます。ここでは初期化完了を示すメッセージをログレベルを「INFO」で出力するようにします。利用可能なポート数を取得してログレベルを「DEBUG」で出力します。「EALの初期化」で説明しています。rte_eth_dev_count_avail());・・・RTE_LOG()のパラメータに関して解説します。RTE_LOG_DP()のパラメータについても同様となります。第1パラメータは、ログレベルを指定します。この時プレフィックス(RTE_LOG_)は付けないようにしてください。第2パラメータは、ログ種別を指定します。この時プレフィックス(RTE_LOGTYPE_)は付けないようにしてください。第3パラメータは、出力するメッセージをprintf()の書式で指定します。次にパケット処理にRTE_LOG_DP()を埋め込みます。RTE_LOG_DP()を利用したログは、DPDKのconfigファイル(※1)の「CONFIG_RTE_LOG_DP_LEVEL」に指定したログレベル未満のプライオリティはコンパイル対象外にすることができ、性能を損なわないような考慮が簡単に実現できます。「CONFIG_RTE_LOG_DP_LEVEL」のデフォルト値は"RTE_LOG_INFO"のログレベルなっているので、RTE_LOG_DP()でDEBUGログを出力したい場合は、CONFIG_RTE_LOG_DP_LEVELを"RTE_LOG_DEBUG"を設定してコンパイルして下さい。今回はログの出力内容の例として、パケットの内容を表示したいケースが考えられます。ここでは受信したパケットの先頭6byteを出力する例を紹介します。パケットの内容を出力するため、パケットバッファの内容を参照する必要があります。rte_pktmbuf_mtod()でパケットバッファのアドレスを取得し、16進でログに出力します。6byteの情報を16進数のchar型で確保する配列を用意。1byteの情報は16進数では2文字で表現できるため、6*2+1(終端文字)byteの領域を確保する。str);rte_pktmbuf_mtod()のパラメータに関して解説します。第1パラメータは、パケットバッファのポインタを指定します。第2パラメータは、キャストする型を指定します。「DPDKのコンフィグ」を参照してください。rte_mbuf.h動作確認それでは実際にログを出力します。パケット処理のログを確認するために、以前紹介したncコマンドを、tailコマンドを使って説明します。今回のソースコード一式(ソースコードとMakefile)を格納したディレクトリ"src"を、ホストBのホームディレクトリ配下に配置します。main.c「log.c」をコンパイル対象に含めるため、Makefileの変数:"SRCS-y"に追加します。main.cこれまでと同様に、ソースコードをコンパイルします。my_app.mapログはコンソール上の標準出力と、"/var/log/syslog"に出力されます。ホストBで別のコンソールを立ち上げ、-fオプションを付けたtailコマンドを実行すると、syslogファイルに出力される状況がリアルタイムに確認できます。/var/log/syslog続いてDPDKアプリケーションを起動します、起動方法はこれまでと変わりありません。0.今回追加したログを確認下さい。ソースコードに仕込んだログが出力されています。今回は「グローバルのログレベル」をINFOに設定したので、DEBUGログは出力されていないことが分かります。0.今度はDEBUGログを出力するように変更してみます。「ctrl+c」でDPDKアプリケーションを停止してからソースコードを編集します。DEBUGログを出力するため、rte_log_set_global_level()で設定するログレベルを「RTE_LOG_DEBUG」変更します。srcコード上も好きなメッセージをDEBUGレベルで追記してみてください。*///rte_log_set_global_level(RTE_LOG_INFO);rte_log_set_global_level(RTE_LOG_DEBUG);再度DPDKアプリケーションをコンパイルして起動します。log・・・DPDKアプリケーション起動後、syslogの内容を確認すると、DEBUGログが出力されました。次に、パケット処理時のDEBUGログの動作を確認します。ホストAのeth0からパケットを送信します。第2回~と同じなので、細かい説明は割愛します。5000testtestこの箇所はDEBUGレベルでRTE_LOG_DP()を利用しました。そのため、普通にコンパイルした場合は、DEBUGログは出力されません。出力するためには、DPDKのconfigファイルの"CONFIG_RTE_LOG_DP_LEVEL"を"RTE_LOG_DEBUG"に書き換えます。▼dpdk-<version>/<target>/.config・・・#CONFIG_RTE_LOG_DP_LEVEL=RTE_LOG_INFOCONFIG_RTE_LOG_DP_LEVEL=RTE_LOG_DEBUG・・・CONFIG_RTE_LOG_DP_LEVELの設定反映のため、一旦「ctrl+c」でDPDKアプリケーションを停止してから、DPDKライブラリとDPDKアプリケーションを再コンパイルします。make・・・DPDKアプリケーションを起動します。RTE_LOG_DP()のDEBUGログが有効になっていると、起動時にDPDKが「データパスのDEBUGログが有効になっているため性能が低下します」という警告が表示されます。再度ホストAからUDPパケットを送信します。5000・・・testtestDEBUGログでパケットの先頭6byteの情報が出力されていることが分かります。先頭6byteは宛先macアドレスになりますので、環境に応じた出力の値になっていることを確認してみてください。今まではDPDKアプリケーションにログを埋め込む方法を紹介してきました。DPDKアプリケーションにバグがあった場合、ログ内容から不具合箇所が特定できればよいのですが、他にも「デバッガ」を使う方法がありますので少し紹介します。デバッガは実行途中で直接プログラム中の変数を参照したり値を書き換えることができ、テスト環境を整えずともプログラムの確認をすることができます。ここではDPDKアプリケーションにデバッガを使う方法を紹介します。デバッカはLinux環境においてよく使われる「gdb(※2)」を使用します。gdbは、以下コマンドでインストールできます。gdbまた、デバッガを扱うためにプログラムに「デバックシンボル(※3)」を埋め込む必要があります。コンパイラにより実行ファイルに対して「最適化」がかかることで、変数の参照などが上手くいかないケースがあるため、「最適化なし」でコンパイルします。DPDKライブラリを「最適化なし」及び「デバックシンボルの埋め込み」でコンパイルします。makeコマンドを実行する際、変数EXTRACFLAGSで最適化なし(-O0)デバックシンボル埋め込み(-g)のコンパイルオプションを指定します。次にDPDKアプリケーションを「最適化なし」及び「デバックシンボルの埋め込み」でコンパイルするため、Makefileのコンパイルオプションを書き換えます。-gDPDKアプリケーションのコンパイルを行い、実行ファイルを作成します。最後に、デバッガを用いてDPDKアプリケーションを起動します。DPDKアプリケーションを起動する際にはgdbコマンドの"--args"オプションで、DPDKアプリケーションの起動コマンドラインを指定します。build/my_app...done.(gdb)ここまで出来れば、デバッガを操作してデバッグを行うことが可能です。デバッガの操作についてはgdbのmanページ(※2)を参照してください。デバッグシンボルデバッガが使用するデータです。プログラム中に埋め込むと、デバッガでメモリアドレスが参照出来たり、デバッガにソースコードがマッピングされて、変数名や処理ロジックを参照できるようになります。デバッグシンボルを含めてコンパイルした場合、実行ファイルのサイズが大きくなるため注意してください。今回作成したソースコードについて最後に、今回作成したDPDKアプリケーションのソースコード一式を公開します。今回はソースコードやMakefileを直接編集して、DEBUGログの有効化やデバックシンボルの埋め込みを行いましたが、デバックの度にファイル編集をしていては非効率です。そこで、公開するソースコード一式では、コンパイル時に変数DEBUGを'y'に設定することで、「DEBUGログ有効化」「最適化なし」「デバックシンボル埋め込み」を行ってコンパイル出来るようにしています。DEBUG=y上記のようにコンパイルすると、DEBUGログが出力され、gdbでデバッグ出来る実行ファイルが出来上がりますので、試してみてください。本ソースコードおよびMakefileはあくまでサンプルです。本ソースコードおよびMakefileを利用して発生した損害について、当社は一切の責任を負いません。おわりに今回はDPDKアプリケーションのデバックで利用するログ出力の機能を中心に解説させていただきました。次回はDPDKの設計方法に関して複数回かけて解説する予定です。ご覧いただきありがとうございました。長年NTTの通信基盤となるネットワーク関連の仕事に従事。最近では仮想化技術が主流化しており、最新動向を追従する日々。DPDKに関してはニッチな領域のためか仲間が増えないと感じており、ブログを通した仲間づくりを開始。横浜生まれだが、巨人ファン。東京ドームに観戦に行くことが楽しみ。Corporation。