OpenCVのロギング機能

• この記事はOpenCV Advent Calendar 2020の7日目の記事です。
• 他の記事は目次にまとめられています。

はじめに

過去にflannモジュール内に実装されたロギング機能についてOpenCVのLoggerという記事で紹介されていました。一方でcoreモジュールに実装されているOpenCVのロギング機能に触れている記事がないのでこれを機会に本記事で紹介してみようと思います。

ロギング機能（基礎編）

ヘッダファイル

OpenCVのロギング機能を使うためには以下のヘッダファイルをインクルードする必要があります。

#include <opencv2/core/utils/logger.hpp>

ロギング用マクロ

OpenCVでよく使われる基本的なロギング用マクロは以下の通りです（厳密にはこれらを拡張したマクロがあるので後述します）。上にあるほど深刻な時のログです。

• CV_LOG_FATAL
• CV_LOG_ERROR
• CV_LOG_WARNING
• CV_LOG_INFO
• CV_LOG_DEBUG
• CV_LOG_VERBOSE

https://docs.opencv.org/4.5.0/d3/dcb/group__core__logging.html

CV_LOG_ERRORの使用例は以下の通りです。

int val = 0;
CV_LOG_ERROR(nullptr, cv::format("val = %d", val));

また、ログメッセージの例は以下の通りです。

[ERROR:0] global /home/xxx/logger/main.cpp (11) func val = 0

このログメッセージから以下のことがわかります。

メッセージ	意味
[ERROR:0]	ERRORはCV_LOG_ERRORのログであることを示しています。また、(0)はcv::utils::getThreadIDで取得したスレッド番号です。
global	OpenCVのロギング機能では通常CV_LOGTAG_GLOBALが使われる（https://github.com/opencv/opencv/blob/4.5.0/modules/core/include/opencv2/core/utils/logger.hpp#L105）ため、globalという表示になります。OpenCVのロギング機能にはLogTagという概念があり、そのタグ名のことです。この概念は少しややこしいのでこの記事では説明を省きます。
/home/xxx/logger/main.cpp (11)	ログが出力されているファイル名、行番号です。
func	ログが出力されている関数名です。

ログレベル

OpenCVでは以下のログレベルが定義されています。このログレベルを設定することでロギング機能で表示するレベルをコントロールできます。

• cv::utils::logging::LOG_LEVEL_SILENT
• cv::utils::logging::LOG_LEVEL_FATAL
• cv::utils::logging::LOG_LEVEL_ERROR
• cv::utils::logging::LOG_LEVEL_WARNING
• cv::utils::logging::LOG_LEVEL_INFO
• cv::utils::logging::LOG_LEVEL_DEBUG
• cv::utils::logging::LOG_LEVEL_VERBOSE

詳細はhttps://docs.opencv.org/4.5.0/da/db0/namespacecv_1_1utils_1_1logging.html#a57fad1f723934e699c495e99140f1bd9を参照下さい。このページの説明にもあるようにLOG_LEVEL_DEBUG、LOG_LEVEL_VERBOSEはReleaseビルド時は無効化されています。

また、ログレベルのデフォルト値はOpenCVのライブラリのビルドタイプによって変わるので注意が必要です（OpenCV使ったアプリケーションのビルドタイプではない）。

• Debugビルド： LOG_LEVEL_INFO
• Releaseビルド： LOG_LEVEL_WARNING

https://github.com/opencv/opencv/blob/4.5.0/modules/core/src/logger.cpp#L79-L81

ログレベル取得

cv::utils::logging::getLogLevelで現在のログレベルを取得できます。

auto log_level = cv::utils::logging::getLogLevel();

ログレベル設定

cv::utils::logging::setLogLevelでログレベルを設定できます。

cv::utils::logging::setLogLevel(cv::utils::logging::LOG_LEVEL_FATAL);

サンプルコード

OpenCVのロギング機能について基本的なところは説明したのでサンプルコードを使って挙動を確かめてみましょう。

#include <opencv2/core/core.hpp>
#include <opencv2/core/utils/logger.hpp>
#include <iostream>

void func(int val)
{
    CV_LOG_VERBOSE(nullptr, 0, cv::format("val = %d", val));
    CV_LOG_DEBUG(nullptr, cv::format("val = %d", val));
    CV_LOG_INFO(nullptr, cv::format("val = %d", val));
    CV_LOG_WARNING(nullptr, cv::format("val = %d", val));
    CV_LOG_ERROR(nullptr, cv::format("val = %d", val));
    CV_LOG_FATAL(nullptr, cv::format("val = %d", val));
}

int main()
{
    std::cout << "// logger test1" << std::endl;
    func(1);

    std::cout << "\n// logger test2" << std::endl;
    cv::utils::logging::setLogLevel(cv::utils::logging::LOG_LEVEL_VERBOSE);
    func(2);

    std::cout << "\n// logger test3" << std::endl;
    cv::utils::logging::setLogLevel(cv::utils::logging::LOG_LEVEL_SILENT);
    func(3);

    return 0;
}

ログメッセージ（Releaseビルド）

サンプルコードをReleaseビルドにした場合のログメッセージは以下の通りです。

// logger test1
[ WARN:0] global /home/xxx/logger/main.cpp (10) func val = 1
[ERROR:0] global /home/xxx/logger/main.cpp (11) func val = 1
[FATAL:0] global /home/xxx/logger/main.cpp (12) func val = 1

// logger test2
[ INFO:0] global /home/xxx/logger/main.cpp (9) func val = 2
[ WARN:0] global /home/xxx/logger/main.cpp (10) func val = 2
[ERROR:0] global /home/xxx/logger/main.cpp (11) func val = 2
[FATAL:0] global /home/xxx/logger/main.cpp (12) func val = 2

// logger test3

Releaseビルド時のログメッセージからわかることは以下の通りです。

• デフォルトのログレベルだとWARNING以上のレベルのログしか出ていないことがわかります（logger test1）
  • OpenCVのライブラリはReleaseビルドのものを使っているため
• 明示的にログレベルをLOG_LEVEL_VERBOSEにするとINFOのログが出るようになっていることがわかります（logger test2）
• 明示的にログレベルをLOG_LEVEL_SILENTにすると全てのログが出なくことがわかります。（logger test3）

ログメッセージ（Debugビルド）

サンプルコードをDebugビルドにした場合のログメッセージは以下の通りです。

// logger test1
[ WARN:0] global /home/xxx/logger/main.cpp (10) func val = 1
[ERROR:0] global /home/xxx/logger/main.cpp (11) func val = 1
[FATAL:0] global /home/xxx/logger/main.cpp (12) func val = 1

// logger test2
[DEBUG:0] global /home/xxx/logger/main.cpp (8) func val = 2
[ INFO:0] global /home/xxx/logger/main.cpp (9) func val = 2
[ WARN:0] global /home/xxx/logger/main.cpp (10) func val = 2
[ERROR:0] global /home/xxx/logger/main.cpp (11) func val = 2
[FATAL:0] global /home/xxx/logger/main.cpp (12) func val = 2

// logger test3

Debugビルド時のログメッセージからわかることは以下の通りです。

• デフォルトのログレベルだとWARNING以上のレベルのログしか出ていないことがわかります（logger test1）
  • OpenCVのライブラリはReleaseビルドのものを使っているため
• 明示的にログレベルをLOG_LEVEL_VERBOSEにするとINFO、DEBUGのログが出るようになっていることがわかります（logger test2）
  • よく見るとCV_LOG_VERBOSEのログが出ていないことがわかります（このあたりの話はややこしいので後述します）
• 明示的にログレベルをLOG_LEVEL_SILENTにすると全てのログが出なくことがわかります。（logger test3）

ロギング機能（応用編）

これまでは基本的なロギング機能について紹介してきましたが、https://github.com/opencv/opencv/pull/16704でいくつかロギング機能が拡張されているので紹介します。

条件付きログ出力

ロギング機能である条件を満たしたときだけログを出力したいケースがあります。このような機能を実現するためにOpenCVでは以下のマクロを提供しています。

• CV_LOG_IF_FATAL
• CV_LOG_IF_ERROR
• CV_LOG_IF_WARNING
• CV_LOG_IF_INFO
• CV_LOG_IF_DEBUG
• CV_LOG_IF_VERBOSE

それではこの機能をどのように実現しているかというとopencv2/core/utils/logger.hppで条件チェックマクロであるCV__LOG_IF_CHECKを定義していてそのマクロによってログ出力を制御しています。

#define CV__LOG_IF_CHECK(logging_cond) \
    if (!(logging_cond)) break;

#define CV_LOG_IF_FATAL(tag, logging_cond, ...) CV_LOG_WITH_TAG(tag, cv::utils::logging::LOG_LEVEL_FATAL, , CV__LOG_IF_CHECK(logging_cond), __VA_ARGS__)
#define CV_LOG_IF_ERROR(tag, logging_cond, ...) CV_LOG_WITH_TAG(tag, cv::utils::logging::LOG_LEVEL_ERROR, , CV__LOG_IF_CHECK(logging_cond), __VA_ARGS__)
#define CV_LOG_IF_WARNING(tag, logging_cond, ...) CV_LOG_WITH_TAG(tag, cv::utils::logging::LOG_LEVEL_WARNING, , CV__LOG_IF_CHECK(logging_cond), __VA_ARGS__)
#define CV_LOG_IF_INFO(tag, logging_cond, ...) CV_LOG_WITH_TAG(tag, cv::utils::logging::LOG_LEVEL_INFO, , CV__LOG_IF_CHECK(logging_cond), __VA_ARGS__)
#define CV_LOG_IF_DEBUG(tag, logging_cond, ...) CV_LOG_WITH_TAG(tag, cv::utils::logging::LOG_LEVEL_DEBUG, , CV__LOG_IF_CHECK(logging_cond), __VA_ARGS__)
#define CV_LOG_IF_VERBOSE(tag, v, logging_cond, ...) CV_LOG_WITH_TAG(tag, (cv::utils::logging::LOG_LEVEL_VERBOSE + (int)(v)), , CV__LOG_IF_CHECK(logging_cond), __VA_ARGS__)

サンプルコード

CV_LOG_IF_ERRORを使ったサンプルコードを以下に示します。

#include <opencv2/core/core.hpp>
#include <opencv2/core/utils/logger.hpp>
#include <iostream>

void func(int val)
{
    CV_LOG_IF_ERROR(nullptr, (val < 0), cv::format("val = %d", val));
}

int main()
{
    func(0);  // OK
    func(-1); // NG
    return 0;
}

このサンプルコードの実行結果（例）は以下の通りです。
この結果からCV_LOG_IF_ERRORに設定した条件（val < 0）を満たしているときだけログが出ていることがわかります。

[ERROR:0] global /home/xxx/logger/main.cpp (7) func val = -1

ONCEログ出力

ロギング機能で同じメッセージが出続けるとログが読みづらくなるので最初の1回だけ出したいというケースがあります。このような機能を実現するためにOpenCVでは以下のマクロを提供しています。

• CV_LOG_ONCE_FATAL
• CV_LOG_ONCE_ERROR
• CV_LOG_ONCE_WARNING
• CV_LOG_ONCE_INFO
• CV_LOG_ONCE_DEBUG
• CV_LOG_ONCE_VERBOSE

それではこの機能をどのように実現しているかというとopencv2/core/utils/logger.hppのマクロ内でログ出力済かどうかのstatic変数を定義していてその変数を使ってログ出力を制御しています。

#define CV__LOG_ONCE_CHECK_PRE \
    static bool _cv_log_once_ ## __LINE__ = false; \
    if (_cv_log_once_ ## __LINE__) break;

#define CV__LOG_ONCE_CHECK_POST \
    _cv_log_once_ ## __LINE__ = true;

https://github.com/opencv/opencv/blob/4.5.0/modules/core/include/opencv2/core/utils/logger.hpp#L152-L157

サンプルコード

CV_LOG_ONCE_ERRORを使ったサンプルコードを以下に示します。

#include <opencv2/core/core.hpp>
#include <opencv2/core/utils/logger.hpp>

void func(int val)
{
    CV_LOG_ONCE_ERROR(nullptr, cv::format("val = %d", val));
}

int main()
{
    func(0);
    func(1);
    func(2);
    return 0;
}

このサンプルコードの実行結果（例）は以下の通りです。この結果から、funcの初回コール時のみログが表示されていることがわかります。

[ERROR:0] global /home/xxx/logger/main.cpp (6) func val = 0

CV_LOG_VERBOSEがデフォルトだと出力されないのはなぜか？

冒頭でCV_LOG_VERBOSEのメッセージが出力されないという話がありました。
この振る舞いに関しては、OpenCVのロギング機能が、ログレベルだけでなく、CV_LOG_STRIP_LEVELマクロによって制御されているためです。

CV_LOG_STRIP_LEVELはopencv2/core/utils/logger.hppで以下のように定義されています。

#ifndef CV_LOG_STRIP_LEVEL
# if defined NDEBUG
#   define CV_LOG_STRIP_LEVEL CV_LOG_LEVEL_DEBUG
# else
#   define CV_LOG_STRIP_LEVEL CV_LOG_LEVEL_VERBOSE
# endif
#endif

DebugビルドなのでCV_LOG_STRIP_LEVELはCV_LOG_LEVEL_VERBOSEになります。
そのため、opencv2/core/utils/logger.hppにある下記の処理によりCV_LOG_VERBOSEが空実装に置き換えられてしまい、ログのメッセージが表示されていないということになります。

#if CV_LOG_STRIP_LEVEL <= CV_LOG_LEVEL_VERBOSE
#undef CV_LOG_VERBOSE
#define CV_LOG_VERBOSE(tag, v, ...)
#endif

以下にCV_LOG_VERBOSEを表示させるためのサンプルコードを示します。

#define CV_LOG_STRIP_LEVEL CV_LOG_LEVEL_VERBOSE + 1
#include <opencv2/core/core.hpp>
#include <opencv2/core/utils/logger.hpp>
#include <iostream>

void func(int val)
{
    CV_LOG_VERBOSE(nullptr, 0, cv::format("val = %d", val));
}

int main()
{
    cv::utils::logging::setLogLevel(cv::utils::logging::LOG_LEVEL_VERBOSE);
    func(0);
    return 0;
}

CV_LOG_STRIP_LEVELはopencv2/core/utils/logger.hppで以下のように定義されているのでここでCV_LOG_STRIP_LEVELの定義がなされる前に定義してしまうという方法ですね（実際にhttps://github.com/opencv/opencv/blob/4.5.0/modules/core/src/utils/samples.cpp#L10-L11でも同じ方法がとられています）。

#ifndef CV_LOG_STRIP_LEVEL
# if defined NDEBUG
#   define CV_LOG_STRIP_LEVEL CV_LOG_LEVEL_DEBUG
# else
#   define CV_LOG_STRIP_LEVEL CV_LOG_LEVEL_VERBOSE
# endif
#endif

先程のサンプルコードの実行結果（例）は以下の通りです。
無事にCV_LOG_VERBOSEでログを出力させることが出来ました。

global /home/xxx/logger/main.cpp (8) func val = 0

動作確認環境

筆者は以下の環境で動作確認しました。

ソフトウェア

• Ubuntu 20.04 64bit
• CMake 3.16.3
• gcc 9.3.0
• CUDA 11.1
• OpenCV 4.5.0

ハードウェア

• CPU：Intel Core i7-9800X CPU @ 3.80GHz
• メモリ：32GB
• GPU：NVIDIA GeForce RTX 2080 Ti 11GB

おわりに

今回coreモジュールに実装されているOpenCVのロギング機能を紹介しました。OpenCVで提供されているロギング機能で十分ということであればマルチプラットフォーム対応されていてOpenCVさえあればすぐに使えることから選択肢に含めても良いかもしれません。明日も引き続きdandelion1124の記事です。

Appendix

OpenCVのロギング機能開発の歴史的経緯などを知りたい場合は以下のURLを読むとよいでしょう。

• ロギング機能のリファクタリング
  • https://github.com/opencv/opencv/pull/13909
• ロギング機能拡張のPR
  • https://github.com/opencv/opencv/pull/16704
• OpenCVのロギング機能開発方針
  • https://github.com/opencv/opencv/wiki/OE-11.-Logging
  • https://github.com/opencv/opencv/issues/11003