小さい頃はエラ呼吸

いつのまにやら肺で呼吸をしています。


【VC++】デバッグログ出力時に呼び出し元関数名を出力する

はじめに

デバッグログを出力する関数の設計時に、呼び出し元の関数名を引数に含めるを忘れてしまいました。このため、テスト時にデバッグログを出力させたら、どの関数が吐いたログか分かりにくい状態となってしまった。

関数の引数を変更しようにも、呼び出し元はたくさんあって、呼び出し箇所すべての引数変更を行うのはちょっと大変です。
そんなとき、デバッグログ出力関数側から呼び出し元関数名を取得する方法を紹介します。

この記事は、以下のページを参考にさせていただきました。

ログ出力時の呼び出し元関数名を出力する - 白メモログ出力時の呼び出し元関数名を出力する - 白メモ

環境
  • Visual Studio 2005 + Windows7
デバッグログ出力時に呼び出し元関数名を出力する

デバッグログ出力関数から、呼び出し元関数名を取得するには、__FUNCTION__マクロと__VA_ARGS__マクロを使います。

以下のサンプルプログラムは、呼び出し元からはLog_dというデバッグログ出力関数を呼び出します。Log_d関数を内部でOutputLog関数を呼び出すよう、define定義を行い、__FUNCTION__マクロで呼び出し元関数名を渡します。

#define Log_d(lpszFormat, ...) OutputLog(_T(__FUNCTION__), lpszFormat, __VA_ARGS__)
デバッグログ出力関数

OutputLog関数は、関数名とデバッグログに出力する内容を引数で、受け取りファイルに出力します。このとき、現在時刻を取得し、あわせてログに出力します。

void OutputLog(LPCTSTR lpszFuncName, LPCTSTR lpszFormat, ...)
{
  va_list args;
  va_start(args, lpszFormat);
  TCHAR szBuffer[1024] = { 0 };
  _vstprintf(szBuffer, lpszFormat, args);

  // 現在時刻の取得
  SYSTEMTIME st;
  GetSystemTime(&st);
  char szTime[25] = { 0 };
  wsprintf(szTime, "%04d/%02d/%02d %02d:%02d:%02d %03d",
       st.wYear, st.wMonth, st.wDay,
       st.wHour + 9, st.wMinute, st.wSecond, st.wMilliseconds);

  FILE *fp;
  fp = fopen("c:\\debug.csv", "a");
  // 現在時刻,[関数名],任意のログ出力内容
  fprintf(fp, "%s, [%s], %s\n", szTime, lpszFuncName, szBuffer);
  fclose(fp);

  va_end(args);
}
サンプルプログラム

サンプルプログラムを以下に載せます。

#include <windows.h>
#pragma warning ( disable : 4996 )

#define Log_d(lpszFormat, ...) OutputLog(_T(__FUNCTION__), lpszFormat, __VA_ARGS__)
int func1();
int func2();
int func3();

void OutputLog(LPCTSTR lpszFuncName, LPCTSTR lpszFormat, ...)
{
  va_list args;
  va_start(args, lpszFormat);
  TCHAR szBuffer[1024] = { 0 };
  _vstprintf(szBuffer, lpszFormat, args);

  SYSTEMTIME st;
  GetSystemTime(&st);
  char szTime[25] = { 0 };
  wsprintf(szTime, "%04d/%02d/%02d %02d:%02d:%02d %03d",
       st.wYear, st.wMonth, st.wDay,
       st.wHour + 9, st.wMinute, st.wSecond, st.wMilliseconds);

  FILE *fp;
  fp = fopen("c:\\debug.csv", "a");
  fprintf(fp, "%s, [%s], %s\n", szTime, lpszFuncName, szBuffer);
  fclose(fp);

  va_end(args);
}

// サブルーチン1
int func1()
{
  Log_d(_T("デバッグログfunc1"));
  return 0;
}

// サブルーチン2
int func2()
{
  Log_d(_T("デバッグログfunc2"));
  func3();
  return 0;
}

// サブルーチン3
int func3()
{
  Log_d(_T("デバッグログfunc3"));
  return 0;
}

// メインルーチン
int _tmain(int argc, _TCHAR *argv[])
{
  Log_d(_T("デバッグログmain start"));

  int ret;
  ret = func1();
  ret = func2();

  Log_d(_T("デバッグログmain end"));
  return 0;
}
デバッグログの出力内容

上記のサンプルプログラムを実行すると、以下のようなログが出力されます。

2014/07/28 17:39:10 385, [main], デバッグログmain start
2014/07/28 17:39:10 401, [func1], デバッグログfunc1
2014/07/28 17:39:10 401, [func2], デバッグログfunc2
2014/07/28 17:39:10 401, [func3], デバッグログfunc3
2014/07/28 17:39:10 401, [main], デバッグログmain end