Небольшой логгер стека вызовов для C++

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

Будет рассмотрен небольшой, но иногда довольно полезный класс, плюс небольшой трюк с макросами, позволяющие проводить первичный анализ стека вызовов (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!

Автор: Mezomish