通常、Linuxでプロファイリングレポートを準備するために、 perf report
を実行するための最も簡単なオプションのみを使用しました（ perf record
コマンドでperf report
を実行する前にパフォーマンスデータを取得する必要があります 。 ここで例を参照してください）。
モジュールレポート：
$ perf report --stdio --kallsyms=/boot/System.map-$(uname -r) --sort=dso -g none
機能レポート：
perf report -g none --stdio --kallsyms=/boot/System.map-$(uname -r)
コールグラフプロットを使用した関数レポート：
perf report --stdio --kallsyms=/boot/System.map-$(uname -r) -g
多くの場合、このようなレポートはパフォーマンスの問題を見つけるのに十分でした。 しかし、少し前に、コールグラフレポートが非常に大きなコールツリーを示し、理解するのが難しい状況に直面しました。
パフォーマンスレポートをよりよく理解するために、プログラムサブシステムに正確に対応する別のレポートに分割したかったのです。
- メッセージ受信サブシステム、メイン関数：
amqp_service::on_message()
- メッセージ処理サブシステム、メイン関数：
input_handler::execute()
- 通知配信サブシステム、メイン関数：
event_handler::on_msg()
Linux perfには、コールスタック内の1つの関数に関連するイベントのみを選択できるキーがあることがわかりました。
-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イベントは、イベント72784958041の合計数の約2％であることがわかります。つまり、この関数は、負荷が高い場合でも多くのイベントを生成しませんでした。 念のため、 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
このデータとamqp_service::on_message()
グラフをamqp_service::on_message()
完全なレポートから、負荷がかかると、関数は主にメッセージのコピーに時間を費やすことがわかります。 この関数でmutecをブロックすることは問題ではなく、負荷がかかっているのは1.8％だけです。レポートによると、この関数とそれから呼び出される関数でmutecに大きな競合はありません。
input_handlerの分析:: execute（）関数。
この別個の機能に関するレポート：
$ perf report -x --stdio --kallsyms=/boot/System.map-$(uname -r) \ -g -p "input_handler::execute"
このフィルターを使用したイベントの数：
# Event count (approx.): 16423187486
16423187486イベントは、イベント72784958041の合計数の22％であることがわかります。これは、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()
-fno-omit-frame-pointer
なしでinput_handler::execute()
されているようにinput_handler::execute()
、 input_handler::execute()
された関数の一部は、 -fno-omit-frame-pointer
input_handler::execute()
して分析するとレポートに--parent
れませんでした--parent
、そして、一般的なレポートにあります。