Введение

Доводилось ли вам когда-нибудь работать над C++ проектом с такой огромной кодовой базой, что понимание того, что на самом деле происходит во время выполнения программы, требует кучи времени и сил? Откуда и какие функции вызываются? Вам когда-нибудь поручали исправить баг в таком проекте, прилагая лишь логи, которые приближают вас к нахождению первопричины проблемы так же, как Моисей к земле обетованной? А попытки воспроизведения бага не дают вам никакой полезной информации? Если ваш ответ да – пожалуйста, присаживайтесь поудобнее.

Поиск решения

В какой-то момент я начал размышлять над тем, какими характеристиками должен обладать инструмент, который мог бы помочь мне лучше понять природу возникающих проблем и багов. Кто-то здесь может спросить — “Разве не для этого придуманы дебаггеры?”. Конечно, дебаггеры очень выручают, если у вас есть доступ к среде, в которой вы можете свободно запускать некорректный код и отлаживать его строчка за строчкой, что, по моему опыту, тоже не всегда так радужно. Но во многих случаях проблема воспроизводима только в инфраструктуре заказчика и экспериментировать на живом теле вам не позволят. Или вы не располагаете необходимым тестовым сетапом. Или источник проблемы кроется в сторонней библиотеке, и у вас нет доступа к ее исходному коду. Или проблема просто слишком сложна, чтобы отлаживать ее традиционными способами. Какой бы ни была причина, иногда альтернативный подход является единственным доступным решением. В итоге я сформировал следующие ограничения на инструмент, который мог бы удовлетворить мои потребности:

• каждый раз, когда вызывается пользовательская функция, это должно быть отражено в логах;

• функции должны быть в demangled виде и представлены в логах в удобочитаемом для пользователя виде;

• логирование должно выполняться из коробки — без необходимости засорять код лишними макросами в начале каждой функции;

• функции из стандартной библиотеки должны быть исключены из логирования — мы хотим избежать ситуации, когда в логах отражены сотни строк выполнения простых операций над контейнерами;

• в логах должны отражаться имя файла и номер строки откуда вызывается данная функция;

• каждое вложение функции добавляет отступ, а возврат из функции удаляет его – в результате во время выполнения формируется дерево стека вызовов, дающее наглядное представление о том, какая функция кем вызвана;

• механизм логирования может быть активирован только в том случае, если он скомпилирован с дебажным определенным флагом – таким образом мы избежим чрезмерных накладных расходов при рядовом выполнении программы;

• должен работать на gcc;

Как бы тщательно я ни шерстил веб, я мог найти решения, которые соответствовали только одному пункту из моих требований. Ни одно из них не могло похвастаться всеми пунктами, поэтому я решил написать свой собственный микро-фреймворк и назвал его Call Stack Logger.

Отправная точка

Во-первых, для начала нам нужен механизм, который позволит вызывать определенные функции каждый раз по факту входа или выхода из каждой функции. Это может казаться немного похожим на аспектно-ориентированное программирование, но разница здесь в том, что вход и выход из функции имеют сигнатуры, уже определенные компилятором. Я говорю о фиче gcc, называемой инструментирование/инструментация функций (function instrumentation). Чтобы активировать ее, мы должны передать в gcc следующий флаг компиляции:

-finstrument-functions

Теперь мы можем определить функции для профилирования кода в любом удобном для нас месте. Я создал файл trace.cpp и поместил туда следующие две функции:

extern "C" __attribute__((no_instrument_function))
void __cyg_profile_func_enter(void *callee, void *caller) {
    // Код, который будет выполняться сразу после входа в функцию.
}

extern "C" __attribute__((no_instrument_function))
void __cyg_profile_func_exit(void *callee, void *caller) {
    // Код, который будет выполняться непосредственно перед выходом из функции.
}

Обе функции принимают в качестве аргументов два указателя на void: callee является указателем на функцию, которая вызывается в данный момент, а caller это точка вызова, который указывает на место (строку кода), откуда вызывается функция. attribute((no_instrument_function)) в сигнатуре функции нужен для ограждения данной функции от инструментирования. Другими словами, мы не хотим, чтобы наши функции для профилирования были инструментированы, чтобы избежать бесконечных вызовов, вызывающих ошибки сегментации. Чтобы сделать этот атрибут немного лаконичнее и нагляднее, мы можем определить макрос:

#ifndef NO_INSTRUMENT
    #define NO_INSTRUMENT __attribute__((no_instrument_function))
#endif

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

#include <stdio.h>

static FILE *fp_trace;

__attribute__ ((constructor))
NO_INSTRUMENT
void trace_begin() {
    fp_trace = fopen("trace.out", "a");
}

__attribute__ ((destructor))
NO_INSTRUMENT
void trace_end() {
    if(fp_trace != nullptr) {
        fclose(fp_trace);
    }
}

После инициализации указателя на файл мы можем использовать его внутри функции __cyg_profile_func_enter. Пока просто будем записывать туда адреса вызываемых функций:

if(fp_trace != nullptr) {
    fprintf(fp_trace, "enter %p\n", callee);
}

И давайте запустим простенький пример:

#include <iostream>
#include <vector>
#include <algorithm>

class A {
public:
    static void foo() {
        std::cout << "static foo \n";
        std::vector<int> vec { 1, 55, 78, 3, 11, 7, 90 };
        std::sort(vec.begin(), vec.end());
    }
};

int main() {
    // Тест логирования статических методов-членов класса.
    A::foo();
    return 0;
}

Файл trace.out будет содержать следующее:

enter 0x5602d9622be5
enter 0x5602d9622f1c
enter 0x5602d9623084
enter 0x5602d96233b2
enter 0x5602d96230fc
enter 0x5602d962342a
enter 0x5602d96239b6
enter 0x5602d9623fa6
…
…
…

Расшифровка адресов

Приведенный выше вывод не очень информативен для нас как для человека, так как мы видим только адреса вызываемых функций, что не сильно облегчает нам процесс отладки. Кроме того, мы сложно не обратить внимание на большое количество записей в лог-файле (в результате мы получили целых 232 строки) вместо всего двух — для main и A::foo(). Откуда они все взялись? Чтобы понять это, нам все-таки придется расшифровать эти адреса. Для этого нам понадобится binutils:

$ sudo apt install binutils-dev

Также для того чтобы получить информацию о динамических символах в исполняемом файле, нам нужно добавить еще одну опцию gcc:

-rdynamic

А также залинковать эти две библиотеки:

-ldl -lbfd

libdl это Dynamic Link Library, которая представляет собой интерфейс для динамического загрузчика и позволяет нам, среди прочего, искать символы, а libbfd это Binary File Descriptor Library, которая нужна для работы с объектными файлами и будет использоваться нами позже.

Теперь мы можем расшифровать адреса. Включите заголовки:

#include <dlfcn.h> // for dladdr
#include <cxxabi.h> // for __cxa_demangle

И теперь вместо наивного логирования адреса функций мы можем определить для __cyg_profile_func_enter следующее тело:

if (fp_trace != nullptr) {
    Dl_info info;
    if (dladdr(func, &info)) {
        int status;
        const char* name;
        char* demangled = abi::__cxa_demangle(info.dli_sname, nullptr, 0, &status);
        if (status == 0) {
            name = demangled ? demangled : "[not demangled]";
        } else {
            name = info.dli_sname ? info.dli_sname : "[no dli_sname]";
        }
        fprintf(fp_trace, "%s (%s)\n", name, info.dli_fname);
        if (demangled) {
            delete demangled;
            demangled = nullptr;
        }
    } else {
        fprintf(fp_trace, "%s\n", "unknown");
    }
}

После компиляции и запуска программы вы увидите в файле trace.out следующее:

main (build/runDemo)
A::foo() (build/runDemo)
std::allocator::allocator() (build/runDemo)
__gnu_cxx::new_allocator::new_allocator() (build/runDemo)
std::vector<int, std::allocator >::vector(std::initializer_list, std::allocator const&) (build/runDemo)
std::_Vector_base<int, std::allocator >::_Vector_base(std::allocator const&) (build/runDemo)
std::_Vector_base<int, std::allocator >::_Vector_impl::_Vector_impl(std::allocator const&) (build/runDemo)
std::allocator::allocator(std::allocator const&) (build/runDemo)
__gnu_cxx::new_allocator::new_allocator(__gnu_cxx::new_allocator const&) (build/runDemo)
std::_Vector_base<int, std::allocator >::_Vector_impl_data::_Vector_impl_data() (build/runDemo)
std::initializer_list::end() const (build/runDemo)
std::initializer_list::begin() const (build/runDemo)
std::initializer_list::size() const (build/runDemo)
std::initializer_list::begin() const (build/runDemo)
void std::vector<int, std::allocator >::_M_range_initialize(int const*, int const*, std::forward_iterator_tag) (build/runDemo)
std::iterator_traits::difference_type std::distance(int const*, int const*) (build/runDemo)
…
…
…

И вот мы снова видим 232 строки расшифрованных функций. Почти все эти функции из стандартной библиотеки и связаны они со всеми операциями, которые вызываются при создании, аллокации, инициализации, сортировке и уничтожении вектора, который мы использовали в нашем примере. Мы всего-то написали и вызвали 3-строчную функцию, а в результате получили такой большой объем информации. Это настолько захламляет наши логи, что мы определенно должны что-то с этим сделать, иначе мы просто утонем в этих функциях. Кроме того, в большинстве случаев нас совершенно не интересуют детали того, что делают стандартные функции, поскольку мы можем позволить себе положиться на то, что они делают именно то, что от них ожидается. Мы хотим сосредоточиться на бизнес-логике, которую формируют наши пользовательские функции, и ограничить внимание механизма логирования только ими.

Исключаем стандартную библиотеку из инструментирования

К счастью, gcc предоставляет нам специальную опцию инструментирования:

-finstrument-functions-exclude-file-list

в которой мы можем перечислить расположение всех заголовков из стандарта C++, которые мы хотели бы исключить из инструментирования, например, /usr/include, /usr/include/c++, /usr/include/x86_64-linux-gnu/c++/10, и т.д.

К сожалению, эти пути могут разниться в зависимости от версии Linux или gcc, поэтому, чтобы упростить задачу, я добавил shell-скрипт в Makefile, чтобы автоматически находить и перечислять все локации заголовков стандартной библиотеки C++ и передавать их в –finstrument-functions-exclude-file-list:

# Ищем заголовочные файлы стандартной библиотеки C++, чтобы исключить их из инструментирования.
CPP_STD_INCLUDES=$(shell ( `gcc -print-prog-name=cc1plus` -v < /dev/null 2>&1 \
                 | LC_ALL=C sed -ne '/starts here/,/End of/p' \
                 | grep -o '/[^"]*' ; \
               `gcc -print-prog-name=cpp` -v < /dev/null 2>&1 \
                 | LC_ALL=C sed -ne '/starts here/,/End of/p' \
                 | grep -o '/[^"]*' ) \
               | cat | sort | uniq | tr '\n' ',' | sed 's/\(.*\),/\1 /' | xargs )

# Исключаем функции для трассировки из инструментирования
CPP_STD_INCLUDES := "${CPP_STD_INCLUDES},include/callStack.h"

CXXFLAGS = -g -Wall -rdynamic -std=c++17 -finstrument-functions -finstrument-functions-exclude-file-list=$(CPP_STD_INCLUDES

С этими изменениями, если мы перекомпилируем и запустим программу, мы получим следующий вывод:

main (build/runDemo)
A::foo() (build/runDemo)

Ну разве так не лучше? Это уже намного ближе к тому, чего мы хотим достичь.

Улучшение решения

Теперь, когда мы создали базовое решение, настало время внести дополнительные улучшения. Вместо того, чтобы выводить двоичное имя, мы будем выводить имя файла и номер строки, из которой была вызвана функция, так как это гораздо более полезная информация для поиска первопричины проблемы. Мы также можем добавить таймстемп, когда вызывалась определенная функция. Ниже приведен код, отвечающий за основные функции Call Stack Logger:

#include "callStack.h"
#include "prettyTime.h"
#include "unwinder.h"
#include <bfd.h>
#include <cxxabi.h> // для __cxa_demangle
#include <dlfcn.h> // для dladdr
#include <fstream>
#include <map>
#include <memory>
#include <stdexcept>
#include <unistd.h>

namespace {

NO_INSTRUMENT
std::string demangle_cxa(const std::string& _cxa) {
    int status;
    std::unique_ptr<char, void (*)(void*)> realname(
            abi::__cxa_demangle(_cxa.data(), nullptr, nullptr, &status), &free);
    if (status != 0) {
        return _cxa;
    }

    return realname ? std::string(realname.get()) : "";
}

} // namespace

namespace instrumentation {

struct ResolvedFrame {
    std::string timestamp;
    std::optional<void*> callee_address;
    std::string callee_function_name;
    std::string caller_filename;
    std::optional<unsigned int> caller_line_number;
};

std::optional<ResolvedFrame> resolve(void* callee_address, void* caller_address) {
    return bfdResolver::resolve(callee_address, caller_address);
}

std::optional<ResolvedFrame> bfdResolver::resolve(void* callee_address, void* caller_address) {
    check_bfd_initialized();

    auto maybe_func_name = resolve_function_name(callee_address);
    if (!maybe_func_name) {
        return std::nullopt;
    }
    ResolvedFrame resolved;
    resolved.callee_function_name = *maybe_func_name;

    // Если код не изменен, 6 первых фреймов будут всегда одними и теми же, как и сам поток выполнения
    // начиная с 6-го фрейма и заканчивая вершиной стека, это будет выглядеть следующим образом:
    // * 6th - instrumentation::FrameUnwinder::unwind_nth_frame
    // * 5th - bfdResolver::resolve instrumentation::unwind_nth_frame
    // * 4th - instrumentation::bfdResolver::resolve
    // * 3rd - instrumentation::resolve
    // * 2nd - __cyg_profile_func_enter
    // * 1st - A::foo() --> function we are interested in
    // В противном случае, если этот поток вызовов будет изменен, количество фреймов должно быть пересчитано.
    Callback callback(caller_address);
    unwind_nth_frame(callback, 6);

    auto pair = resolve_filename_and_line(callback.caller);
    resolved.caller_filename = pair.first;
    resolved.caller_line_number = pair.second;
    resolved.timestamp = utils::pretty_time();

    return std::make_optional(resolved);
}

std::optional<std::string> bfdResolver::resolve_function_name(void* address) {
    Dl_info info;
    dladdr(address, &info);
    if (info.dli_fbase == nullptr) {
        return "<address to object not found>";
    }

    if (!ensure_bfd_loaded(info) || s_bfds.find(info.dli_fbase) == s_bfds.end()) {
        return "<could not open object file>";
    }
    storedBfd& currBfd = s_bfds.at(info.dli_fbase);

    asection* section = currBfd.abfd->sections;
    const bool relative = section->vma < static_cast<uintptr_t>(currBfd.offset);

    while (section != nullptr) {
        const intptr_t offset = reinterpret_cast<intptr_t>(address) - (relative ? currBfd.offset :               0) - static_cast<intptr_t>(section->vma);

        if (offset < 0 || static_cast<size_t>(offset) > section->size) {
            section = section->next;
            continue;
        }

        const char* file;
        const char* func;
        unsigned line;
        if (bfd_find_nearest_line(currBfd.abfd.get(), section, currBfd.symbols.get(), offset, &file,                  &func, &line)) 
        {
            auto demangled = demangle_cxa(func);
            return demangled.empty() ? std::nullopt : std::make_optional(demangled);
        }
        return demangle_cxa(info.dli_sname != nullptr ? info.dli_sname : "") + " <bfd_error>";
    }
    return "<not sectioned address>";
}

std::pair<std::string, std::optional<unsigned int>> bfdResolver::resolve_filename_and_line(void* address)
{
    // Получаем путь и смещение общего объекта, содержащего адрес вызывающей стороны.
    Dl_info info;
    dladdr(address, &info);
    if (info.dli_fbase == nullptr) {
        return std::make_pair("<caller address to object not found>", std::nullopt);
    }

    if (!ensure_bfd_loaded(info) || s_bfds.find(info.dli_fbase) == s_bfds.end()) {
        return std::make_pair("<could not open caller object file>", std::nullopt);
    }
    storedBfd& currBfd = s_bfds.at(info.dli_fbase);

    asection* section = currBfd.abfd->sections;
    const bool relative = section->vma < static_cast<uintptr_t>(currBfd.offset);

    while (section != nullptr) {
        const intptr_t offset = reinterpret_cast<intptr_t>(address) - (relative ? currBfd.offset :               0) - static_cast<intptr_t>(section->vma);

        if (offset < 0 || static_cast<size_t>(offset) > section->size) {
            section = section->next;
            continue;
        }
        const char* file;
        const char* func;
        unsigned int line = 0;
        if (bfd_find_nearest_line(currBfd.abfd.get(), section, currBfd.symbols.get(), offset, &file,                 &func, &line))
        {
            if (file != nullptr) {
                return std::make_pair(std::string(file), std::make_optional(line));
            }
            return std::make_pair(demangle_cxa(func), std::nullopt);
        }
        if (info.dli_sname != nullptr) {
            return std::make_pair(demangle_cxa(info.dli_sname) + " <bfd_error>", std::nullopt);
        }
    }
    return std::make_pair("<not sectioned address>", std::nullopt);
}

} // namespace instrumentation

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

Нам также следует изменить функцию __cyg_profile_func_enter:

extern "C" NO_INSTRUMENT
void __cyg_profile_func_enter(void *callee, void *caller) {
    if(fp_trace != nullptr) {
        auto maybe_resolved = instrumentation::resolve(callee, caller);
        if (!maybe_resolved) { return; }
        fprintf(fp_trace, "%s\n", utils::format(*maybe_resolved).c_str());
    }
}

Мы начинаем с функции resolve, принимающей адреса как вызываемой функции (callee), так и вызывающей стороны (caller). Ниже мы, в свою очередь, вызываем отдельные функции для адреса вызываемой функции (resolve_function_name) и адреса вызывающей стороны (resolve_filename_and_line) — так как из первого мы можем расшифровать имя класса и вызываемой функции, а второй позволяет нам получить информацию о точке вызова — точном месте, откуда была вызвана функция. Если бы мы передали функции resolve_filename_and_line адрес вызываемой функции вместо адреса вызывающей стороны, то она указала бы на первую строку определения вызываемой функции.

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

Если resolve_function_name не удается декодировать имя функции, мы не будем декодировать имя файла и строку, мы просто пропустим эту запись.

Также стоит отметить, что адрес вызывающей стороны не может быть преобразован стандартным способом. Это из-за какой-то ошибки в значении счетчика команд, приводящей к возврату неправильного места вызова. Оговорив это, прежде чем передать адрес вызывающей стороны функции resolve_filename_and_line мы должны сначала раскрутить (unwind) n-й фрейм, извлечь его адрес и только потом передать его в resolve_filename_and_line. К счастью, глубина раскрутки постоянна и для текущей реализации равна 6. Чтобы сделать это, раскрутчик использует библиотеку libunwind.

Теперь наш файл trace.out будет выглядеть следующим образом:

[13-06-2021 20:33:49.544] main  (called from: /build/glibc-S9d2JN/glibc-2.27/csu/../csu/libc-start.c:310)
[13-06-2021 20:33:49.600] A::foo()  (called from: /home/ubuntu/Desktop/call-stack-logger.8-final-with-identation-ready/src/main.cpp:39)

Но есть еще кое-что, что мы могли бы улучшить. Чтобы было намного легче отследить фактический поток выполнения, мы добавим отступы. Мы немного изменим __cyg_profile_func_enter и добавить реализацию __cyg_profile_func_exit:

static int current_stack_depth = -1;
static bool last_frame_was_resolved = false;

extern "C" NO_INSTRUMENT
void __cyg_profile_func_enter(void *callee, void *caller) {
    if(fp_trace != NULL) {
        last_frame_was_resolved = false;
        auto maybe_resolved = instrumentation::resolve(callee, caller);
        if (!maybe_resolved) { return; }
        last_frame_was_resolved = true;
        current_stack_depth++;
        fprintf(fp_trace, "%s\n", utils::format(*maybe_resolved, current_stack_depth).c_str());
    }
}

extern "C" NO_INSTRUMENT
void __cyg_profile_func_exit(void *callee, void *caller) {
    if(fp_trace != nullptr && last_frame_was_resolved) {
        current_stack_depth--;
    }
}

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

Теперь нам нужно только передать эту переменную в функцию utils::format и отформатировать строку так, как нам нужно, чтобы она выводилась в файле с логами.

И еще одно — давайте немного изменим наш пример, чтобы лучше продемонстрировать, как Call Stack Logger выводит записи в файл с логами:

class A {
public:
    static void foo() { std::cout << "static foo \n"; }
};

class B {
public:
    void foo() {
        std::cout << "non-static foo \n";
        std::vector<int> vec{ 1, 55, 78, 3, 11, 7, 90 };
        std::sort(vec.begin(), vec.end());
        A::foo();
    }
};

int fibonacci(int n) {
    if (n <= 1)
        return n;
    return fibonacci(n - 1) + fibonacci(n - 2);
}

int main() {
    // Тест логирования статических методов-членов класса.
    A::foo();

    // Тест логирования нестатических методов-членов с вызовами 
    // стандартных функций/контейнеров (которые не должны быть инструментированы).
    B b;
    b.foo();
    fibonacci(6);
    A::foo();
}

И вот окончательный результат:

Заключение

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

Решение, представленное в Call Stack Logger может представлять собой альтернативу стандартной отладке во многих ситуациях, например, когда доступ к производственной среде ограничен, и стоит иметь такой механизм в качестве резервного в нашем пуле инструментов для решения неочевидных проблем.

Вы можете найти Call Stack Logger на Github: TomaszAugustyn / call-stack-logger

Материал подготовлен в преддверии старта онлайн-курса "C++ Developer. Professional".

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