На написание этого топика меня сподвиг топик "Какие кодотрюки вы знаете? ", и я хотел было поделиться данным логгером там, но автор просил «без фанатизма», и желал видеть такие трюки, на понимание которых требуется не больше пяти-десяти секунд, поэтому я решил вынести это дело в отдельный топик, т.к. по-быстрому такое взглядом не окинешь.
Будет рассмотрен небольшой, но иногда довольно полезный класс, плюс небольшой трюк с макросами, позволяющие проводить первичный анализ стека вызовов (call stack) прямо в stdout, в процессе работы программы. Разумеется, на stdout свет клином не сошёлся, и можете перенаправить хоть в файл, хоть куда-нибудь ещё — я лишь демонстрирую общий принцип.
Сразу договоримся:
- злоупотребление макросами — зло
- ничего нового и сверхъестественного в данной статье нет, она будет понятна даже новичку (на них и рассчитана)
- данный приём мало применим (или вообще не применим) в многопоточной среде
- реализация не претендует на идеальность, полноту, и уж тем более уникальность
- данный приём ни в коем случае не заменяет, а лишь дополняет дебаггер
Но если при написании программы вы не раз писали что-то вроде
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!
