]>
Commit | Line | Data |
---|---|---|
3047e0ff SL |
1 | From 3f3325fba1a83235a9d56e20a0e72c25c85416b3 Mon Sep 17 00:00:00 2001 |
2 | From: Milian Wolff <milian.wolff@kdab.com> | |
3 | Date: Mon, 29 Oct 2018 15:16:44 +0100 | |
4 | Subject: perf unwind: Take pgoff into account when reporting elf to libdwfl | |
5 | ||
6 | [ Upstream commit 1fe627da30331024f453faef04d500079b901107 ] | |
7 | ||
8 | libdwfl parses an ELF file itself and creates mappings for the | |
9 | individual sections. perf on the other hand sees raw mmap events which | |
10 | represent individual sections. When we encounter an address pointing | |
11 | into a mapping with pgoff != 0, we must take that into account and | |
12 | report the file at the non-offset base address. | |
13 | ||
14 | This fixes unwinding with libdwfl in some cases. E.g. for a file like: | |
15 | ||
16 | ``` | |
17 | ||
18 | using namespace std; | |
19 | ||
20 | mutex g_mutex; | |
21 | ||
22 | double worker() | |
23 | { | |
24 | lock_guard<mutex> guard(g_mutex); | |
25 | uniform_real_distribution<double> uniform(-1E5, 1E5); | |
26 | default_random_engine engine; | |
27 | double s = 0; | |
28 | for (int i = 0; i < 1000; ++i) { | |
29 | s += norm(complex<double>(uniform(engine), uniform(engine))); | |
30 | } | |
31 | cout << s << endl; | |
32 | return s; | |
33 | } | |
34 | ||
35 | int main() | |
36 | { | |
37 | vector<std::future<double>> results; | |
38 | for (int i = 0; i < 10000; ++i) { | |
39 | results.push_back(async(launch::async, worker)); | |
40 | } | |
41 | return 0; | |
42 | } | |
43 | ``` | |
44 | ||
45 | Compile it with `g++ -g -O2 -lpthread cpp-locking.cpp -o cpp-locking`, | |
46 | then record it with `perf record --call-graph dwarf -e | |
47 | sched:sched_switch`. | |
48 | ||
49 | When you analyze it with `perf script` and libunwind, you should see: | |
50 | ||
51 | ``` | |
52 | 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 | |
53 | ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
54 | ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
55 | ffffffffb1670208 schedule+0x28 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
56 | ffffffffb16737cc rwsem_down_read_failed+0xec (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
57 | ffffffffb1665e04 call_rwsem_down_read_failed+0x14 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
58 | ffffffffb1672a03 down_read+0x13 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
59 | ffffffffb106bd85 __do_page_fault+0x445 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
60 | ffffffffb18015f5 page_fault+0x45 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
61 | 7f38e4252591 new_heap+0x101 (/usr/lib/libc-2.28.so) | |
62 | 7f38e4252d0b arena_get2.part.4+0x2fb (/usr/lib/libc-2.28.so) | |
63 | 7f38e4255b1c tcache_init.part.6+0xec (/usr/lib/libc-2.28.so) | |
64 | 7f38e42569e5 __GI___libc_malloc+0x115 (inlined) | |
65 | 7f38e4241790 __GI__IO_file_doallocate+0x90 (inlined) | |
66 | 7f38e424fbbf __GI__IO_doallocbuf+0x4f (inlined) | |
67 | 7f38e424ee47 __GI__IO_file_overflow+0x197 (inlined) | |
68 | 7f38e424df36 _IO_new_file_xsputn+0x116 (inlined) | |
69 | 7f38e4242bfb __GI__IO_fwrite+0xdb (inlined) | |
70 | 7f38e463fa6d std::basic_streambuf<char, std::char_traits<char> >::sputn(char const*, long)+0x1cd (inlined) | |
71 | 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> >::_M_put(char const*, long)+0x1cd (inlined) | |
72 | 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) | |
73 | 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> | |
74 | 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> | |
75 | 7f38e464bd70 std::ostream& std::ostream::_M_insert<double>(double)+0x90 (/usr/lib/libstdc++.so.6.0.25) | |
76 | 563b9cb502f7 std::ostream::operator<<(double)+0xb7 (inlined) | |
77 | 563b9cb502f7 worker()+0xb7 (/ssd/milian/projects/kdab/rnd/hotspot/build/tests/test-clients/cpp-locking/cpp-locking) | |
78 | 563b9cb506fb double std::__invoke_impl<double, double (*)()>(std::__invoke_other, double (*&&)())+0x2b (inlined) | |
79 | 563b9cb506fb std::__invoke_result<double (*)()>::type std::__invoke<double (*)()>(double (*&&)())+0x2b (inlined) | |
80 | 563b9cb506fb decltype (__invoke((_S_declval<0ul>)())) std::thread::_Invoker<std::tuple<double (*)()> >::_M_invoke<0ul>(std::_Index_tuple<0ul>)+0x2b (inlined) | |
81 | 563b9cb506fb std::thread::_Invoker<std::tuple<double (*)()> >::operator()()+0x2b (inlined) | |
82 | 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> | |
83 | 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_> | |
84 | 563b9cb507e8 std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>::operator()() const+0x28 (inlined) | |
85 | 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/> | |
86 | 7f38e46d24fe __pthread_once_slow+0xbe (/usr/lib/libpthread-2.28.so) | |
87 | 563b9cb51149 __gthread_once+0xe9 (inlined) | |
88 | 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*)> | |
89 | 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) | |
90 | 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> | |
91 | 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> | |
92 | 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 (*)()> >> | |
93 | 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_> | |
94 | 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> | |
95 | 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> | |
96 | 7f38e45f0062 execute_native_thread_routine+0x12 (/usr/lib/libstdc++.so.6.0.25) | |
97 | 7f38e46caa9c start_thread+0xfc (/usr/lib/libpthread-2.28.so) | |
98 | 7f38e42ccb22 __GI___clone+0x42 (inlined) | |
99 | ``` | |
100 | ||
101 | Before this patch, using libdwfl, you would see: | |
102 | ||
103 | ``` | |
104 | 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 | |
105 | ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
106 | ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
107 | ffffffffb1670208 schedule+0x28 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
108 | ffffffffb16737cc rwsem_down_read_failed+0xec (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
109 | ffffffffb1665e04 call_rwsem_down_read_failed+0x14 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
110 | ffffffffb1672a03 down_read+0x13 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
111 | ffffffffb106bd85 __do_page_fault+0x445 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
112 | ffffffffb18015f5 page_fault+0x45 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
113 | 7f38e4252591 new_heap+0x101 (/usr/lib/libc-2.28.so) | |
114 | a041161e77950c5c [unknown] ([unknown]) | |
115 | ``` | |
116 | ||
117 | With this patch applied, we get a bit further in unwinding: | |
118 | ||
119 | ``` | |
120 | 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 | |
121 | ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
122 | ffffffffb166fec5 __sched_text_start+0x545 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
123 | ffffffffb1670208 schedule+0x28 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
124 | ffffffffb16737cc rwsem_down_read_failed+0xec (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
125 | ffffffffb1665e04 call_rwsem_down_read_failed+0x14 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
126 | ffffffffb1672a03 down_read+0x13 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
127 | ffffffffb106bd85 __do_page_fault+0x445 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
128 | ffffffffb18015f5 page_fault+0x45 (/lib/modules/4.14.78-1-lts/build/vmlinux) | |
129 | 7f38e4252591 new_heap+0x101 (/usr/lib/libc-2.28.so) | |
130 | 7f38e4252d0b arena_get2.part.4+0x2fb (/usr/lib/libc-2.28.so) | |
131 | 7f38e4255b1c tcache_init.part.6+0xec (/usr/lib/libc-2.28.so) | |
132 | 7f38e42569e5 __GI___libc_malloc+0x115 (inlined) | |
133 | 7f38e4241790 __GI__IO_file_doallocate+0x90 (inlined) | |
134 | 7f38e424fbbf __GI__IO_doallocbuf+0x4f (inlined) | |
135 | 7f38e424ee47 __GI__IO_file_overflow+0x197 (inlined) | |
136 | 7f38e424df36 _IO_new_file_xsputn+0x116 (inlined) | |
137 | 7f38e4242bfb __GI__IO_fwrite+0xdb (inlined) | |
138 | 7f38e463fa6d std::basic_streambuf<char, std::char_traits<char> >::sputn(char const*, long)+0x1cd (inlined) | |
139 | 7f38e463fa6d std::ostreambuf_iterator<char, std::char_traits<char> >::_M_put(char const*, long)+0x1cd (inlined) | |
140 | 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) | |
141 | 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> | |
142 | 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> | |
143 | 7f38e464bd70 std::ostream& std::ostream::_M_insert<double>(double)+0x90 (/usr/lib/libstdc++.so.6.0.25) | |
144 | 563b9cb502f7 std::ostream::operator<<(double)+0xb7 (inlined) | |
145 | 563b9cb502f7 worker()+0xb7 (/ssd/milian/projects/kdab/rnd/hotspot/build/tests/test-clients/cpp-locking/cpp-locking) | |
146 | 6eab825c1ee3e4ff [unknown] ([unknown]) | |
147 | ``` | |
148 | ||
149 | Note that the backtrace is still stopping too early, when compared to | |
150 | the nice results obtained via libunwind. It's unclear so far what the | |
151 | reason for that is. | |
152 | ||
153 | Committer note: | |
154 | ||
155 | Further comment by Milian on the thread started on the Link: tag below: | |
156 | ||
157 | --- | |
158 | The remaining issue is due to a bug in elfutils: | |
159 | ||
160 | https://sourceware.org/ml/elfutils-devel/2018-q4/msg00089.html | |
161 | ||
162 | With both patches applied, libunwind and elfutils produce the same output for | |
163 | the above scenario. | |
164 | --- | |
165 | ||
166 | Signed-off-by: Milian Wolff <milian.wolff@kdab.com> | |
167 | Acked-by: Jiri Olsa <jolsa@kernel.org> | |
168 | Link: http://lkml.kernel.org/r/20181029141644.3907-1-milian.wolff@kdab.com | |
169 | Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> | |
170 | Signed-off-by: Sasha Levin <sashal@kernel.org> | |
171 | --- | |
172 | tools/perf/util/unwind-libdw.c | 4 ++-- | |
173 | 1 file changed, 2 insertions(+), 2 deletions(-) | |
174 | ||
175 | diff --git a/tools/perf/util/unwind-libdw.c b/tools/perf/util/unwind-libdw.c | |
176 | index 8e969f28cc59..f1fe5acdbba4 100644 | |
177 | --- a/tools/perf/util/unwind-libdw.c | |
178 | +++ b/tools/perf/util/unwind-libdw.c | |
179 | @@ -44,13 +44,13 @@ static int __report_module(struct addr_location *al, u64 ip, | |
180 | Dwarf_Addr s; | |
181 | ||
182 | dwfl_module_info(mod, NULL, &s, NULL, NULL, NULL, NULL, NULL); | |
183 | - if (s != al->map->start) | |
184 | + if (s != al->map->start - al->map->pgoff) | |
185 | mod = 0; | |
186 | } | |
187 | ||
188 | if (!mod) | |
189 | mod = dwfl_report_elf(ui->dwfl, dso->short_name, | |
190 | - (dso->symsrc_filename ? dso->symsrc_filename : dso->long_name), -1, al->map->start, | |
191 | + (dso->symsrc_filename ? dso->symsrc_filename : dso->long_name), -1, al->map->start - al->map->pgoff, | |
192 | false); | |
193 | ||
194 | return mod && dwfl_addrmodule(ui->dwfl, ip) == mod ? 0 : -1; | |
195 | -- | |
196 | 2.19.1 | |
197 |