Временами бывает нужно отпрофилировать производительность программы или потребление памяти в программе на C++. К сожалению, зачастую это сделать не так просто как может показаться.

Здесь будут рассмотрены особенности профилирования программ с использованием инструментов valgrind и google perftools. Материал получился не очень структурированным, это скорее попытка собрать базу знаний «для личных целей», чтобы в будущем не приходилось судорожно вспоминать, «а почему не работает то» или «а как сделать это». Скорее всего, здесь будут затронуты далеко не все неочевидные случаи, если вам есть что добавить, пишите пожалуйста в комментарии.

Все примеры будут запускаться в системе linux.

Профилирование времени выполнения

Подготовка

Для разбора особенностей профилирования я буду запускать небольшие программки, как правило состоящие из одного main.cpp файла и одного файла func.cpp вместе с инклудом.
Компилировать их я буду компилятором g++ 8.3.0.

Так как профилировать неоптимизированные программы — довольно странное занятие, будем компилировать с опцией -Ofast, а для того, чтобы получить debug-символы на выходе, не забудем добавить опцию -g. Тем не менее, иногда вместо нормальных имен функций можно увидеть только невнятные адреса вызовов. Это значит, что произошла «рандомизация размещения адресного пространства». Это можно определить, вызывав команду nm на бинарнике. Если в большинство адресов выглядят примерно так 00000000000030e0 (большое количество нулей в начале), то скорее всего это оно. В нормальной программе адреса выглядят как 0000000000402fa0. Поэтому нужно добавить опцию -no-pie. В результате, полный набор опций будет выглядеть вот так:
-Ofast -g -no-pie

Для просмотра результатов будем использовать программу KCachegrind, который умеет работать с форматом отчетов callgrind

Callgrind

Первая утилита, которую мы сегодня рассмотрим — callgrind. Эта утилита входит в состав инструмента valgrind. Она эмулирует каждую исполняемую инструкцию программы и на основании внутренних метрик о «стоимости» работы каждой инструкции выдает нужное нам заключение. Из-за такого подхода иногда бывает так, что callgrind не может распознать очередую инструкцию и вываливается с ошибкой
Unrecognised instruction at address
Единственный выход из такой ситуации — пересмотреть все опции компиляции и попытаться найти мешающую

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




Компилируем программу, и запускаем valgrind следующим образом:

valgrind --tool=callgrind ./test_profiler 100000000

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

Для того, чтобы это исправить, при запуске программы нужно установить переменную LD_BIND_NOW в значение 1, вот так:

LD_BIND_NOW=1 valgrind --tool=callgrind ./test_profiler 100000000

И теперь, как видите, все нормально

Следующая проблема callgrind-а, вытекающая из профилирования путем эмуляции инструкций в том, что выполнение программы сильно замедляется. Это может нести в себе неправильную относительную оценку времени выполнения различных частей кода.

Давайте рассмотрим такой код:

int func(int arg) {
    int fst = 1;
    int snd = 1;
    std::ofstream file("tmp.txt");
    for (int i = 0; i < arg; i++) {
        int res = (fst + snd + 1) % 19845689;

        std::string r = std::to_string(res);

        file << res;
        file.flush();

        fst = snd;
        snd = res + r.size();
    }
    return fst;
}

Здесь я добавил на каждую итерацию цикла запись небольшого количества данных в файл. Так как запись в файл — довольно длительная операция, для противовеса я добавил на каждую итерацию цикла генерацию строки из числа. Очевидно, что в данном случае операция записи в файл занимает больше времени, чем вся остальная логика функции. Но callgrind считает по-другому:


Также стоит учесть, что callgrind может измерять стоимость работы функции, только когда та работает. Функция не работает — значит, и стоимость не растет. Это усложняет отладку программ, которые время от времени входят в блокировку или работают с блокирующей файловой системой/сетью. Давайте проверим:

#include "func.h"

#include <mutex>

static std::mutex mutex;

int funcImpl(int arg) {
    std::lock_guard<std::mutex> lock(mutex);

    int fst = 1;
    int snd = 1;
    for (int i = 0; i < arg; i++) {
        int res = (fst + snd + 1) % 19845689;
        fst = snd;
        snd = res;
    }
    return fst;
}

int func2(int arg){
    return funcImpl(arg);
}

int func(int arg) {
    return funcImpl(arg);
}

int main(int argc, char **argv) {
    if (argc != 2) {
        std::cout << "Incorrect args";
        return -1;
    }

    const int arg = std::atoi(argv[1]);

    auto future = std::async(std::launch::async, &func2, arg);

    std::cout << "result: " << func(arg) << std::endl;
    std::cout << "second result " << future.get() << std::endl;

    return 0;
}

Здесь мы вложили выполнение функции целиком в lock мьютекса, и вызвали эту функцию из двух разных потоков. Результат callgrind-а вполне предсказуем — он не видит проблемы в захвате мьютекса:


Итак, мы рассмотрели некоторые проблемы использования профилировщика callgrind. Давайте перейдем к следующему испытуемому — профилировщику из состава google perftools

google perftools

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

Давайте для начала попробуем провести профилирование первой программы с двумя библиотеками.

Как правило, для запуска профилирования этой утилитой необходимо предзагрузить библиотеку libprofiler.so, выставить частоту сэмплирования и указать файл для сохранения дампа. К сожалению, профайлер требует, чтобы программа завершалась «своим ходом». Принудительное завершение программы приведет к тому, что дамп отчета просто не создастся. Это неудобно при профилировании долгоживущих программ, которые сами по себе не останавливаются, например демонов. Для обхода этого препятствия я создал такой скрипт:


Эту утилиту нужно запускать, передавая в качестве параметров имя исполняемого файла и список его параметров. Также, предполагается, что рядом со скриптом лежат необходимые ему файлы libprofiler.so и pprof. В случае, если программа долгоживущая и останавливается путем прерывания выполнения, необходимо установить переменную N_STOP в значение true, например так:

N_STOP=true ./gprof.sh ./test_profiler 10000000000

В конце работы скрипт сгенерирует отчет в любимом мною формате callgrind.

Итак, давайте запустим нашу программу под этим профилировщиком

./gprof.sh ./test_profiler 1000000000

В принципе, все довольно наглядно.

Как я уже сказал, гугловый профилировщик работает, останавливая выполнение программы и вычисляя текущую функцию. Как же он это делает? Делает он это путем раскрутки стека. А что, если в момент раскрутки стека программа сама раскручивала стек? Ну, очевидно, что ничего хорошего при этом не произойдет. Давайте это проверим. Напишем такую функцию:

int runExcept(int res) {
    if (res % 13 == 0) {
        throw std::string("Exception");
    }
    return res;
}

int func(int arg) {
    int fst = 1;
    int snd = 1;
    for (int i = 0; i < arg; i++) {
        int res = (fst + snd + 1) % 19845689;

        try {
            res = runExcept(res);
        } catch (const std::string &e) {
            res = res - 1;
        }

        fst = snd;
        snd = res;
    }
    return fst;
}

И запустим профилирование. Программа довольно быстро зависнет.

Есть и другая проблема, связанная с особенностью работы профайлера. Предположим, мы сумели раскрутить стек, и теперь нам нужно сопоставить адреса с конкретными функциями программы. Это может быть очень нетривиально, так как в C++ довольно большое количество функций инлайнится. Давайте посмотрим на таком примере:

#include "func.h"

static int func1(int arg) {
    std::cout << 1 << std::endl;
    return func(arg);
}

static int func2(int arg) {
    std::cout << 2 << std::endl;
    return func(arg);
}

static int func3(int arg) {
    std::cout << 3 << std::endl;
    if (arg % 2 == 0) {
        return func2(arg);
    } else {
        return func1(arg);
    }
}

int main(int argc, char **argv) {
    if (argc != 2) {
        std::cout << "Incorrect args";
        return -1;
    }

    const int arg = std::atoi(argv[1]);

    int arg2 = func3(arg);
    int arg3 = func(arg);

    std::cout << "result: " <<  arg2 + arg3;
    return 0;
}

Очевидно, что если запустить программу например вот так:

./gprof.sh ./test_profiler 1000000000

то функция func1 никогда не вызовется. Но профайлер считает по-другому:

(К слову, valgrind здесь решил скромно промолчать и не уточнять, из какой конкретной функции пришел вызов).

Профилирование памяти

Нередко возникают ситуации, когда память из приложения куда-то «течет». Если это связано с отсутствием очистки ресурсов, то для выявлении проблемы должен помочь Memcheck. Но в современном C++ не так сложно обойтись без ручного управления ресурсами. unique_ptr, shared_ptr, vector, map делают манипулирование «голыми» указателями бесмыссленными.

Тем не менее, и в таких приложениях память бывает что течет. Как это происходит? Довольно просто, как правило это чтото вроде «положил значение в долгоживущий map, а удалить забыл». Давайте попробуем отследить эту ситуацию.

Для этого перепишем нашу тестовую функцию таким образом

#include "func.h"

#include <deque>
#include <string>
#include <map>

static std::deque<std::string> deque;
static std::map<int, std::string> map;

int func(int arg) {
    int fst = 1;
    int snd = 1;
    for (int i = 0; i < arg; i++) {
        int res = (fst + snd + 1) % 19845689;

        fst = snd;
        snd = res;

        deque.emplace_back(std::to_string(res) + " integer");
        map[i] = "integer " + std::to_string(res);
        deque.pop_front();
        if (res % 200 != 0) {
            map.erase(i - 1);
        }
    }
    return fst;
}

Здесь мы на каждой итерации добавляем в мапу некоторые элементы, и совершенно случайно (правда-правда) забываем их оттуда иногда удалить. Также, для отвода глаз мы немного мучаем std::deque.

Отлавливать утечки памяти мы будем двумя инструментами — valgrind massif и google heapdump.

Massif

Запускаем программу такой командой

valgrind --tool=massif  ./test_profiler 1000000

И видим что-то наподобие


Видно, что massif смог обнаружить утечку в функции, но пока не понятно где. Давайте пересоберем программу с флагом -fno-inline и запустим анализ еще раз


Теперь ясно видно, где утечка — в добавлении элемента map-ы. Massif умеет определять короткоживущие объекты, поэтому манипуляции с std::deque в этом дампе незаметны.

Heapdump

Для работы google heapdump необходимо прилинковать или предзагрузить библиотеку tcmalloc. Эта библиотека подменяет стандартные функции выделения памяти malloc, free,… Также она умеет собирать информацию об использовании этих функций, чем мы и воспользуемся при анализе программы.

Так как этот метод работает очень неторопливо (даже по сравнению с massif-ом), рекомендую сразу отключить при компиляции встраивание функций опцией -fno-inline. Итак, пересобираем наше приложение и запускаем с командой

HEAPPROFILESIGNAL=23 HEAPPROFILE=./heap ./test_profiler 100000000

Здесь предполагается, что библиотека tcmalloc прилинкована к нашему приложению.

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

kill -23 <pid>

В результате появляется файл с именем heap.0001.heap, который мы конвертируем в callgrind формат командой

pprof ./test_profiler "./heap.0001.heap" --inuse_space --callgrind > callgrind.out.4

Обратите также внимание на опции pprof-а. Можно выбирать из опций inuse_space, inuse_objects, alloc_space, alloc_objects, которые показывают находящиеся в использование пространство или объекты, или выделенное за все время работы программы пространство и объекты соответственно. Нас интересует опция inuse_space, которая показывает используемое в настоящее время пространство памяти.

Открываем наш любимый kCacheGrind и видим

std::map «выел» слишком много памяти. Наверное утечка в нем.

Выводы

Профилирование на C++ — очень непростая задача. Здесь нам придется бороться с инлайнингом функций, неподдерживаемыми инструкциями, некорректными результатами и т.д. Не всегда можно доверять результатам работы профилировщика.

Кроме предложенных выше функций, есть и другие инструменты, предназначенные для профилирования — perf, intel VTune и другие. Но и они проявляют некоторые из указанных недочетов. Поэтому не стоит забывать и о «дедушкином» способе профилирования путем замера времени выполнения функций и выводе его в лог.

Также, если у вас есть интересные приемы профилирования кода, прошу выкладывать их в комментариях