OpenCVのロギング機能

* この記事は[OpenCV Advent Calendar 2020](http://qiita.com/advent-calendar/2020/opencv)の7日目の記事です。
* 他の記事は[目次](https://qiita.com/advent-calendar/2020/opencv)にまとめられています。

## はじめに
過去にflannモジュール内に実装されたロギング機能について[OpenCVのLogger](http://schima.hatenablog.com/entry/2016/01/27/222414)という記事で紹介されていました。一方でcoreモジュールに実装されているOpenCVのロギング機能に触れている記事がないのでこれを機会に本記事で紹介してみようと思います。

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

```cpp
#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`の使用例は以下の通りです。

```cpp
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](https://docs.opencv.org/4.5.0/d3/dc4/namespacecv_1_1utils.html#a861802cc8e8b0507fd794faec3a08376)で取得したスレッド番号です。|
|`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](https://docs.opencv.org/4.5.0/d3/dcb/group__core__logging.html#ga42b8f832c209189c1abbc5a23892f681)で現在のログレベルを取得できます。

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

### ログレベル設定
[cv::utils::logging::setLogLevel](https://docs.opencv.org/4.5.0/d3/dcb/group__core__logging.html#gaa022dd6c6e2d72539cc1e5100bcb378b)でログレベルを設定できます。

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

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

```cpp
#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ビルドにした場合のログメッセージは以下の通りです。

```log
// 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ビルドにした場合のログメッセージは以下の通りです。

```log
// 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`を定義していてそのマクロによってログ出力を制御しています。

```cpp
#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`を使ったサンプルコードを以下に示します。

```cpp
#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`）を満たしているときだけログが出ていることがわかります。

```log
[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変数を定義していてその変数を使ってログ出力を制御しています。

```cpp
#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`を使ったサンプルコードを以下に示します。

```cpp
#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の初回コール時のみログが表示されていることがわかります。

```log
[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`で以下のように定義されています。

```cpp
#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`が空実装に置き換えられてしまい、ログのメッセージが表示されていないということになります。

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

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

```cpp
#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>でも同じ方法がとられています）。

```cpp
#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`でログを出力させることが出来ました。

```log
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](https://github.com/opencv/opencv/releases/tag/4.5.0)

### ハードウェア
- CPU：Intel Core i7-9800X CPU @ 3.80GHz
- メモリ：32GB
- GPU：NVIDIA GeForce RTX 2080 Ti 11GB

## おわりに
今回coreモジュールに実装されているOpenCVのロギング機能を紹介しました。OpenCVで提供されているロギング機能で十分ということであればマルチプラットフォーム対応されていてOpenCVさえあればすぐに使えることから選択肢に含めても良いかもしれません。明日も引き続き[dandelion1124](https://twitter.com/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