| From b7faeae5fd5e58d5de5215e023813743fd79dbf8 Mon Sep 17 00:00:00 2001 |
| From: Milian Wolff <milian.wolff@kdab.com> |
| Date: Mon, 29 Oct 2018 15:16:44 +0100 |
| Subject: perf unwind: Take pgoff into account when reporting elf to libdwfl |
| |
| [ Upstream commit 1fe627da30331024f453faef04d500079b901107 ] |
| |
| libdwfl parses an ELF file itself and creates mappings for the |
| individual sections. perf on the other hand sees raw mmap events which |
| represent individual sections. When we encounter an address pointing |
| into a mapping with pgoff != 0, we must take that into account and |
| report the file at the non-offset base address. |
| |
| This fixes unwinding with libdwfl in some cases. E.g. for a file like: |
| |
| ``` |
| |
| using namespace std; |
| |
| mutex g_mutex; |
| |
| double worker() |
| { |
| lock_guard<mutex> guard(g_mutex); |
| uniform_real_distribution<double> uniform(-1E5, 1E5); |
| default_random_engine engine; |
| double s = 0; |
| for (int i = 0; i < 1000; ++i) { |
| s += norm(complex<double>(uniform(engine), uniform(engine))); |
| } |
| cout << s << endl; |
| return s; |
| } |
| |
| int main() |
| { |
| vector<std::future<double>> results; |
| for (int i = 0; i < 10000; ++i) { |
| results.push_back(async(launch::async, worker)); |
| } |
| return 0; |
| } |
| ``` |
| |
| Compile it with `g++ -g -O2 -lpthread cpp-locking.cpp -o cpp-locking`, |
| then record it with `perf record --call-graph dwarf -e |
| sched:sched_switch`. |
| |
| When you analyze it with `perf script` and libunwind, you should see: |
| |
| ``` |
| cpp-locking 20038 [005] 54830.236589: sched:sched_switch: prev_comm=cpp-locking prev_pid=20038 prev_prio=120 prev_state=T ==> next_comm=swapper/5 next_pid=0 next_prio=120 |
| ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1670208 schedule+0x28 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb16737cc rwsem_down_read_failed+0xec (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1665e04 call_rwsem_down_read_failed+0x14 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1672a03 down_read+0x13 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb106bd85 __do_page_fault+0x445 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb18015f5 page_fault+0x45 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| 7f38e4252591 new_heap+0x101 (/usr/lib/libc-2.28.so) |
| 7f38e4252d0b arena_get2.part.4+0x2fb (/usr/lib/libc-2.28.so) |
| 7f38e4255b1c tcache_init.part.6+0xec (/usr/lib/libc-2.28.so) |
| 7f38e42569e5 __GI___libc_malloc+0x115 (inlined) |
| 7f38e4241790 __GI__IO_file_doallocate+0x90 (inlined) |
| 7f38e424fbbf __GI__IO_doallocbuf+0x4f (inlined) |
| 7f38e424ee47 __GI__IO_file_overflow+0x197 (inlined) |
| 7f38e424df36 _IO_new_file_xsputn+0x116 (inlined) |
| 7f38e4242bfb __GI__IO_fwrite+0xdb (inlined) |
| 7f38e463fa6d std::basic_streambuf<char, std::char_traits<char> >::sputn(char const*, long)+0x1cd (inlined) |
| 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> >::_M_put(char const*, long)+0x1cd (inlined) |
| 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> > std::__write<char>(std::ostreambuf_iterator<char, std::char_traits<char> >, char const*, int)+0x1cd (inlined) |
| 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_float<double>(std::ostreambuf_iterator<c> |
| 7f38e464bd70 std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, double) const+0x90 (inl> |
| 7f38e464bd70 std::ostream& std::ostream::_M_insert<double>(double)+0x90 (/usr/lib/libstdc++.so.6.0.25) |
| 563b9cb502f7 std::ostream::operator<<(double)+0xb7 (inlined) |
| 563b9cb502f7 worker()+0xb7 (/ssd/milian/projects/kdab/rnd/hotspot/build/tests/test-clients/cpp-locking/cpp-locking) |
| 563b9cb506fb double std::__invoke_impl<double, double (*)()>(std::__invoke_other, double (*&&)())+0x2b (inlined) |
| 563b9cb506fb std::__invoke_result<double (*)()>::type std::__invoke<double (*)()>(double (*&&)())+0x2b (inlined) |
| 563b9cb506fb decltype (__invoke((_S_declval<0ul>)())) std::thread::_Invoker<std::tuple<double (*)()> >::_M_invoke<0ul>(std::_Index_tuple<0ul>)+0x2b (inlined) |
| 563b9cb506fb std::thread::_Invoker<std::tuple<double (*)()> >::operator()()+0x2b (inlined) |
| 563b9cb506fb std::__future_base::_Task_setter<std::unique_ptr<std::__future_base::_Result<double>, std::__future_base::_Result_base::_Deleter>, std::thread::_Invoker<std::tuple<double (*)()> >, dou> |
| 563b9cb506fb std::_Function_handler<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> (), std::__future_base::_Task_setter<std::unique_ptr<std::__future_> |
| 563b9cb507e8 std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>::operator()() const+0x28 (inlined) |
| 563b9cb507e8 std::__future_base::_State_baseV2::_M_do_set(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*)+0x28 (/ssd/milian/> |
| 7f38e46d24fe __pthread_once_slow+0xbe (/usr/lib/libpthread-2.28.so) |
| 563b9cb51149 __gthread_once+0xe9 (inlined) |
| 563b9cb51149 void std::call_once<void (std::__future_base::_State_baseV2::*)(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*)> |
| 563b9cb51149 std::__future_base::_State_baseV2::_M_set_result(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>, bool)+0xe9 (inlined) |
| 563b9cb51149 std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<double (*)()> >, double>::_Async_state_impl(std::thread::_Invoker<std::tuple<double (*)()> >&&)::{lambda()#1}::op> |
| 563b9cb51149 void std::__invoke_impl<void, std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<double (*)()> >, double>::_Async_state_impl(std::thread::_Invoker<std::tuple<double> |
| 563b9cb51149 std::__invoke_result<std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<double (*)()> >, double>::_Async_state_impl(std::thread::_Invoker<std::tuple<double (*)()> >> |
| 563b9cb51149 decltype (__invoke((_S_declval<0ul>)())) std::thread::_Invoker<std::tuple<std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<double (*)()> >, double>::_Async_state_> |
| 563b9cb51149 std::thread::_Invoker<std::tuple<std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<double (*)()> >, double>::_Async_state_impl(std::thread::_Invoker<std::tuple<dou> |
| 563b9cb51149 std::thread::_State_impl<std::thread::_Invoker<std::tuple<std::__future_base::_Async_state_impl<std::thread::_Invoker<std::tuple<double (*)()> >, double>::_Async_state_impl(std::thread> |
| 7f38e45f0062 execute_native_thread_routine+0x12 (/usr/lib/libstdc++.so.6.0.25) |
| 7f38e46caa9c start_thread+0xfc (/usr/lib/libpthread-2.28.so) |
| 7f38e42ccb22 __GI___clone+0x42 (inlined) |
| ``` |
| |
| Before this patch, using libdwfl, you would see: |
| |
| ``` |
| cpp-locking 20038 [005] 54830.236589: sched:sched_switch: prev_comm=cpp-locking prev_pid=20038 prev_prio=120 prev_state=T ==> next_comm=swapper/5 next_pid=0 next_prio=120 |
| ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1670208 schedule+0x28 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb16737cc rwsem_down_read_failed+0xec (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1665e04 call_rwsem_down_read_failed+0x14 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1672a03 down_read+0x13 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb106bd85 __do_page_fault+0x445 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb18015f5 page_fault+0x45 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| 7f38e4252591 new_heap+0x101 (/usr/lib/libc-2.28.so) |
| a041161e77950c5c [unknown] ([unknown]) |
| ``` |
| |
| With this patch applied, we get a bit further in unwinding: |
| |
| ``` |
| cpp-locking 20038 [005] 54830.236589: sched:sched_switch: prev_comm=cpp-locking prev_pid=20038 prev_prio=120 prev_state=T ==> next_comm=swapper/5 next_pid=0 next_prio=120 |
| ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1670208 schedule+0x28 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb16737cc rwsem_down_read_failed+0xec (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1665e04 call_rwsem_down_read_failed+0x14 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb1672a03 down_read+0x13 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb106bd85 __do_page_fault+0x445 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| ffffffffb18015f5 page_fault+0x45 (/lib/modules/4.14.78-1-lts/build/vmlinux) |
| 7f38e4252591 new_heap+0x101 (/usr/lib/libc-2.28.so) |
| 7f38e4252d0b arena_get2.part.4+0x2fb (/usr/lib/libc-2.28.so) |
| 7f38e4255b1c tcache_init.part.6+0xec (/usr/lib/libc-2.28.so) |
| 7f38e42569e5 __GI___libc_malloc+0x115 (inlined) |
| 7f38e4241790 __GI__IO_file_doallocate+0x90 (inlined) |
| 7f38e424fbbf __GI__IO_doallocbuf+0x4f (inlined) |
| 7f38e424ee47 __GI__IO_file_overflow+0x197 (inlined) |
| 7f38e424df36 _IO_new_file_xsputn+0x116 (inlined) |
| 7f38e4242bfb __GI__IO_fwrite+0xdb (inlined) |
| 7f38e463fa6d std::basic_streambuf<char, std::char_traits<char> >::sputn(char const*, long)+0x1cd (inlined) |
| 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> >::_M_put(char const*, long)+0x1cd (inlined) |
| 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> > std::__write<char>(std::ostreambuf_iterator<char, std::char_traits<char> >, char const*, int)+0x1cd (inlined) |
| 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_float<double>(std::ostreambuf_iterator<c> |
| 7f38e464bd70 std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, double) const+0x90 (inl> |
| 7f38e464bd70 std::ostream& std::ostream::_M_insert<double>(double)+0x90 (/usr/lib/libstdc++.so.6.0.25) |
| 563b9cb502f7 std::ostream::operator<<(double)+0xb7 (inlined) |
| 563b9cb502f7 worker()+0xb7 (/ssd/milian/projects/kdab/rnd/hotspot/build/tests/test-clients/cpp-locking/cpp-locking) |
| 6eab825c1ee3e4ff [unknown] ([unknown]) |
| ``` |
| |
| Note that the backtrace is still stopping too early, when compared to |
| the nice results obtained via libunwind. It's unclear so far what the |
| reason for that is. |
| |
| Committer note: |
| |
| Further comment by Milian on the thread started on the Link: tag below: |
| |
| --- |
| The remaining issue is due to a bug in elfutils: |
| |
| https://sourceware.org/ml/elfutils-devel/2018-q4/msg00089.html |
| |
| With both patches applied, libunwind and elfutils produce the same output for |
| the above scenario. |
| --- |
| |
| Signed-off-by: Milian Wolff <milian.wolff@kdab.com> |
| Acked-by: Jiri Olsa <jolsa@kernel.org> |
| Link: http://lkml.kernel.org/r/20181029141644.3907-1-milian.wolff@kdab.com |
| Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> |
| Signed-off-by: Sasha Levin <sashal@kernel.org> |
| --- |
| tools/perf/util/unwind-libdw.c | 4 ++-- |
| 1 file changed, 2 insertions(+), 2 deletions(-) |
| |
| diff --git a/tools/perf/util/unwind-libdw.c b/tools/perf/util/unwind-libdw.c |
| index 880e8db32484..bf5ee8906fb2 100644 |
| --- a/tools/perf/util/unwind-libdw.c |
| +++ b/tools/perf/util/unwind-libdw.c |
| @@ -41,13 +41,13 @@ static int __report_module(struct addr_location *al, u64 ip, |
| Dwarf_Addr s; |
| |
| dwfl_module_info(mod, NULL, &s, NULL, NULL, NULL, NULL, NULL); |
| - if (s != al->map->start) |
| + if (s != al->map->start - al->map->pgoff) |
| mod = 0; |
| } |
| |
| if (!mod) |
| mod = dwfl_report_elf(ui->dwfl, dso->short_name, |
| - (dso->symsrc_filename ? dso->symsrc_filename : dso->long_name), -1, al->map->start, |
| + (dso->symsrc_filename ? dso->symsrc_filename : dso->long_name), -1, al->map->start - al->map->pgoff, |
| false); |
| |
| return mod && dwfl_addrmodule(ui->dwfl, ip) == mod ? 0 : -1; |
| -- |
| 2.19.1 |
| |