Логирование кода как метод отладки программного обеспечения вероятно «родилось» из отладки путём вывода значений переменных на консоль. Результат логирования, т.е. то, что выводится на консоль, в файл и т.п. называется логом.
Де-факто логирование стало настолько универсальным методов отладки, что например в embedded программировании без логирования практически невозможно отладить код, а о серверных логах наверно слышали все.
Рассмотрим пример логирования кода с помощью printf-ов:
#include <cstdio>
int foo(const int param)
{
return param + 1;
}
int main()
{
int x1 = foo(1);
int x2 = foo(x1);
printf("value of x1: %d\n", x1);
printf("value of x2: %d\n", x2);
return 0;
}
Результат:
value of x1: 2 value of x2: 3
Можно заметить, что вызов printf в обоих случаях практически одинаков и можно было бы написать утилитную функцию, которая бы принимала значение типа int и выводила его на консоль с форматом «value of x%d: %d». Но если бы таких вызовов было бы несколько сотен, то количество строк кода от этого бы не уменьшилось. Поэтому лучше внести printf вовнутрь функции «foo» следующим образом:
#include <cstdio>
int foo(const int param)
{
int ret_val = param + 1;
printf("value of ret_val: %d\n", ret_val);
return ret_val;
}
int main()
{
int x1 = foo(1);
int x2 = foo(x1);
return 0;
}
Результат:
value of ret_val: 2 value of ret_val: 3
Для случая сотен вызовов функции foo мы сэкономили сотни строк кода. Однако теперь трудно понять, какое значение переменной какому вызову соответствует. Есть варианты решения этой проблемы:
- Передавать в функцию foo дополнительный параметр (уникальный идентификатор места вызова), например, «this call of foo» или «last call of foo» и т.п. Придётся придумать N таких идентификаторов, где N-количество вызов функции foo.
- Попробовать как-то автоматизировать вариант №1.
Вариант №1 очень трудозатратный. Как можно реализовать вариант №2? Можно использовать технологию wrapper (от анг. обёртка.) с предопределёнными макросами препроцессора __LINE__ и __FILE__, при которой вызывающий функцию код не меняется. Исправленный вариант кода:
#include <cstdio>
#define foo(param) __foo(param, __LINE__, __FILE__)
int __foo(const int param, int line, char* file)
{
int ret_val = param + 1;
printf("This function is caused at line# %d in %s. value of ret_val: %d\n",
line, file, ret_val);
return ret_val;
}
int main()
{
int x1 = foo(1);
int x2 = foo(x1);
return 0;
}
Результат:
This function is caused at line# 241 in ../src/main.cpp. value of ret_val: 2 This function is caused at line# 242 in ../src/main.cpp. value of ret_val: 3
Что ещё нужно для отладки? Во-первых, у этого подхода есть недостаток: пришлось функцию foo переименовать в «__foo()». Для отладки такой вариант приемлем, но для продакшен кода не всегда. Особенно если функция находится в модуле, для исправления которого у вас нет прав. О решении этой проблемы чуть позднее во второй части.
Во-вторых, если таких функций будет несколько, то лог станет нечитаемым. Пример:
#include <cstdio>
#define foo(param) __foo(param, __LINE__, __FILE__)
#define foo1(param) __foo1(param, __LINE__, __FILE__)
int __foo(const int param, int line, char* file)
{
int ret_val = param + 1;
printf("This function is caused at line# %d in %s. value of ret_val: %d\n",
line, file, ret_val);
return ret_val;
}
int __foo1(const int param, int line, char* file)
{
int ret_val = param - 1;
printf("This function is caused at line# %d in %s. value of ret_val: %d\n",
line, file, ret_val);
return ret_val;
}
int main()
{
int x1 = foo(1);
int x2 = foo(foo1(x1));
return 0;
}
Результат:
This function is caused at line# 255 in ../src/main.cpp. value of ret_val: 2 This function is caused at line# 256 in ../src/main.cpp. value of ret_val: 1 This function is caused at line# 256 in ../src/main.cpp. value of ret_val: 2
Обратите внимание, что две строки (2-3) имеют одинаковый номер строки кода (256), но разные возвращаемые значения Сложно ориентироваться в логе, если одинаковых строк (примитивов) много. Другой недостаток: нельзя найти конкретный лог функции по её имени. Можно в ручную заменить фразу «this function» на «foo function» и «foo1 function» соответственно. Но если таких функций будет много, то это будет рутинно и трудоёмко. Кроме этого, при изменении имени функции придётся менять логирования, что неудобно. Здесь приходит на помощь препроцессор с предопределённым макросом __FUNCTION__. Улучшенная версия кода:
#include <cstdio>
#define foo(param) __foo(param, __LINE__, __FILE__)
#define foo1(param) __foo1(param, __LINE__, __FILE__)
int __foo(const int param, int line, char* file)
{
int ret_val = param + 1;
printf("%s function is caused at line# %d in %s. value of ret_val: %d\n",
__FUNCTION__, line, file, ret_val);
return ret_val;
}
int __foo1(const int param, int line, char* file)
{
int ret_val = param - 1;
printf("%s function is caused at line# %d in %s. value of ret_val: %d\n",
__FUNCTION__, line, file, ret_val);
return ret_val;
}
int main()
{
int x1 = foo(1);
int x2 = foo(foo1(x1));
return 0;
}
Результат:
__foo function is caused at line# 255 in ../src/main.cpp. value of ret_val: 2 __foo1 function is caused at line# 256 in ../src/main.cpp. value of ret_val: 1 __foo function is caused at line# 256 in ../src/main.cpp. value of ret_val: 2
Проблема решена и теперь видим практически историческую последовательность (trace) вызов функций в программе. Может ли дебаггер, которым вы пользуетесь, показать, что происходило в прошлом после выполнения программы? Многие ответят «нет». (Прим. В MS Visual Studio С# появился исторический дебаггер, способный «вернуть в прошлое» на несколько шагов исполнения назад. Трудно предсказать, когда исторические дебаггеры появятся для C++ и других языков программирования.)
Как вы наверно уже догадались или увидели, предложенный выше код опять имеет ряд недостатков. Предположим, добавили условие в функцию __foo1:
#include <cstdio>
#define foo(param) __foo(param, __LINE__, __FILE__)
#define foo1(param) __foo1(param, __LINE__, __FILE__)
int __foo(const int param, int line, char* file)
{
int ret_val = param + 1;
printf("%s function is caused at line# %d in %s. value of ret_val: %d\n",
__FUNCTION__, line, file, ret_val);
return ret_val;
}
int __foo1(const int param, int line, char* file)
{
int ret_val = 1;
if ((param % 2) == 0)
{
ret_val = foo(param + 1);
}
printf("%s function is caused at line# %d in %s. value of ret_val: %d\n",
__FUNCTION__, line, file, ret_val);
return ret_val;
}
int main()
{
int x1 = foo(foo1(1));
int x2 = foo(foo1(x1));
return 0;
}
Результат:
__foo1 function is caused at line# 297 in ../src/main.cpp. value of ret_val: 1 __foo function is caused at line# 297 in ../src/main.cpp. value of ret_val: 2 __foo function is caused at line# 286 in ../src/main.cpp. value of ret_val: 4 __foo1 function is caused at line# 298 in ../src/main.cpp. value of ret_val: 4 __foo function is caused at line# 298 in ../src/main.cpp. value of ret_val: 5
По такому логу трудно понять, где вызов функции foo был отдельно, а где из функции foo1. Можно «разобрать код по полочкам», но если кода будет очень много, то понять весь код вы не сможете. Особенно, если дефект нужно будет срочно исправить в считанные часы. Какие есть ещё проблемы у предыдущего примера кода:
- Не логируются входные значения функций. Если бы они были, то можно было бы, по крайней мере, легко понять прошло ли условие в функции foo1 или нет.
- Форматная строка, передаваемая в printf, дублируется.
- Если залогируем входные значения функций, то в более сложных примерах всё равно не будет понятно, где функция вызывается отдельно, а где её вызов вложен в другую функцию.
- Если залогировать входные значение, то придётся их как-то именовать в логе.
- «../src/main.cpp» — слишком длинный путь, достаточно было бы иметь только имя файла «main.cpp» (обычно уникально в рамках одного проекта).
Эти проблемы решаются следующем образом:
#include <cstdio>
#include <cstring>
inline const char* __BaseFileName( const char* file_name )
{
const char* ret_val;
ret_val = strrchr( file_name, '/' );
if (ret_val != NULL)
{
++ret_val;
}
else
{
ret_val = file_name;
}
return ret_val;
}
#define LOG_INT(value) printf("[%d]%s=%d\n", __LINE__, #value, (int)value)
#define LOG_ENTRY(l, f) \
printf("%s[%s,%d] is called from %s:%d ENTER\n", \
__FUNCTION__, __BaseFileName(__FILE__), __LINE__, __BaseFileName(f), l)
#define LOG_EXIT() printf("%s[%d] EXIT\n", __FUNCTION__, __LINE__)
#define foo(param) __foo(param, __LINE__, __FILE__)
#define foo1(param) __foo1(param, __LINE__, __FILE__)
int __foo(const int param, int line, char* file)
{
int ret_val;
LOG_ENTRY(line, file);
LOG_INT(param);
ret_val = param + 1;
LOG_INT(ret_val);
LOG_EXIT();
return ret_val;
}
int __foo1(const int param, int line, char* file)
{
int ret_val = 1;
LOG_ENTRY(line, file);
LOG_INT(param);
if ((param % 2) == 0)
{
ret_val = foo(param + 1);
}
LOG_INT(ret_val);
LOG_EXIT();
return ret_val;
}
int main()
{
int x1 = foo(foo1(1));
int x2 = foo(foo1(x1));
return 0;
}
Результат (добавление отступов легко автоматизируется):
__foo1[main.cpp,372] is called from main.cpp:388 ENTER
[373]param=1
[380]ret_val=1
__foo1[381] EXIT
__foo[main.cpp,356] is called from main.cpp:388 ENTER
[358]param=1
[362]ret_val=2
__foo[363] EXIT
__foo1[main.cpp,372] is called from main.cpp:389 ENTER
[373]param=2
__foo[main.cpp,356] is called from main.cpp:377 ENTER
[358]param=3
[362]ret_val=4
__foo[363] EXIT
[380]ret_val=4
__foo1[381] EXIT
__foo[main.cpp,356] is called from main.cpp:389 ENTER
[358]param=4
[362]ret_val=5
__foo[363] EXIT
Имена входных переменных функций и их значения автоматически логируются с вызовом LOG_INT. Форматная строка не дублируется, а реюзается. Добавление двух разных макросов LOG_ENTRY/EXIT позволяет определить в логе, что происходило внутри функций. Таким образом, проблема определения вложенных вызовов функций решена. Имя файла сокращено до только его базовой части. Код стал значительно более универсальным. Совершенству нет придела ;).
Как же быть после отладки, «выкидывать» код логирования? Конечно, нет. Разумней накапливать логирования в проекте, чтобы при необходимости быстрой отладки всегда иметь детальный лог. Но если логирование оставить, в коде будут следующие проблемы:
- увеличится размер исполняемого файла;
- для приложений критичных к производительности, printf может добавить значительный overhead на производительность;
- как быть если при добавлении логирования забыли, например, макрос LOG_EXIT, но добавили LOG_ENTRY, не «поедет» ли логирование при раскручивании вложенности.
Эти проблемы решаются следующим образом:
#define LOGGING_ON 1
#include <cstdio>
#if LOGGING_ON
#include <cstring>
...
#define LOG_ENTRY(l, f) \
{ \
printf("%s[%s,%d] is called from %s:%d ENTER\n", \
__FUNCTION__, __BaseFileName(__FILE__), __LINE__, __BaseFileName(f), l)
#define LOG_EXIT() \
} \
printf("%s[%d] EXIT\n", __FUNCTION__, __LINE__)
#else /* LOGGING_ON */
#define LOG_INT(value) ((void)0)
#define LOG_ENTRY(l, f) ((void)0)
#define LOG_EXIT() ((void)0)
#endif /* LOGGING_ON */
Вложенные скобки в макросах ENTRY/EXIT позволяют выявлять на этапе компиляции пропущенные ENTRY и EXIT, а директива LOGGING_ON позволяет полностью отключать логирование в продакшен коде и включать его в случае необходимости. Таким образом, можно безопасно оставлять логирование в коде.
Продолжение следует…