Анализ производительности отдельных подсистем программы по Linux perf report

Обычно для подготовки отчета по профилированию на Linux я использовал только самые простые варианты запуска perf report (сами данные по производительности должны быть получены до запуска perf report командой perf record, вот тут можно подробнее прочесть с примером):

Отчет по модулям:

$ perf report --stdio --kallsyms=/boot/System.map-$(uname -r) --sort=dso -g none

Отчет по функциям:

perf report -g none --stdio --kallsyms=/boot/System.map-$(uname -r)

Отчет по функциям с построением callgraph:

perf report --stdio --kallsyms=/boot/System.map-$(uname -r) -g

Для многих ситуаций таких отчетов было вполне достаточно, чтобы найти проблемы с производительностью. Однако некоторое время назад я столкнулся с ситуацией когда отчет по callgraph показывал очень большое дерево вызовов и его было затруднительно понимать.

Для лучшего понимания отчета по производительности хотелось разбить его на отдельные отчеты, которые бы точно соответствовали подсистемам программы:

1. Подсистема получения сообщения, основная функция: amqp_service::on_message()
2. Подсистема обработки сообщения, основная функция: input_handler::execute()
3. Подсистема рассылки нотификаций, основная функция: event_handler::on_msg()

Оказалось, что у Linux perf есть ключ, который позволяет выбрать только события относящиеся к одной функции в стеке вызовов:

       -p, --parent=<regex>
           A regex filter to identify parent. The parent is a caller of this function and searched through the callchain, 
          thus it requires callchain information recorded. The pattern is in the exteneded regex format and 
          defaults to "^sys_|^do_page_fault"

Этот ключ позволил мне проанализировать производительность отдельно для каждой важной мне функции. Предварительно надо сказать, что по отчету общее количество событий в perf.dat было такое:

# Event count (approx.): 72784958041

Анализ amqp_service::on_message()

Построение отчета по amqp_service::on_message():

$ perf report -x --stdio --kallsyms=/boot/System.map-$(uname -r) \
    -g -p "amqp_service::on_message"

Количество событий с таким фильтром

# Event count (approx.): 1590851860

Получается, что 1590851860 событий — это примерно 2% от общего числа событий 72784958041. То есть эта функция не генерировала много событий даже под большой нагрузкой. На всякий случай я смотрю какие функции были в топе, когда работала amqp_service::on_message() и нет ли в топе pthread_mutex_lock()/pthread_mutex_unlock():

$ perf report -x --stdio --kallsyms=/boot/System.map-$(uname -r) \
    -g -p "amqp_service::on_message" | \
    grep -E -e "^[ ]+[0-9]"  | sed -re 's/[ ]+data_provider::.*+$//' | head

    29.38%  data_provider  [kernel.kallsyms]     [k] clear_page_c
    11.09%  data_provider  libc-2.12.so          [.] memcpy
     6.01%  data_provider  [kernel.kallsyms]     [k] __alloc_pages_nodemask
     5.27%  data_provider  [kernel.kallsyms]     [k] compact_zone
     4.44%  data_provider  [kernel.kallsyms]     [k] page_fault
     4.08%  data_provider  [kernel.kallsyms]     [k] get_pageblock_flags_group
     4.05%  data_provider  [kernel.kallsyms]     [k] __reset_isolation_suitable
     3.55%  data_provider  [kernel.kallsyms]     [k] compaction_alloc
     1.78%  data_provider  libpthread-2.12.so    [.] pthread_mutex_lock
     1.61%  data_provider  [kernel.kallsyms]     [k] __mem_cgroup_commit_charge

По этим данным и по полному отчету с callgraph для amqp_service::on_message() я вижу, что под нагрузкой функция в основном тратит время на копирование сообщений. Блокирование на мьютеках в этой функции не является проблемой, всего 1,8% под нагрузкой, большого contention на мьютеках в этой функции и в функциях вызываемых из нее по отчету нет.

Анализ функции input_handler::execute().

Построение отчета по этой отдельной функции:

$ perf report -x --stdio --kallsyms=/boot/System.map-$(uname -r) \
    -g -p "input_handler::execute"

Количество событий с таким фильтром:

# Event count (approx.): 16423187486

Получается, что 16423187486 событий — это 22% от общего числа событий 72784958041. Это уже большое количество работы относительно общего количества событий perf и тут я смотрел более внимательно на то, где алгоритм проводит время.

$ perf report -x --stdio --kallsyms=/boot/System.map-$(uname -r) \
    -g -p "input_handler::execute" | \
    grep -E -e "^[ ]+[0-9]"  | sed -re 's/[ ]+data_provider::.*+$//' | head

     7.31%  data_provider  data_provider.005.00  [.] dtl::basic_string_ref<char, std::char_traits<char> >::empty() const
     7.19%  data_provider  data_provider.005.00  [.] dtl::string_parser::fail() const
     4.95%  data_provider  data_provider.005.00  [.] dtl::string_parser::eof() const
     4.87%  data_provider  data_provider.005.00  [.] dtl::string_parser::peek() const
     3.46%  data_provider  data_provider.005.00  [.] meta::json::decoder::parse_value(dtl::basic_string_ref<char, std::char_traits<char> >&)
     3.08%  data_provider  data_provider.005.00  [.] dtl::basic_string_ref<char, std::char_traits<char> >::operator[](unsigned long) const
     2.53%  data_provider  data_provider.005.00  [.] dtl::basic_string_ref<char, std::char_traits<char> >::remove_prefix(unsigned long)
     2.30%  data_provider  data_provider.005.00  [.] dtl::hash_seq(unsigned char const*, unsigned long)
     2.21%  data_provider  data_provider.005.00  [.] bool dtl::strtou<(unsigned char)10, unsigned char>(dtl::basic_string_ref<char, std::char_traits<char> >&, unsigned char&)

Однако, судя по этим данным, функция выполняет большое количество декодирования, но проблем с масштабированием в коде нет — нет значительного количества вызовов pthread_mutex_lock(). То есть можно добавлять еще потоки для input_handler::execute() и ожидать увеличения общей производительности.

Анализ функции event_handler::on_msg().

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

$ perf report -x --stdio --kallsyms=/boot/System.map-$(uname -r) \
    -g -p "event_handler::on_msg" | \
    grep -E -e "^[ ]+[0-9]"  | sed -re 's/[ ]+data_provider::.*+$//' | head 

     6.73%  data_provider  libpthread-2.12.so    [.] pthread_mutex_lock
     4.90%  data_provider  libpthread-2.12.so    [.] pthread_mutex_unlock
     4.45%  data_provider  data_provider.005.00  [.] std::__atomic_base<unsigned int>::operator++()
     3.84%  data_provider  [kernel.kallsyms]     [k] _spin_lock
     3.54%  data_provider  data_provider.005.00  [.] std::__atomic_base<unsigned long>::fetch_add(unsigned long, std::memory_order)
     3.47%  data_provider  data_provider.005.00  [.] dtl::intrusive_ptr<meta::object>::intrusive_ptr(dtl::intrusive_ptr<meta::object> const&)
     2.92%  data_provider  data_provider.005.00  [.] (anonymous namespace)::page_allocator_base::allocate_obj(dtl::page_allocation_info&)
     2.70%  data_provider  data_provider.005.00  [.] std::char_traits<char>::length(char const*)
     2.18%  data_provider  data_provider.005.00  [.] dtl::string::size() const
     1.96%  data_provider  data_provider.005.00  [.] dtl::string::create_(dtl::basic_string_ref<char, std::char_traits<char> > const&)

В итоге, построение отчета с использованием ключа --parent помогло проанализировать производительность отдельных частей моей програмы. Однако из-за того, что используемая Lua библиотека, видимо, была собрана без -fno-omit-frame-pointer, часть функций, которые выполнялись в input_handler::execute() при анализе с --parent в отчет не попали, хотя они и есть в общем отчете.