MyTetra Share
Делитесь знаниями!
Небольшой логгер стека вызовов для C++
Время создания: 03.08.2012 10:19
Текстовые метки: c++, отладчик, отладка, дебаг, дебаггер
Раздел: Компьютер - Программирование - Язык C++ (Си++)
Запись: xintrea/mytetra_syncro/master/base/1343974797n9xn3767e5/text.html на raw.github.com


На написание этого топика меня сподвиг топик "Какие кодотрюки вы знаете?", и я хотел было поделиться данным логгером там, но автор просил «без фанатизма», и желал видеть такие трюки, на понимание которых требуется не больше пяти-десяти секунд, поэтому я решил вынести это дело в отдельный топик, т.к. по-быстрому такое взглядом не окинешь.

Будет рассмотрен небольшой, но иногда довольно полезный класс, плюс небольшой трюк с макросами, позволяющие проводить первичный анализ стека вызовов (call stack) прямо в stdout, в процессе работы программы. Разумеется, на stdout свет клином не сошёлся, и можете перенаправить хоть в файл, хоть куда-нибудь ещё — я лишь демонстрирую общий принцип.

Сразу договоримся:

  1. злоупотребление макросами — зло
  2. ничего нового и сверхъестественного в данной статье нет, она будет понятна даже новичку (на них и рассчитана)
  3. данный приём мало применим (или вообще не применим) в многопоточной среде
  4. реализация не претендует на идеальность, полноту, и уж тем более уникальность
  5. данный приём ни в коем случае не заменяет, а лишь дополняет дебаггер


Но если при написании программы вы не раз писали что-то вроде

printf("Entering Foo()\n");

для мониторинга входа в ту или иную функцию, то вы пришли как раз по адресу.

* * *


Итак, мы постараемся облагородить это самое printf("Entering Foo()\n") и выжать из него максимум. Первое, что приходит на ум — это заменить ручное печатание имени функции на предопределённый макрос __FUNCTION__, который содержит строку (т.е. const shar*) с именем обрамляющей функции:

printf("Entering %s()\n", __FUNCTION__);


А для того, чтобы не захламлять код визуально и не создавать отвлекающих факторов при чтении, запрячем это дело под макрос:

#define LOG_TRACE printf("Entering %s()\n", __FUNCTION__);


Теперь если у нас есть какой-нибудь лапшевидный код, то аккуратно расставив макросы LOG_TRACE в начале каждой функции получим что-то вроде такого:

#include <stdio.h>

#define LOG_TRACE printf("Entering %s()\n", __FUNCTION__);

void abc() {

LOG_TRACE

}

void foo() {

LOG_TRACE

abc();

}

void bar() {

LOG_TRACE

foo();

abc();

}

int main(int argc, char* argv[]) {

bar();

return 0;

}


При его исполнении в консоль выведется

Entering bar()

Entering foo()

Entering abc()

Entering abc()


Уже кое-что. Но мало. Однако если вспомнить, что помимо макроса __FUNCTION__ у нас есть не менее замечательные макросы __FILE__ и __LINE__, то в дополнение к имени функции мы можем выводить ещё и имя файла и номер строки:

#define LOG_TRACE printf("Entering %s() (%s:%d)\n", __FUNCTION__, __FILE__, __LINE__);

Получим:

Entering bar() (main.cpp:23)

Entering foo() (main.cpp:18)

Entering abc() (main.cpp:14)

Entering abc() (main.cpp:14)


Уже лучше — сразу видно, где чего искать.

Не будем тянуть кота за хвост и сделаем так, чтобы логгировался не только вход, но и выход из функции. На этом этапе мы расстанемся с уютной сишечкой и перейдём к её плюсатому отпрыску.

Что у нас происходит при выходе из функции (да и любой другой области видимости)? Происходит очистка стека от того, что в него было положено в теле функции (области видимости). Технически не совсем очистка, а только сдвиг указателя верхушки стека, но назовём это так, ибо нас интересует не что иное, как разрушение созданных не стеке объектов при покидании области видимости, в связи с чем вызываются их деструкторы.

Так что если мы теперь заменим функцию-логгер на объект схожего поведения, то сможем мониторить не только вход в функцию, но и выход из неё.

Заведём класс TraceLogger, который в конструкторе будет сообщать о входе в функцию, а в деструкторе радостно рапортовать о выходе.

TraceLogger.h:

class TraceLogger {

public:

TraceLogger(const char* fileName,

const char* funcName,

int lineNumber);

~TraceLogger();

private:

const char* _fileName;

const char* _funcName;

};

#define LOG_TRACE TraceLogger traceLogger(__FILE__, __FUNCTION__, __LINE__);



Теперь за макросом скрывается создание объекта на стеке с передачей ему в конструкторе имени файла, имени функции и номера строки. Имена файла и функции мы запомним — пригодятся в деструкторе. В данном случае можно не создавать копии строк, а ограничиться указателями на них, т.к. время жизни объекта ограничено телом функции, и именно в течение этого отрезка времени остаются валидными строки, в которые разворачиваются макросы __FILE__ и __FUNCTION__ при препроцессинге.

Реализация методов выглядит так:

TraceLogger.cpp:

TraceLogger::TraceLogger(const char* fileName,

const char* funcName,

int lineNumber)

{

_fileName = fileName;

_funcName = funcName;

std::cout << "Entering " << _funcName << "() - (" << _fileName << ":" << lineNumber << ")" << std::endl;

}

TraceLogger::~TraceLogger() {

std::cout << "Leaving " << _funcName << "() - (" << _fileName << ")" << std::endl;

}



А вывод, соответственно, так:

Entering bar() - (main.cpp:19)

Entering foo() - (main.cpp:14)

Entering abc() - (main.cpp:10)

Leaving abc() - (main.cpp)

Leaving foo() - (main.cpp)

Entering abc() - (main.cpp:10)

Leaving abc() - (main.cpp)

Leaving bar() - (main.cpp)


Глядя на такое, на языке вертится фраза «Вот бы ещё к этому сделать отступы!», не так ли? Не вопрос! Заведём статический член класса, в котором будем хранить строку-отступ (тупо несколько пробелов) и будем выводить её в начале лог-строки. При создании нового экземпляра (что происходит при входе в очередную функцию) будем увеличивать отступ, а при его разрушении (что происходит в момент выхода из функции) будем его уменьшать.

TraceLogger.h:

class TraceLogger {

...

private:

...

static std::string Indent;

};


TraceLogger.cpp:

std::string TraceLogger::Indent;

TraceLogger::TraceLogger(const char* fileName,

const char* funcName,

int lineNumber)

{

_fileName = fileName;

_funcName = funcName;

std::cout << Indent << "Entering " << _funcName << "() - (" << _fileName << ":" << lineNumber << ")" << std::endl;

Indent.append(" ");

}

TraceLogger::~TraceLogger()

{

Indent.resize(Indent.length() - 2);

std::cout << Indent << "Leaving " << _funcName << "() - (" << _fileName << ")" << std::endl;

}

И теперь наш вывод выглядит так:

Entering bar() - (main.cpp:19)

Entering foo() - (main.cpp:14)

Entering abc() - (main.cpp:10)

Leaving abc() - (main.cpp)

Leaving foo() - (main.cpp)

Entering abc() - (main.cpp:10)

Leaving abc() - (main.cpp)

Leaving bar() - (main.cpp)


Ура! Теперь в любой момент выполнения программы можно наглядно видеть, в какой функции мы в данный момент находимся и как мы туда, собственно, попали. Ну и если что-то упало, то сразу видно, где именно (ещё до того, как расчехлить gdb и скормить ему корку).

Что ещё можно сделать? Конечно же, отключить всё это безобразие в релиз-версии:

TraceLogger.h:

#ifdef DEBUG

#define LOG_TRACE TraceLogger logger(__FILE__, __FUNCTION__, __LINE__);

#else

#define LOG_TRACE

#endif


И теперь в релиз-версии все наши LOG_TRACE банально пусты. А для сохранения чистоты бинарника можно вообще выкусить весь класс целиком, упрятав и объявление, и реализацию за #ifdef DEBUG — это я вам оставлю для самостоятельной доработки. Как и таймстампы в начале строки — они тоже бывают весьма полезны.

На этом всё. Надеюсь, кому-нибудь окажется полезным.

Happy coding!

Так же в этом разделе:
 
MyTetra Share v.0.59
Яндекс индекс цитирования