Логирование кода как метод отладки программного обеспечения вероятно «родилось» из отладки путём вывода значений переменных на консоль. Результат логирования, т.е. то, что выводится на консоль, в файл и т.п. называется логом.
Де-факто логирование стало настолько универсальным методов отладки, что например в 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 позволяет полностью отключать логирование в продакшен коде и включать его в случае необходимости. Таким образом, можно безопасно оставлять логирование в коде.
Продолжение следует…