Анализ производительности отдельных подсистем программы по 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 в отчет не попали, хотя они и есть в общем отчете.

    Ads
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More

    Comments 1

      +1
      Что за отчёт? Почему? Зачем? Про что статья? «Когда я отлаживал свою программу.» — какую, о чем речь вообще?
      Мне честно интересно было бы узнать о perf, но не в таком виде/изложении.

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