Логирование как метод отладки программного обеспечения. Часть первая (основы)

Логирование кода как метод отладки программного обеспечения вероятно «родилось» из отладки путём вывода значений переменных на консоль. Результат логирования, т.е. то, что выводится на консоль, в файл и т.п. называется логом.

Де-факто логирование стало настолько универсальным методов отладки, что например в 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 мы сэкономили сотни строк кода. Однако теперь трудно понять,  какое значение переменной какому вызову соответствует. Есть варианты решения этой проблемы:

  1. Передавать в функцию foo дополнительный параметр (уникальный идентификатор места вызова), например, «this call of foo» или «last call of foo» и т.п. Придётся придумать N таких идентификаторов, где N-количество вызов функции foo.
  2. Попробовать как-то автоматизировать вариант №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.  Можно «разобрать код по полочкам», но если кода будет очень много, то понять весь код вы не сможете. Особенно, если дефект нужно будет срочно исправить в считанные часы. Какие есть ещё проблемы у предыдущего примера кода:

  1. Не логируются входные значения функций. Если бы они были, то можно было  бы, по крайней мере,  легко понять прошло ли условие в функции foo1 или нет.
  2. Форматная строка, передаваемая в printf, дублируется.
  3. Если залогируем входные значения функций, то в более сложных примерах всё равно не будет понятно, где функция вызывается отдельно, а где её вызов вложен в другую функцию.
  4. Если залогировать входные значение, то придётся их как-то именовать в логе.
  5. «../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 позволяет полностью отключать логирование в продакшен коде и включать его в случае необходимости. Таким образом, можно безопасно оставлять логирование в коде.

Продолжение следует…

Запись опубликована в рубрике Программирование с тэгами , , , , . Создать закладку наpermalink. Оставить комментарийили trackback:Trackback URL.

Оставить комментарий

Ваш e-mail никогда не будет опубликован или передан третьим лицам. Обязательные поля отмечены *

*
*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>