情報畑でつかまえてロゴ
本サイトは NTTテクノクロスが旬の IT をキーワードに
IT 部門が今知っておきたい最新テクノロジーに関する情報をお届けするサイトです

DPDKのログ出力 ~DPDK入門 第10回~

今回はDPDKアプリケーションのログを出力する方法について解説します。

はじめに

こんにちは、NTTテクノクロス株式会社の寺尾です。今回はアプリケーションのデバッグなどで利用するログ出力の機能を解説します。

DPDKのログ機能について

アプリケーションのデバック方法として、プログラムの「ログ」から処理内容を確認する方法をよく使います。「ログ」とはプログラムの活動記録のようなもので、開発者では解析する情報として重要なものとして取り扱われています。DPDKではログ出力の便利なAPIが用意されていますので、そのAPIを説明します。今回は 前回の記事 で紹介したDPDKアプリケーションに対して、ログを出力する機能を便利に使えるような処理を追加します。




DPDKのログ出力のAPIでは、ログのカテゴリ(ログの出力元情報)や優先度の条件を設定し、その条件によってログの出力要否を選ぶことができます。このログのカテゴリを「ログ種別」、優先度を「ログレベル」として今後説明していきます。ログの出力を行うAPIはrte_log()で例えば以下のようにして使います。 この例では、ログのカテゴリとして「app_main」を1つ定義し、ログの優先度を「DEBUG」として定義しました。このように定義をすることで、例えばapp_mainのカテゴリは普段の運用では出力したくないなどの設定ができるようになります。

▼ rte_log()の使い方の例
int id = rte_log_register("app_main");     // ログ種別の定義
rte_log_set_level(id, RTE_LOG_DEBUG);      // ログレベルの設定
rte_log(RTE_LOG_DEBUG, id, "test message");  // ログ出力


上記のようにrte_log()の関数を使えばログを出力することができますが、今回はこの方法よりも手軽にログを出力できるマクロがDPDKで用意されていますので、その方法を紹介します。DPDKではRTE_LOG()とRTE_LOG_DP()の2つのマクロが用意されており、以下のように使い分けます。
- RTE_LOG() : ログを出力する基本のマクロ。
- RTE_LOG_DP() : ログの出力要否を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()の処理や特殊なプレフィックスを使ったマクロ定義が不要です。

▼ 独自のログ種別を定義(src/log.h)
#define RTE_LOGTYPE_APP_MAIN rte_log_register("app_main")
#define RTE_LOGTYPE_APP_FWD rte_log_register("app_forward")


次にログレベルを設定します。ログ出力処理には必ずログレベルを指定しますが、実際に出力するかどうかはシステムのログ出力の優先度と比較し、その優先度より高ければログ出力するようになります。例えばログ出力処理でログレベルを「INFO」と設定した場合、システムのログ出力の優先度が「INFO」よりも高いレベルで設定されていた場合はログが出力されません。DPDKで指定可能なログレベルを以下に示します。


DPDKのログレベル一覧(プライオリティが高い順に列挙)

ログレベル 説明
RTE_LOG_EMERG 致命的な状態にあることを示すログ
RTE_LOG_ALERT 早急な対応が必要なことを示すログ
RTE_LOG_CRIT 危険な状態にあることを示すログ
RTE_LOG_ERR 一般的エラーであることを示すログ
RTE_LOG_WARNING 一般的な警告を示すログ
RTE_LOG_NOTICE 重要な通知を示すログ
RTE_LOG_INFO システムからの情報を示すログ
RTE_LOG_DEBUG デバック用の情報であることを示すログ


ログ出力の優先度は全体に1つ設定すれば良いですが、必要に応じて「ログ種別」毎に設定することもできます。DPDKでは全体に設定するログ出力の優先度を「グローバル」の「ログレベル」と表現しています。「グローバル」の設定と「ログ種別」毎の優先度の判定は以下のイメージとなります。「ログ種別」毎の設定が特にない場合は判定自体スキップされます。


グローバルのログレベルの設定にはrte_log_set_global_level()、ログ種別ごとのログレベル設定にはrte_log_set_level()を使います。今回は、グローバルのログレベルを「RTE_LOG_INFO」に、ログ種別(app_main)のログレベルを「RTE_LOG_ERROR」に設定しました。こうすることで、app_mainのログはERRORレベル未満のものは出力を抑止できるとともに、他のログ種別はINFOレベルで出力することができます。

▼ ログレベル設定定義(src/log.c)
/* グローバルのログレベル */
rte_log_set_global_level(RTE_LOG_INFO);
/* ログ種別ごとのログレベル */
rte_log_set_level(RTE_LOGTYPE_APP_MAIN, RTE_LOG_ERROR);


【APIリファレンス】
rte_log_register

引数 in/out パラメータ 補足
const char * input ログ種別名称 既に同じ名称のログ種別が登録されていた場合、そのログ種別のIDを返却する
戻り値 説明
int 整数値(1以上) ログ種別のID
負値(-ENOMEM) メモリ割り当て失敗
ヘッダファイル rte_log.h


rte_log_set_global_level

引数 in/out パラメータ 補足
uint32_t input グローバルのログレベル -
戻り値 説明
void - -
ヘッダファイル rte_log.h


rte_log_set_level

引数 in/out パラメータ 補足
uint32_t input ログ種別 -
uint32_t input ログ種別ごとのログレベル -
戻り値 説明
int 0 ログレベル設定成功
負値 ログレベル設定失敗
ヘッダファイル rte_log.h

初期化処理のログ出力

それでは、サンプルプログラムの初期化処理にRTE_LOG()を埋め込みます。ここでは初期化完了を示すメッセージをログレベルを「INFO」で出力するようにします。また、利用可能なポート数を取得してログレベルを「DEBUG」で出力します。なお、rte_eth_dev_count_avail()は、DPDKアプリケーションの作成 初期化処理編 ~DPDK入門 第7回~ の「EALの初期化」で説明しています。

▼初期化処理のログ出力
・・・
RTE_LOG(INFO, APP_MAIN, "Initialize DPDK done.\n");
RTE_LOG(DEBUG, APP_MAIN, "Avail device num = %u\n", rte_eth_dev_count_avail());
・・・


RTE_LOG()のパラメータに関して解説します。なお、RTE_LOG_DP()のパラメータについても同様となります。
- 第1パラメータは、ログレベルを指定します。この時プレフィックス(RTE_LOG_)は付けないようにしてください。
- 第2パラメータは、ログ種別を指定します。この時プレフィックス(RTE_LOGTYPE_)は付けないようにしてください。
- 第3パラメータは、出力するメッセージをprintf()の書式で指定します。

【APIリファレンス】
RTE_LOG

引数 in/out パラメータ 補足
uint32_t input ログレベル プレフィックスは付けずに指定(RTE_LOG_DEBUGなら、"DEBUG"と指定)
uint32_t input ログ種別 プレフィックスは付けずに指定(RTE_LOGTYPE_APP_MAINというログ種別なら、"APP_MAIN"と指定)
... input メッセージ printf()の書式で指定
ヘッダファイル rte_log.h

パケット処理のログ出力

次にパケット処理に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"を設定してコンパイルして下さい。

▼dpdk-<version>/<target>/.config

・・・
CONFIG_RTE_LOG_DP_LEVEL=RTE_LOG_INFO
・・・


今回はログの出力内容の例として、パケットの内容を表示したいケースが考えられます。ここでは受信したパケットの先頭6byteを出力する例を紹介します。パケットの内容を出力するため、パケットバッファの内容を参照する必要があります。rte_pktmbuf_mtod()でパケットバッファのアドレスを取得し、16進でログに出力します。

▼パケットの内容を出力する処理(src/fwd.c)
// 6byteの情報を16進数のchar型で確保する配列を用意。
// 1byteの情報は16進数では2文字で表現できるため、6*2+1(終端文字)byteの領域を確保する。 char str[(6 * 2) + 1] = {0};
// パケットバッファのアドレスを16進文字に変換して領域に書き込みログに出力する uint8_t *dat = rte_pktmbuf_mtod(pkt, uint8_t *); // pktはパケットバッファのポインタ for (int i = 0; i < 6; i++) sprintf(&str[i * 2], "%02x", *(dat + i)); RTE_LOG_DP(DEBUG, APP_FWD, "[Dump 6byte] %s\n", str);

rte_pktmbuf_mtod()のパラメータに関して解説します。
- 第1パラメータは、パケットバッファのポインタを指定します。
- 第2パラメータは、キャストする型を指定します。

※1 DPDKのconfigファイルについて
configファイルについては、 開発環境の構築 ~DPDK入門第9回~ の「DPDKのコンフィグ」を参照してください。

【APIリファレンス】
RTE_LOG_DP

引数 in/out パラメータ 補足
uint32_t input ログレベル プレフィックスは付けずに指定(RTE_LOG_DEBUGなら、"DEBUG"と指定)
uint32_t input ログ種別 プレフィックスは付けずに指定(RTE_LOGTYPE_APP_MAINというログ種別なら、"APP_MAIN"と指定)
... input メッセージ printf()の書式で指定
ヘッダファイル rte_log.h


rte_pktmbuf_mtod

引数 in/out パラメータ 補足
struct rte_mbuf * input パケットバッファ -
(任意) input キャスト指定 パケットバッファは、このパラメータで指定したポインタ型にキャストして参照
戻り値 説明
(任意) アドレス パケットの先頭アドレス
ヘッダファイル rte_mbuf.h


rte_pktmbuf_mtod_offset

引数 in/out パラメータ 補足
struct rte_mbuf * input パケットバッファ -
(任意) input キャスト指定 パケットバッファは、このパラメータで指定したポインタ型にキャストして参照
(整数型) input オフセット パケットの参照したい位置までのオフセット
戻り値 説明
(任意) アドレス パケットの先頭からオフセット分移動した位置のアドレス
ヘッダファイル rte_mbuf.h

動作確認

それでは実際にログを出力します。動作確認の環境はDPDKのパケット処理 ~DPDK入門 第2回~と同様です。また、パケット処理のログを確認するために、以前紹介したncコマンドを、tailコマンドを使って説明します。


まず、今回のソースコード一式(ソースコードとMakefile)を格納したディレクトリ"src"を、ホストBのホームディレクトリ配下に配置します。

hostb$ ls -la ~/src
・・・
-rw-rw-r-- 1 xxxxx xxxxx 1717 Jul 16 08:05 Makefile
-rw-rw-r-- 1 xxxxx xxxxx 1594 Jul 16 09:05 fwd.c
-rw-rw-r-- 1 xxxxx xxxxx 360 Jul 16 08:56 fwd.h
-rw-rw-r-- 1 xxxxx xxxxx 562 Jul 12 04:18 log.c
-rw-rw-r-- 1 xxxxx xxxxx 527 Jul 12 04:19 log.h
-rw-rw-r-- 1 xxxxx xxxxx 4644 Jul 16 09:22 main.c


「log.c」をコンパイル対象に含めるため、Makefileの変数:"SRCS-y"に追加します。

▼ ~/src/Makefile

#SRCS-y := fwd.c main.c
SRCS-y := log.c fwd.c main.c

これまでと同様に、ソースコードをコンパイルします。

hostb$ cd dpdk-<version>
hostb$ export RTE_SDK=`pwd`
hostb$ export RTE_TARGET=x86_64-native-linuxapp-gcc
hostb$ cd ~/src
hostb$ make
  CC log.o
  CC fwd.o
  CC main.o
  LD my_app
  INSTALL-APP my_app
  INSTALL-MAP my_app.map


ログはコンソール上の標準出力と、"/var/log/syslog"に出力されます。ホストBで別のコンソールを立ち上げ、-fオプションを付けたtailコマンドを実行すると、syslogファイルに出力される状況がリアルタイムに確認できます。

hostb$ sudo tail -f /var/log/syslog


続いてDPDKアプリケーションを起動します、起動方法はこれまでと変わりありません。

hostb$ sudo ./build/my_app -c 1
EAL: Detected 32 lcore(s)
・・・
APP_MAIN: Initialize DPDK done.
APP_MAIN: Initializing port 0
APP_MAIN: Please wait for the port 0 to LinkUp...
APP_MAIN: done.
APP_FWD: Forwards packets received on port 0 to port 0.


今回追加したログを確認下さい。ソースコードに仕込んだログが出力されています。今回は「グローバルのログレベル」をINFOに設定したので、DEBUGログは出力されていないことが分かります。

hostb$ sudo tail -f /var/log/syslog
・・・
Nov 12 01:41:22 hostb my_app[2949]: APP_MAIN: Initialize DPDK done.
Nov 12 22 01:41:22 hostb my_app[2949]: APP_MAIN: Initializing port 0
Nov 12 01:41:22 hostb my_app[2949]: APP_MAIN: Please wait for the port 0 to LinkUp...
Nov 12 01:41:22 hostb my_app[2949]: APP_MAIN: done.
Nov 12 01:41:22 hostb my_app[2949]: APP_FWD: Forwards packets received on port 0 to port 0.


今度はDEBUGログを出力するように変更してみます。一旦「ctrl+c」でDPDKアプリケーションを停止してからソースコードを編集します。DEBUGログを出力するため、rte_log_set_global_level()で設定するログレベルを「RTE_LOG_DEBUG」変更します。また、srcコード上も好きなメッセージをDEBUGレベルで追記してみてください。

▼ ログレベル設定定義を変更(src/log.c)

/* グローバルのログレベル */
//rte_log_set_global_level(RTE_LOG_INFO);
rte_log_set_global_level(RTE_LOG_DEBUG);

再度DPDKアプリケーションをコンパイルして起動します。

hostb$ make
・・・
hostb$ sudo ./build/my_app -c 1
・・・
APP_MAIN: test debug log
・・・


DPDKアプリケーション起動後、syslogの内容を確認すると、DEBUGログが出力されました。

hostb$ sudo tail -f /var/log/syslog
・・・
Jul 22 02:08:59 hostb my_app[3443]: APP_MAIN: test debug log
・・・


次に、パケット処理時のDEBUGログの動作を確認します。まず、ホストAのeth0からパケットを送信します。方法はDPDKのパケット処理 ~DPDK入門 第2回~と同じなので、細かい説明は割愛します。

hosta$ sudo arp -s 192.168.11.100 aa:aa:aa:bb:bb:bb
・・・
hosta$ nc -u 192.168.11.100 5000
test
test


この箇所は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_INFO
CONFIG_RTE_LOG_DP_LEVEL=RTE_LOG_DEBUG
・・・

CONFIG_RTE_LOG_DP_LEVELの設定反映のため、一旦「ctrl+c」でDPDKアプリケーションを停止してから、DPDKライブラリとDPDKアプリケーションを再コンパイルします。

hostb$ cd $RTE_SDK/$RTE_TARGET
hostb$ make
・・・
hostb$ cd ~/src
hostb$ make
・・・


DPDKアプリケーションを起動します。RTE_LOG_DP()のDEBUGログが有効になっていると、起動時にDPDKが「データパスのDEBUGログが有効になっているため性能が低下します」という警告が表示されます。

hostb$ sudo ./build/my_app -c 1
・・・
EAL: Debug dataplane logs available - lower performance
・・・


再度ホストAからUDPパケットを送信します。

hosta$ nc -u 192.168.11.100 5000
・・・
test
test


DEBUGログでパケットの先頭6byteの情報が出力されていることが分かります。尚、先頭6byteは宛先macアドレスになりますので、環境に応じた出力の値になっていることを確認してみてください。

hostb$ sudo ./build/my_app -c 1
・・・
Nov 14 09:43:50 hostb my_app[5639]: APP_FWD: [Dump 6byte] aaaaaabbbbbb
Nov 14 09:43:53 hostb my_app[5639]: APP_FWD: [Dump 6byte] aaaaaabbbbbb

デバッガの利用

今まではDPDKアプリケーションにログを埋め込む方法を紹介してきました。もし、DPDKアプリケーションにバグがあった場合、ログ内容から不具合箇所が特定できればよいのですが、他にも「デバッガ」を使う方法がありますので少し紹介します。

デバッガは実行途中で直接プログラム中の変数を参照したり値を書き換えることができ、テスト環境を整えずともプログラムの確認をすることができます。。ここではDPDKアプリケーションにデバッガを使う方法を紹介します。なお、デバッカはLinux環境においてよく使われる「gdb(※2)」を使用します。gdbは、以下コマンドでインストールできます。

$ sudo apt install gdb


また、デバッガを扱うためにプログラムに「デバックシンボル(※3)」を埋め込む必要があります。また、コンパイラにより実行ファイルに対して「最適化」がかかることで、変数の参照などが上手くいかないケースがあるため、「最適化なし」でコンパイルします。

まず、DPDKライブラリを「最適化なし」及び「デバックシンボルの埋め込み」でコンパイルします。makeコマンドを実行する際、変数EXTRACFLAGSで最適化なし(-O0)デバックシンボル埋め込み(-g)のコンパイルオプションを指定します。

$ cd $RTE_SDK/$RTE_TARGET
$ make clean
$ make EXTRACFLAGS="-O0 -g"
・・・


次にDPDKアプリケーションを「最適化なし」及び「デバックシンボルの埋め込み」でコンパイルするため、Makefileのコンパイルオプションを書き換えます。

▼ ~/src/Makefile
#CFLAGS += -O3
CFLAGS += -O0 -g

DPDKアプリケーションのコンパイルを行い、実行ファイルを作成します。

$ cd ~/src
$ make
・・・


最後に、デバッガを用いてDPDKアプリケーションを起動します。DPDKアプリケーションを起動する際にはgdbコマンドの"--args"オプションで、DPDKアプリケーションの起動コマンドラインを指定します。

$ sudo gdb --args build/my_app -c 0x1
GNU gdb (Ubuntu 8.1-0ubuntu3) 8.1.0.20180409-git
Copyright (C) 2018 Free Software Foundation, Inc.
・・・
Reading symbols from build/my_app...done.
(gdb)


ここまで出来れば、デバッガを操作してデバッグを行うことが可能です。デバッガの操作についてはgdbのmanページ(※2)を参照してください。

※2 gdb
https://linuxjm.osdn.jp/html/GNU_gdb/man1/gdb.1.html

※3 デバッグシンボル
デバッガが使用するデータです。プログラム中に埋め込むと、デバッガでメモリアドレスが参照出来たり、デバッガにソースコードがマッピングされて、変数名や処理ロジックを参照できるようになります。なお、デバッグシンボルを含めてコンパイルした場合、実行ファイルのサイズが大きくなるため注意してください。

今回作成したソースコードについて

最後に、今回作成したDPDKアプリケーションのソースコード一式を公開します。

今回はソースコードやMakefileを直接編集して、DEBUGログの有効化やデバックシンボルの埋め込みを行いましたが、デバックの度にファイル編集をしていては非効率です。そこで、公開するソースコード一式では、コンパイル時に変数DEBUGを'y'に設定することで、「DEBUGログ有効化」「最適化なし」「デバックシンボル埋め込み」を行ってコンパイル出来るようにしています。

$ make DEBUG=y


上記のようにコンパイルすると、DEBUGログが出力され、gdbでデバッグ出来る実行ファイルが出来上がりますので、試してみてください。(※4)

ソースコード一式(第10回)

※4 サンプルコードご利用の際の注意事項
本ソースコードおよびMakefileはあくまでサンプルです。本ソースコードおよびMakefileを利用して発生した損害について、当社は一切の責任を負いません。

おわりに

今回はDPDKアプリケーションのデバックで利用するログ出力の機能を中心に解説させていただきました。次回はDPDKの設計方法に関して複数回かけて解説する予定です。ご覧いただきありがとうございました。

連載シリーズ
DPDK入門
著者プロフィール
寺尾 智之
寺尾 智之
長年NTTの通信基盤となるネットワーク関連の仕事に従事。 最近では仮想化技術が主流化しており、最新動向を追従する日々。 DPDKに関してはニッチな領域のためか仲間が増えないと感じており、ブログを通した仲間づくりを開始。 横浜生まれだが、巨人ファン。たまに東京ドームに観戦に行くことが楽しみ。