こんにちは、ナナです。
膨大な量のプログラムを動かしていると、プログラムの問題をトレースするためのログを出力したい時があります。
ログは、printf関数を使って次のように出力するのが基本です。
int testFunc(int num)
{
if (num < 0)
{
printf("testFunc関数 引数異常:%d\n", num);
return -1;
}
if (subFunc() == -1)
{
printf("subfunc関数 戻り値 失敗\n");
return -1;
}
return 0;
}
このようなログは、プログラムのいたるところに必要になり、出力形式をどのようにすればよりよいログとして機能するかが課題となります。
このログの出力形式で大事なことは、ログからプログラムの出力箇所を素早く特定できることです。
そのためにログの中に「ファイル名」や「行番号」を埋め込んでおくと便利になります。
本記事では次の疑問点を解消する内容となっています。
では、ログの出力方法を解説していきましょう。
「ファイル名」と「行番号」を示すマクロを活用
最初にログとして機能するために必要な情報と取得方法を示します。
動作ログに必要な情報
ログとして出力する代表的な情報は次のようなものです。
項目 | 概要 |
---|---|
ファイル名 | どのファイルによって出力されたログなのかが特定できること |
行番号 | ファイル内のどこで出力されたログなのかが特定できること |
関数名 | どの関数で出力されたログなのかが特定できること |
メッセージ内容 | どのようなログ内容なのかがわかること |
重要度 | ログの重要度がわかること |
ログとして機能するために最も大事なことが、プログラムコード上のどこで出力されたログなのかが素早く特定できることです。
大規模開発の場合、問題のログがどの場所から出力されたのかを探すのに苦労しているようでは作業効率が悪いのです。
そのため、「ファイル名」「行番号」はログの中に是非とも入れておきたい情報です。
地道なログの出力例
「ファイル名」や「行番号」をprintf関数を使って出力するとなると、次のように直接指定する形を思い浮かべることでしょう。
#include <stdio.h>
int main(void)
{
printf("ファイル名:%s(%d)", "main.c", 5);
return 0;
}
ファイル名:main.c(5)
しかし、こんな作業はやってられませんね。ファイル名はともかく行番号なんていうのはプログラムを編集するたびに変化する可能性があるからです。
プログラムは常にメンテナンス性に強い構成にしておくことを想定しましょう。
このような情報はマクロを使うことで取得できるのです。
マクロを使った情報の取得
実は「ファイル名」や「行番号」はプリプロセッサによって標準で定義されたマクロが用意されています。
項目 | マクロ名 | 出力指定子 | 出力例 |
---|---|---|---|
ファイル名 | __FILE__ | %s | C:\LearningC\Project1\main.c |
行番号 | __LINE__ | %d | 5 |
関数名 | __func__ __FUNCTION__ | %s | main |
これらのマクロを活用することで、どのファイルのどの行で出力されたログなのかを瞬時に特定することができるようになります。
具体的なマクロの使い方は次のように行います。
#include <stdio.h>
int main(void)
{
printf("%s %d %s", __FILE__, __LINE__, __func__);
return 0;
}
C:\LearningC\Project1\main.c 5 main
ファイルと行番号が特定できれば、場所が特定できます。関数名も出力しておくと、ログを見ただけで「この関数でエラーが出てる」などが判断できるようになります。
ログ出力用のprntf関数のカスタマイズ方法
それでは具体的なプログラム例で、ログをどのように出力するかを示しましょう。
関数マクロを使ったprintf関数のカスタマイズ定義例
次のように関数マクロを使ってprintf関数をカスタマイズします。
// デバッグ機能の有効/無効
#define DEBUG_ON
#ifdef DEBUG_ON
#define DEBUG_PRINT(...) printf("%s(%d) %s:", __FILE__, __LINE__, __func__), printf(__VA_ARGS__)
#else
#define DEBUG_PRINT(...)
#endif
これは定義の一例ですが、このような関数マクロを定義しておくと、実際にログを出力するのが非常に楽になります。
関数マクロが何かわからない人は『define マクロ【数値に名前を付ける意味とメリット】』を参考にしてください。
ログの出力方法とログの表示結果
それでは実際にログを出力するプログラムを示しましょう。
#include <stdio.h>
// デバッグ機能の有効/無効
#define DEBUG_ON
#ifdef DEBUG_ON
#define DEBUG_PRINT(...) printf("%s(%d) %s:", __FILE__, __LINE__, __func__), printf(__VA_ARGS__)
#else
#define DEBUG_PRINT(...)
#endif
int main(void)
{
int num = 123;
DEBUG_PRINT("ログ出力テスト1\n");
DEBUG_PRINT("ログ出力テスト2 %d \n", num);
return 0;
}
C:\LearningC\Project1\main.c(16) main:ログ出力テスト1
C:\LearningC\Project1\main.c(17) main:ログ出力テスト2 123
関数マクロで定義した「DEBUG_PRINT」を利用し、printf関数のように出力するとログの結果に「ファイル名」「行番号」「関数名」が自動で付与されていますね。
これが関数マクロの便利なところです。
関数マクロを利用することで、ログ出力箇所にprintf関数の呼び出しが埋め込まれます。
ログ出力の停止方法
ログ機能というのは、デバッグ時など検査すべき工程では出力したいが、製品リリースの段階では出力したくないといった要望があります。
今回のログ機能は、条件コンパイルを利用することで、出力を無効化することができます。
// デバッグ機能の有効/無効
//#define DEBUG_ON
#ifdef DEBUG_ON
#define DEBUG_PRINT(...) printf("%s(%d) %s:", __FILE__, __LINE__, __func__), printf(__VA_ARGS__)
#else
#define DEBUG_PRINT(...)
#endif
このように「DEBUG_ON」のマクロ定義を削除することで、関数マクロを無効化するのです。
条件コンパイルを知らない方は『ifdef 【プログラムをカットする技術と使い方を紹介】』を見ておきましょう。
プリプロセッサを活用したテクニックは非常に強力な機能になります。仕組みをしっかりと理解することで、様々なバリエーションを自分でも作ることができるようになりますよ。
ログ出力用の関数マクロの仕組み解説
関数マクロの仕組みを理解することで、皆さん自身が様々なログの形式をカスタマイズできるようになります。
それでは「DEBUG_PRINT」の関数マクロがどのような仕組みで動いているのかを解説しましょう。
#define DEBUG_PRINT(...) printf("%s(%d) %s:", __FILE__, __LINE__, __func__), printf(__VA_ARGS__)
可変個引数を持つprintf関数
ログ出力はprintf関数を使うわけですから、まずはprintf関数の特徴を理解する必要があります。
printf関数の特徴とは「可変個引数」を持つ関数であることです。
int printf(const char * format, ...);
C言語において「…」が引数として登場する関数は「可変個引数」を持つ関数となります。
通常、引数とは関数定義時に個数が確定しますが、可変個引数の場合に限り、引数の数を変化させることができます。
printf("Hello %d \n", 10); // 引数が2個
printf("Hello %d %d \n", 10, 20); // 引数が3個
このようにprintf関数を呼び出す箇所において引数の数を変えられるのは、可変個引数で定義されているからなのです。
C言語の中で可変個引数は非常に特殊な関数です。皆さんが可変個引数を持つ関数を作ることもできるのですよ。
可変個引数をマクロ展開する「__VA_ARGS__」
DEBUG_PRINTの展開先には「__VA_ARGS__」という見慣れない記述あるのがわかりますね。
これは関数マクロにおいて、可変個引数の情報を展開するためのものです。
これにより次のように記述されたDEBUG_PRINT関数マクロは図のように展開されます。
DEBUG_PRINT("ログ出力テスト2 %d \n", num);
このようにマクロとは文字列を置換することが本質です。「…」の可変個引数として指定された文字を「__VA_ARGS__」の場所にコピペすることで展開するのです。
ログ出力方法のバリエーション紹介
ログの出力形式はアイデア次第で様々なバリエーションに作り変えることができます。
皆さんは自分が出力したい情報を自分なりにカスタマイズして利用するとよいでしょう。
異常・警告レベル付きログ出力
ログは大量に出しすぎると、重症なログと軽症なログが入り乱れて、大事なログを見落とすといったことがよくあります。
そのような場合は、ログの中に異常・警告のレベルを埋め込むといったことも可能です。
// 警告レベル付き
#define DEBUG_PRINT_W(level, ...) printf("[W%d] %s(%d) %s: ", level, __FILE__, __LINE__, __func__), printf(__VA_ARGS__)
// 異常レベル付き
#define DEBUG_PRINT_E(level, ...) printf("[E%d] %s(%d) %s: ", level, __FILE__, __LINE__, __func__), printf(__VA_ARGS__)
使い方はログ出力時に第1引数に警告・異常レベルを指定します。
int main(void)
{
if (num > 10)
{
DEBUG_PRINT_W(2, "想定外の値範囲 \n"); // 警告ログ出力
}
if (func() < 0)
{
DEBUG_PRINT_E(1, "致命的エラー発生\n"); // 異常ログ出力
}
return 0;
}
[W2] C:\LearningC\Project1\main.c(27) main: 想定外の値範囲
[E1] C:\LearningC\Project1\main.c(32) main: 致命的エラー発生
ログの先頭に「W2」や「E1」といった警告・異常のレベル付きログができあがりました。
大量に出力されたログの中から、これらのキーワードを検索しフィルタリングすることで重要なログを見落とさないといったことができるようになります。
これはあくまでも一つの定義例でしかありません。自分なりに出力したいログの構成を検討し独自のログシステムを構築するとよいでしょう。