Небольшой логгер стека вызовов для 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!
    Share post

    Comments 38

      +2
      Осталось только положить отступы не в статик, а в TLS, чтобы они не поломались в многопоточном приложении. А чтобы совсем хорошо было — добавить и std::flush, тогда при падении будет видно намного больше.
        +4
        Если несколько потоков будет выводить логи, да еще и с отступами, то в файле лога будет каша.
        +3
        std::endl вызывает flush.
          +1
          Основная проблема логов в многопоточной среде — влияние на нормальный ход выполнения программы за счет внесения дополнительных синхронизаций при записи логов.

          При этом можно дойти до такой крайности, когда программа будет кое-как работать при включенных логах, но стоит только логи отключить — тут-же падает.
            0
            А мы тогда включим логи постоянно и перенаправим их в /dev/null — problem solved! :)
        +9
        Советую новичкам научится анализировать Crash Dump-ы с использованием нормального отладчика.

        Дело в том, что по началу логи кажутся проще чем Crash Dump-ы, и новички пытаются логированием заменить работу с отладчиком. Это может быть ошибкой, научитесь использовать все возможности отладчика.

        Также в некоторых случаях стоит освоить работу с ядерным отладчиком для отладки сложных сценариев.
          +3
          Когда программа портит свой стек такой логгер может пригодиться.
            +1
            Даже при переездах по памяти windbg зачастую позволяет втащить интересующие куски, особенно если полный дамп, особенно если с включенным appverifier-ом
            +3
            Советую новичкам научиться пользоваться отладчиком и стараться никогда им не пользоваться. Попытка что-то разбирать с отладчиком означает либо серьезные алгоритмические сложности (для которых отладчик зачастую далеко не самое эффективное средство разбирательства), либо обилие bad practices, которые создали проблемы на пустом месте.

            Есть масса других, более эффективных инструментов — продуманная система тестов, статические проверки, lint'ы и т.д.
              0
              В этом есть доля истины, но этот совет лучше давать уже не новичкам.

              Новичкам необходимо понимать как работает их код, для этого отладчик — именно то, что нужно.
              Под отладчиком можно пошагово смотреть что происходит в коде, смотреть значения всех переменных и т.п.
                +1
                Ну, в таком виде — да, полезно, но разве что на самом начальном этапе обучения.

                Пошаговый просмотр и вообще трассировка программы — это такое специальное зло, которое надо искоренять :) У программы есть блоки разных уровней, какая-то модульная структура. Единица отладки и тестирования — модуль. Если хочется проверить, что он себя ведет так, как надо — то процедура проверки не проделывается руками, а записывается в виде теста, проверки — в виде assert'ов.
                  +3
                  А вообще я говорил не о пошаговой отладке, а об анализе падений программы в первую очередь.

                  То есть когда программа падает, она создает dump своего состояния, который затем отправляется на сайт Microsoft, откуда его можно скачать, если зарегистрировать свою компанию и версию продукта. См. Windows Error Reporting.

                  Такие дампы поступают от пользователей, у которых происходят критические сбои программы.

                  Также дамп можно создать вручную, если программа к примеру зависла.
                  При том на Windows 7 это можно сделать прямо из Task Manager-а.

                  Так вот, умение анализировать такие дампы весьма необходимо, т.к. без этого невозможно достоверно узнать причину падения, приходится только догадываться.
                  Но сделать такой анализ порой не так уж просто, т.к. программа будет релизной и придется анализировать ассемблерный код. Делается это при помощи мощных отладчиков, таких как WinDBG.

                  Также стоит помнить о замечательной возможности отладчика подключатся удаленно к работающей программе по сети. К примеру у тестировщиков воспроизвелось странное поведение программы, можно подключится к программе и проанализировать ее внутренне состояние.

                  И уж совсем тяжелая артиллерия — ядерный отладчик, это когда отладчик подключается к самой операционной системе и отлаживается вся операционная система со всеми программами. Так обычно отлаживаются драйвера, но и простые программы тоже можно отлаживать, к примеру на этапе загрузки системы, или при сложном взаимодействии нескольких процессов.
                    +2
                    >>Если хочется проверить, что он себя ведет так, как надо — то процедура проверки не проделывается руками, а записывается в виде теста, проверки — в виде assert'ов.

                    Это все прекрасно и необходимо, но всего не предугадаешь. Программы все равно будут сбоить, портить память, зависать и т.п. И никакие юнит-тесты это не исправят.

                    Вот как Вы проанализируете deadlock программы при помощи асертов?

                    Под отладчиком (WinDBG) можно хоть посмотреть кто залочил критическую секцию или мьютекс.
                    Посмотреть состояние всех потоков, памяти и т.п.
                  +3
                  Это всё хорошо работает в стране розовых единорогов и сферических коней в вакууме. Ещё это хорошо работает для программ на 1000 строк. Но это плохо работает в реальном мире, где исходный код продуктов может иметь возраст 15 лет и больше, где код объемом в миллионы строк писали в общей сложности сотни людей, разного опыта и поколений, где применялись разные практики и парадигмы.
                +1
                Кому не нужны велосипеды, но хочется схожего функционала могут использовать boost.log
                  +3
                  Какой у вас компилятор? У msvc, например, есть опция для «инструментирования» каждого входа (и выхода) в функцию. Думаю, у вашего компилятора (если это не msvc) тоже что-то подобное есть.
                    0
                    А зачем? Для этого есть профайлеры. Во время ошибки тоже можно определить.
                      +1
                      Имхо, стоящая идея. Довольно просто, но действенно. Разве что, для пущей совместимости я бы сделал с sprintf, а не с std::string и cout.
                        +6
                        Заходя под кат надеялся увидеть что-то типа: svn.pld-linux.org/svn/backtracexx.
                        В GCC и MSVS есть все средства для расчета call stack'a, и не надо ничего в каждую функцию добавлять.
                        В собственном продукте я реализовывал базовые классы исключение с использованием подобного функционала, чтобы у любого исключения можно было спросить call stack на момент его генерации. Если такое исключение никем не поймано, то в лог выводится call stack этого исключения.
                        Плюс такого подхода, что при наличии pdb файлов он работает и в Release конфигурации.
                        В остальных случаях, как по мне, call stack удобно видеть при выводе ошибки в лог файл, но никак не на каждую функцию при нормальной работе программы.
                          +3
                          Есть один неприятный момент: стек вызовов обычно хотят печатать после получения SIGSEGV/SIGBUS, но есть ненулевая вероятность (и на практике такое встречается не слишком редко), что кто-то проедется по стеку и вытащить вызовы функций гццшными функциями будет нельзя. + ещё при их использовании надо крайне аккуратно с памятью работать. Коллега подсказал, что в gdb есть свои функции для раскручивания стека, и что они действительно лучше работают, в чём он убеждался на практике.
                            0
                            Согласен. Но я считаю лучше хотя бы такой механизм чем ничего. Не всегда есть возможность использовать gdb. У нас иногда случается, что определенная ошибка повторяется только на компьютере клиента, и нет возможности ехать к нему на другой континент. Тогда хотя бы обрывки call stack'а очень помогают в определении не правильного поведения.
                          +4
                            0
                            Мы в свое время развлекались с структурным логгером (самописанным, кода там на пару сотен строчек), который умеет в XHTML результаты дампить. Для проекта, работающего с изображениями это оказалось очень удобно:

                              0
                              Желательно переделать LOG_TRACE так:
                              #define LOG_TRACE() TraceLogger traceLogger(__FILE__, __FUNCTION__, __LINE__)
                              

                              Чтобы её использование выглядело как вызов функции и заканчивалось точкой с запятой:
                              void abc() {
                                  LOG_TRACE();
                              }
                              

                              Так читать проще и редакторы не сходят с ума, когда автоматические отступы делают.
                                +2
                                Точка с запятой отделяет выражения одно от другого. При этом выражения могут быть пустыми.

                                Поэтому ничего страшного нет в коде: int main() { ;;; }

                                Поэтому, например, я всегда в конце макросов ставлю точку с запятой: кто хочет приписывает в конце вызова еще одну, кому лень — не нужно.
                                  +2
                                  При использовании макросов в операциях "? :" и "," точка с запятой окажутся лишними. А если под макросом скрывается возвращаемое значение, то, при наличии точки с запятой, его нельзя будет использовать в условных операторах.
                                    0
                                    Речь о конкретно этом слушае. А так вы правы, да.
                                0
                                __FUNCTINON__ если не ошибаюсь, это расширение.
                                А вот в с++11 добавлен __func__, используйте лучше его. Или хотя бы учитывайте его возможное применение в будущем
                                  0
                                  Что ещё можно сделать? Конечно же, отключить всё это безобразие в релиз-версии
                                  Вот именно для Release-версии это и нужно! Если вам надо программу из beta-версии перевести в качественный и отказоустойчивый продукт, то она должна уметь сообщать свое состояние в случае ошибки. «Состояние» — это 1) потоки, 2) стек функций в них и 3) аргументы функций. Имея эту информацию, можно достоверно понять что произошло.
                                  Информация по потокам — несложно. Так же вполне несложно добавлять стек вызовов для каждого потока. А вот аргументы — это уже посложней…
                                  И, если уж идею развивать дальше, то хорошо бы, чтобы вся эта информация была бы… ну-у, свернутой, что ли. А вот если произошла ошибка — то ее развернуть в полный вид. Т. е. в случае корректной работы подробная (и вообще какая бы то ни было) информация о состоянии не нужна. А вот в случае ошибки нужно побольше информации.
                                  Altap Salamander (зарубежный платный и весьма качественный аналог Total Commander-а) имеет такую функцию. Он в случае падения пишет в свою директорию salamander.bug. При старте, если он там обнаруживает этот файл, он предлагает его выслать разработчикам. Я туда заглядывал — там есть весь стек и состояние операционной системы. Вот аргументов функций нет.
                                    0
                                    Я, как говорится, «дал удочку и показал, где река», а пытливый ум всегда найдёт способ что-нибудь улучшить.

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

                                    Можно завести отдельный логгер для каждого потока и вести для отдельные логи.

                                    И так далее…
                                      0
                                      она должна уметь сообщать свое состояние в случае ошибки. «Состояние» — это 1) потоки, 2) стек функций в них и 3) аргументы функций.
                                      Вы всё правильно пишете, только вот логгировать каждый вызов функции, включая аргументы — сомнительное решение. Программа должна уметь в случае критической ошибки сохранять свой дамп и завершаться без порчи пользовательских данных. А при наличии у разработчика отладочных символов он из этого дампа вынет и стеки всех потоков, и аргументы вызываемых функций и много чего ещё.
                                      +2
                                      > предопределённый макрос __FUNCTION__

                                      BOOST_CURRENT_FUNCTION более переносимо.
                                        0
                                        Можно еще timestamp'ы добавить.
                                        Многие не учитывают что такая штука может оказаться полезной при embedded отладке, когда из средств отладки только uart :)
                                          0
                                          Мне кажется, что любой С++ программист рано или поздно пытался написать свою версию логгера стека вызовов. И я в том числе. Но потом научился пользоваться WinDbg.
                                            +2
                                            Приведу пример ещё одного проекта где это всё уже давно реализовано и хорошо работает, не требует никакого изменения кода, и запросто можно держать активным даже в deployed проекте (просто сохранять крашы в лог на пользовательских компьютерах и к примеру посылать их разработчикам когда надо. И это лучше цем посылать обычные crashdump — лог можно просто прочитать и чтобы получить информацию о функциях, стэке и т.д., не нужно будет его загружать никуда, как с crashdumps).: www.codeproject.com/KB/threads/StackWalker.aspx
                                              0
                                              Отличная статья, в мемориз.

                                              Люто бешено проплюсовал.

                                              Что-то как-то руки все не доходили сделать нормальный отладочный вывод, мучился с префиксами WRN, ERR, уровнем отладочных сообщений, но это все не то.
                                                0
                                                В деструкторе TraceLogger с помощью функции std::uncaught_exception можно проверить, как завершает работу функция: это нормальный возврат или было выброшено исключение.

                                                Only users with full accounts can post comments. Log in, please.