Пара приемов визуального анализа исполнения программы

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

Итак, напишем простейшую программу, которую мы будем тестировать, и поместим ее в файл test.cc.

class  A
{
    public:
        A() : a_( 0 ) { a(); }

        ~A() { delete a_; }

        void a( void ) { a_ = new int( 0 ); }

        void  realloc( void ) { delete a_; a_ = new int( 0 ); }

    private:
        int *  a_;
};

int  main( void )
{
    A  a[ 10 ];

    for ( int  i( 0 ); i < 10; ++i )
    {
        a[ i ].realloc();
    }
}

В функции main() создаем массив a из десяти объектов типа A. В конструкторе класса A с помощью функции-члена a() выделяется динамическая память под объект типа int, а в деструкторе она освобождается. Кроме того, в классе A имеется функция-член realloc(), которая освобождает выделенную память и снова выделяет ее. Функция realloc() вызывается для всех элементов массива a внутри функции main(). Две функции внутри класса A нам будут нужны для демонстрации работы gprof2dot, а манипуляции с динамической памятью - для massif-visualizer.

Откомпилируем нашу программу

g++ -g -o test test.cc

и приступим к разбору утилит.

gprof2dot. Эта утилита позволяет выводить красивые диаграммы вызова функций на основании результатов профилирования тестируемой программы. Самый стандартный профилировщик для gcc - это gprof, отсюда и название gprof2dot. Однако мы не будем использовать gprof, так как для его поддержки пришлось бы компилировать программу со специальными флагами. Вместо этого будем использовать инструмент callgrind, входящий в состав valgrind, а gprof2dot сообщим, что мы использовали callgrind с помощью опции --format=callgrind. Кроме того, для получения результирующего изображения нам понадобится пакет graphviz, который предоставляет утилиту dot (вторая часть в названии gprof2dot), которая, в свою очередь, умеет генерировать из промежуточного dot-файла изображение заданного формата.

Запускаем тестируемую программу из-под valgrind

valgrind --tool=callgrind --callgrind-out-file=callgrind.out ./test

и строим изображение

gprof2dot --format=callgrind --output=out.dot -s callgrind.out
dot -Tpng out.dot -o out.png

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

Вот так выглядит полученная картинка out.png (кликните по изображению для его увеличения):

Изображение состоит из набора элементов двух типов: прямоугольников - функций и стрелок - вызовов функций. Каждый элемент сопровождается профильной информацией. Для функций - это библиотека или исполняемая программа, которой принадлежит функция, имя функции, время ее выполнения в процентах от общего времени исполнения программы и количество ее вызовов. Стрелки сопровождаются информацией о времени выполнения всей иерархии функций, вызовы которых они порождают и количестве вызовов дочерней функции из родительской, соединенных этой стрелкой. Качественная информация о времени выполнения отдельных функций передается цветом прямоугольника: чем теплее цвет - тем больше времени заняло выполнение данной функции. Так, корневая функция, вместо имени которой указан адрес (верхний прямоугольник), окрашена красным цветом и время ее выполнения соответствует 100%, так как вызовы всех остальных функций были порождены ею, значение в скобках - 0.00% - это время выполнения ее тела. Функции, которые выполнялись за меньшее время окрашены в оранжевый, желтый и зеленый цвета, самые быстрые - в синий.

Соответственно, на нашем изображениии видно, что львиную долю времени заняли вызовы системных функций линковщика, в частности _dl_relocate_object() была вызвана 7 раз и заняла 88.92% всего времени. Наша главная функция main() потратила всего лишь 2.19% от общего времени. И это не удивительно в случае такой простой программы, как наша. Конструктор A::A() вызывался 10 раз из функции main() и потратил 0.95% общего времени, функция-член A::realloc() вызывалась тоже 10 раз и потратила 1.04% общего времени. Все время обоих функций было затрачено на вызов оператора new() и, затем, функции malloc().

Что если нас не интересуют системные вызовы? Утилита gprof2dot позволяет строить вызовы функций из определенного корня с помощью опции -z. Например, чтобы построить вызовы всех фунций, начиная с нашей функции main(), нужно выполнить

gprof2dot --format=callgrind --output=out_main.dot -s -z main callgrind.out
dot -Tpng out_main.dot -o out_main.png

Полученное изображение out_main.png представляет собой небольшой участок общей картинки:

Есть еще одна полезная опция -l - это когда нужно изобразить все, что вызывает указанную функцию.

massif-visualizer. Эта утилита полезна, когда нужно визуализировать выделение и освобождение динамической памяти в процессе прогона тестируемой программы. Она тоже является простой оболочкой над инструментом massif из состава valgrind. При сборке программы вручную важно учесть, что она зависит от библиотек разработки KDE.

Запустим программу test под massif

valgrind --tool=massif --massif-out-file=massif.out --time-unit=B --detailed-freq=1 ./test

и откроем сгенерированный файл massif.out с помощью massif-visualizer

massif-visualizer massif.out

Откроется вот такое окно:

В центральной области расположен график, изображающий этапы выделения и освобождения динамической памяти. Горизонтальная ось графика - время работы программы, выраженное в байтах, это соответствует опции massif --time-unit=B. Время, выраженное в байтах, лучше всего подходит для небольших тестовых программ, каковой и является наша программа test. Другие возможные единицы измерения времени в massif - количество инструкций (по умолчанию) и миллисекунды. Опция --detailed-freq=1 в нашем случае также имеет важное значение: она задает самое детализированное накопление снапшотов, то есть столбцов графика и элементов из списка справа от него. В случае продолжительно работающих программ ее значение по умолчанию 10 является более предпочтительным, чем 1.

По вертикальной оси отложено количество выделенной динамической памяти. Очевидно, пиковое значение 40 байт соответствует десятикратному значению размера типа int (4 байта * 10 элементов массива a). Память, выделенная функцией A::a(), обозначена желтым цветом. Она постепенно снижалась за счет вызова функции A::realloc() в цикле for внутри main(). Вызовам A::realloc() соответствуют синие столбцы на графике. В итоге, в конце программы вся память была освобождена, поскольку на правом крае графика столбцы отсутствуют.

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