Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1642327 > unrolled thread
| Started by | Milian Wolff <milian.wolff@kdab.com> |
|---|---|
| First post | 2017-05-16 11:10 +0200 |
| Last post | 2017-05-18 10:20 +0200 |
| Articles | 6 — 2 participants |
Back to article view | Back to linux.kernel
[PATCH v2] perf report: fix off-by-one for non-activation frames Milian Wolff <milian.wolff@kdab.com> - 2017-05-16 11:10 +0200
Re: [PATCH v2] perf report: fix off-by-one for non-activation frames Namhyung Kim <namhyung@kernel.org> - 2017-05-16 16:50 +0200
Re: [PATCH v2] perf report: fix off-by-one for non-activation frames Milian Wolff <milian.wolff@kdab.com> - 2017-05-16 18:20 +0200
Re: [PATCH v2] perf report: fix off-by-one for non-activation frames Milian Wolff <milian.wolff@kdab.com> - 2017-05-16 18:30 +0200
Re: [PATCH v2] perf report: fix off-by-one for non-activation frames Namhyung Kim <namhyung@kernel.org> - 2017-05-17 07:20 +0200
Re: [PATCH v2] perf report: fix off-by-one for non-activation frames Milian Wolff <milian.wolff@kdab.com> - 2017-05-18 10:20 +0200
| From | Milian Wolff <milian.wolff@kdab.com> |
|---|---|
| Date | 2017-05-16 11:10 +0200 |
| Subject | [PATCH v2] perf report: fix off-by-one for non-activation frames |
| Message-ID | <tHGEq-3GY-31@gated-at.bofh.it> |
As the documentation for dwfl_frame_pc says, frames that
are no activation frames need to have their program counter
decremented by one to properly find the function of the caller.
This fixes many cases where perf report currently attributes
the cost to the next line. I.e. I have code like this:
~~~~~~~~~~~~~~~
#include <thread>
#include <chrono>
using namespace std;
int main()
{
this_thread::sleep_for(chrono::milliseconds(1000));
this_thread::sleep_for(chrono::milliseconds(100));
this_thread::sleep_for(chrono::milliseconds(10));
return 0;
}
~~~~~~~~~~~~~~~
Now compile and record it:
~~~~~~~~~~~~~~~
g++ -std=c++11 -g -O2 test.cpp
echo 1 | sudo tee /proc/sys/kernel/sched_schedstats
perf record \
--event sched:sched_stat_sleep \
--event sched:sched_process_exit \
--event sched:sched_switch --call-graph=dwarf \
--output perf.data.raw \
./a.out
echo 0 | sudo tee /proc/sys/kernel/sched_schedstats
perf inject --sched-stat --input perf.data.raw --output perf.data
~~~~~~~~~~~~~~~
Before this patch, the report clearly shows the off-by-one issue.
Most notably, the last sleep invocation is incorrectly attributed
to the "return 0;" line:
~~~~~~~~~~~~~~~
Overhead Source:Line
........ ...........
100.00% core.c:0
|
---__schedule core.c:0
schedule
do_nanosleep hrtimer.c:0
hrtimer_nanosleep
sys_nanosleep
entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
__nanosleep_nocancel .:0
std::this_thread::sleep_for<long, std::ratio<1l, 1000l> > thread:323
|
|--90.08%--main test.cpp:9
| __libc_start_main
| _start
|
|--9.01%--main test.cpp:10
| __libc_start_main
| _start
|
--0.91%--main test.cpp:13
__libc_start_main
_start
~~~~~~~~~~~~~~~
With this patch here applied, the issue is fixed. The report becomes
much more usable:
~~~~~~~~~~~~~~~
Overhead Source:Line
........ ...........
100.00% core.c:0
|
---__schedule core.c:0
schedule
do_nanosleep hrtimer.c:0
hrtimer_nanosleep
sys_nanosleep
entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
__nanosleep_nocancel .:0
std::this_thread::sleep_for<long, std::ratio<1l, 1000l> > thread:323
|
|--90.08%--main test.cpp:8
| __libc_start_main
| _start
|
|--9.01%--main test.cpp:9
| __libc_start_main
| _start
|
--0.91%--main test.cpp:10
__libc_start_main
_start
~~~~~~~~~~~~~~~
Note how this patch fixes this issue for both unwinding methods, i.e.
both dwfl and libunwind. The former case is straight-forward thanks
to dwfl_frame_pc. For libunwind, we replace the functionality via
unw_is_signal_frame for any but the very first frame.
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Yao Jin <yao.jin@linux.intel.com>
Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
---
tools/perf/util/unwind-libdw.c | 6 +++++-
tools/perf/util/unwind-libunwind-local.c | 14 ++++++++++++++
2 files changed, 19 insertions(+), 1 deletion(-)
v2:
- use unw_is_signal_frame to also fix this issue for libunwind
diff --git a/tools/perf/util/unwind-libdw.c b/tools/perf/util/unwind-libdw.c
index f90e11a555b2..943a06291587 100644
--- a/tools/perf/util/unwind-libdw.c
+++ b/tools/perf/util/unwind-libdw.c
@@ -168,12 +168,16 @@ frame_callback(Dwfl_Frame *state, void *arg)
{
struct unwind_info *ui = arg;
Dwarf_Addr pc;
+ bool isactivation;
- if (!dwfl_frame_pc(state, &pc, NULL)) {
+ if (!dwfl_frame_pc(state, &pc, &isactivation)) {
pr_err("%s", dwfl_errmsg(-1));
return DWARF_CB_ABORT;
}
+ if (!isactivation)
+ --pc;
+
return entry(pc, ui) || !(--ui->max_stack) ?
DWARF_CB_ABORT : DWARF_CB_OK;
}
diff --git a/tools/perf/util/unwind-libunwind-local.c b/tools/perf/util/unwind-libunwind-local.c
index f8455bed6e65..30ab26375c80 100644
--- a/tools/perf/util/unwind-libunwind-local.c
+++ b/tools/perf/util/unwind-libunwind-local.c
@@ -690,8 +690,22 @@ static int get_entries(struct unwind_info *ui, unwind_entry_cb_t cb,
if (ret)
display_error(ret);
+ bool previous_frame_was_signal = false;
while (!ret && (unw_step(&c) > 0) && i < max_stack) {
unw_get_reg(&c, UNW_REG_IP, &ips[i]);
+
+ /*
+ * Decrement the IP for any non-activation frames.
+ * this is required to properly find the srcline
+ * for caller frames.
+ * See also the documentation for dwfl_frame_pc,
+ * which this code tries to replicate.
+ */
+ bool frame_is_signal = unw_is_signal_frame(&c) > 0;
+ if (!previous_frame_was_signal && !frame_is_signal)
+ --ips[i];
+ previous_frame_was_signal = frame_is_signal;
+
++i;
}
--
2.13.0
[toc] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2017-05-16 16:50 +0200 |
| Message-ID | <tHLXs-6QP-9@gated-at.bofh.it> |
| In reply to | #1642327 |
On Tue, May 16, 2017 at 10:59:51AM +0200, Milian Wolff wrote:
> As the documentation for dwfl_frame_pc says, frames that
> are no activation frames need to have their program counter
> decremented by one to properly find the function of the caller.
>
> This fixes many cases where perf report currently attributes
> the cost to the next line. I.e. I have code like this:
>
> ~~~~~~~~~~~~~~~
> #include <thread>
> #include <chrono>
>
> using namespace std;
>
> int main()
> {
> this_thread::sleep_for(chrono::milliseconds(1000));
> this_thread::sleep_for(chrono::milliseconds(100));
> this_thread::sleep_for(chrono::milliseconds(10));
>
> return 0;
> }
> ~~~~~~~~~~~~~~~
It'd be nice if the test program has a signal frame for verification.
>
> Now compile and record it:
>
> ~~~~~~~~~~~~~~~
> g++ -std=c++11 -g -O2 test.cpp
> echo 1 | sudo tee /proc/sys/kernel/sched_schedstats
> perf record \
> --event sched:sched_stat_sleep \
> --event sched:sched_process_exit \
> --event sched:sched_switch --call-graph=dwarf \
> --output perf.data.raw \
> ./a.out
> echo 0 | sudo tee /proc/sys/kernel/sched_schedstats
> perf inject --sched-stat --input perf.data.raw --output perf.data
> ~~~~~~~~~~~~~~~
>
> Before this patch, the report clearly shows the off-by-one issue.
> Most notably, the last sleep invocation is incorrectly attributed
> to the "return 0;" line:
>
> ~~~~~~~~~~~~~~~
> Overhead Source:Line
> ........ ...........
>
> 100.00% core.c:0
> |
> ---__schedule core.c:0
> schedule
> do_nanosleep hrtimer.c:0
> hrtimer_nanosleep
> sys_nanosleep
> entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
> __nanosleep_nocancel .:0
> std::this_thread::sleep_for<long, std::ratio<1l, 1000l> > thread:323
> |
> |--90.08%--main test.cpp:9
> | __libc_start_main
> | _start
> |
> |--9.01%--main test.cpp:10
> | __libc_start_main
> | _start
> |
> --0.91%--main test.cpp:13
> __libc_start_main
> _start
> ~~~~~~~~~~~~~~~
>
> With this patch here applied, the issue is fixed. The report becomes
> much more usable:
>
> ~~~~~~~~~~~~~~~
> Overhead Source:Line
> ........ ...........
>
> 100.00% core.c:0
> |
> ---__schedule core.c:0
> schedule
> do_nanosleep hrtimer.c:0
> hrtimer_nanosleep
> sys_nanosleep
> entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
> __nanosleep_nocancel .:0
> std::this_thread::sleep_for<long, std::ratio<1l, 1000l> > thread:323
> |
> |--90.08%--main test.cpp:8
> | __libc_start_main
> | _start
> |
> |--9.01%--main test.cpp:9
> | __libc_start_main
> | _start
> |
> --0.91%--main test.cpp:10
> __libc_start_main
> _start
> ~~~~~~~~~~~~~~~
>
> Note how this patch fixes this issue for both unwinding methods, i.e.
> both dwfl and libunwind. The former case is straight-forward thanks
> to dwfl_frame_pc. For libunwind, we replace the functionality via
> unw_is_signal_frame for any but the very first frame.
>
> Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
> Cc: David Ahern <dsahern@gmail.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Cc: Yao Jin <yao.jin@linux.intel.com>
> Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
> ---
> tools/perf/util/unwind-libdw.c | 6 +++++-
> tools/perf/util/unwind-libunwind-local.c | 14 ++++++++++++++
> 2 files changed, 19 insertions(+), 1 deletion(-)
>
> v2:
> - use unw_is_signal_frame to also fix this issue for libunwind
>
> diff --git a/tools/perf/util/unwind-libdw.c b/tools/perf/util/unwind-libdw.c
> index f90e11a555b2..943a06291587 100644
> --- a/tools/perf/util/unwind-libdw.c
> +++ b/tools/perf/util/unwind-libdw.c
> @@ -168,12 +168,16 @@ frame_callback(Dwfl_Frame *state, void *arg)
> {
> struct unwind_info *ui = arg;
> Dwarf_Addr pc;
> + bool isactivation;
>
> - if (!dwfl_frame_pc(state, &pc, NULL)) {
> + if (!dwfl_frame_pc(state, &pc, &isactivation)) {
> pr_err("%s", dwfl_errmsg(-1));
> return DWARF_CB_ABORT;
> }
>
> + if (!isactivation)
> + --pc;
> +
> return entry(pc, ui) || !(--ui->max_stack) ?
> DWARF_CB_ABORT : DWARF_CB_OK;
> }
> diff --git a/tools/perf/util/unwind-libunwind-local.c b/tools/perf/util/unwind-libunwind-local.c
> index f8455bed6e65..30ab26375c80 100644
> --- a/tools/perf/util/unwind-libunwind-local.c
> +++ b/tools/perf/util/unwind-libunwind-local.c
> @@ -690,8 +690,22 @@ static int get_entries(struct unwind_info *ui, unwind_entry_cb_t cb,
> if (ret)
> display_error(ret);
>
> + bool previous_frame_was_signal = false;
> while (!ret && (unw_step(&c) > 0) && i < max_stack) {
> unw_get_reg(&c, UNW_REG_IP, &ips[i]);
> +
> + /*
> + * Decrement the IP for any non-activation frames.
> + * this is required to properly find the srcline
> + * for caller frames.
> + * See also the documentation for dwfl_frame_pc,
> + * which this code tries to replicate.
> + */
> + bool frame_is_signal = unw_is_signal_frame(&c) > 0;
> + if (!previous_frame_was_signal && !frame_is_signal)
> + --ips[i];
> + previous_frame_was_signal = frame_is_signal;
Does it need to check previous frame too?
Thanks,
Namhyung
> +
> ++i;
> }
>
> --
> 2.13.0
>
[toc] | [prev] | [next] | [standalone]
| From | Milian Wolff <milian.wolff@kdab.com> |
|---|---|
| Date | 2017-05-16 18:20 +0200 |
| Message-ID | <tHNmx-7PP-3@gated-at.bofh.it> |
| In reply to | #1642595 |
[Multipart message — attachments visible in raw view] — view raw
On Dienstag, 16. Mai 2017 16:38:29 CEST Namhyung Kim wrote:
> On Tue, May 16, 2017 at 10:59:51AM +0200, Milian Wolff wrote:
> > As the documentation for dwfl_frame_pc says, frames that
> > are no activation frames need to have their program counter
> > decremented by one to properly find the function of the caller.
> >
> > This fixes many cases where perf report currently attributes
> > the cost to the next line. I.e. I have code like this:
> >
> > ~~~~~~~~~~~~~~~
> >
> > #include <thread>
> > #include <chrono>
> >
> > using namespace std;
> >
> > int main()
> > {
> >
> > this_thread::sleep_for(chrono::milliseconds(1000));
> > this_thread::sleep_for(chrono::milliseconds(100));
> > this_thread::sleep_for(chrono::milliseconds(10));
> >
> > return 0;
> >
> > }
> >
> > ~~~~~~~~~~~~~~~
>
> It'd be nice if the test program has a signal frame for verification.
I have pretty much zero experience about signals. Would it be enough to add a
signal handler for, say, SIGUSR1 to my test application and then trigger a
sleep when that signal is delivered? If that should be enough, I'll write and
test it out.
<snip>
> > diff --git a/tools/perf/util/unwind-libunwind-local.c
> > b/tools/perf/util/unwind-libunwind-local.c index
> > f8455bed6e65..30ab26375c80 100644
> > --- a/tools/perf/util/unwind-libunwind-local.c
> > +++ b/tools/perf/util/unwind-libunwind-local.c
> > @@ -690,8 +690,22 @@ static int get_entries(struct unwind_info *ui,
> > unwind_entry_cb_t cb,>
> > if (ret)
> >
> > display_error(ret);
> >
> > + bool previous_frame_was_signal = false;
> >
> > while (!ret && (unw_step(&c) > 0) && i < max_stack) {
> >
> > unw_get_reg(&c, UNW_REG_IP, &ips[i]);
> >
> > +
> > + /*
> > + * Decrement the IP for any non-activation frames.
> > + * this is required to properly find the srcline
> > + * for caller frames.
> > + * See also the documentation for dwfl_frame_pc,
> > + * which this code tries to replicate.
> > + */
> > + bool frame_is_signal = unw_is_signal_frame(&c) > 0;
> > + if (!previous_frame_was_signal && !frame_is_signal)
> > + --ips[i];
> > + previous_frame_was_signal = frame_is_signal;
>
> Does it need to check previous frame too?
That's what dwfl_frame_pc does, if I'm not misunderstanding it's source code?
Bye
--
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts
[toc] | [prev] | [next] | [standalone]
| From | Milian Wolff <milian.wolff@kdab.com> |
|---|---|
| Date | 2017-05-16 18:30 +0200 |
| Message-ID | <tHNwe-7SQ-17@gated-at.bofh.it> |
| In reply to | #1642641 |
[Multipart message — attachments visible in raw view] — view raw
On Dienstag, 16. Mai 2017 18:17:26 CEST Milian Wolff wrote:
> On Dienstag, 16. Mai 2017 16:38:29 CEST Namhyung Kim wrote:
> > On Tue, May 16, 2017 at 10:59:51AM +0200, Milian Wolff wrote:
> > > As the documentation for dwfl_frame_pc says, frames that
> > > are no activation frames need to have their program counter
> > > decremented by one to properly find the function of the caller.
> > >
> > > This fixes many cases where perf report currently attributes
> > > the cost to the next line. I.e. I have code like this:
> > >
> > > ~~~~~~~~~~~~~~~
> > >
> > > #include <thread>
> > > #include <chrono>
> > >
> > > using namespace std;
> > >
> > > int main()
> > > {
> > >
> > > this_thread::sleep_for(chrono::milliseconds(1000));
> > > this_thread::sleep_for(chrono::milliseconds(100));
> > > this_thread::sleep_for(chrono::milliseconds(10));
> > >
> > > return 0;
> > >
> > > }
> > >
> > > ~~~~~~~~~~~~~~~
> >
> > It'd be nice if the test program has a signal frame for verification.
>
> I have pretty much zero experience about signals. Would it be enough to add
> a signal handler for, say, SIGUSR1 to my test application and then trigger
> a sleep when that signal is delivered? If that should be enough, I'll write
> and test it out.
~~~~~~~~~~~~~~~
#include <thread>
#include <chrono>
#include <signal.h>
using namespace std;
volatile bool run_loop = true;
void my_handler(int signum)
{
this_thread::sleep_for(chrono::milliseconds(1000));
this_thread::sleep_for(chrono::milliseconds(100));
this_thread::sleep_for(chrono::milliseconds(10));
run_loop = false;
}
int main()
{
signal(SIGUSR1, my_handler);
while (run_loop) {}
return 0;
}
~~~~~~~~~~~~~~~
This does not properly unwind neither before nor after this patch. I only ever
get:
100.00% core.c:0
|
---__schedule core.c:0
schedule
do_nanosleep hrtimer.c:0
hrtimer_nanosleep
sys_nanosleep
entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
__nanosleep_nocancel .:0
std::this_thread::sleep_for<long, std::ratio<1l, 1000l> >
thread:323
So... should this work? Please tell me how to test this properly.
Thanks
--
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts
[toc] | [prev] | [next] | [standalone]
| From | Namhyung Kim <namhyung@kernel.org> |
|---|---|
| Date | 2017-05-17 07:20 +0200 |
| Message-ID | <tHZxn-7lc-3@gated-at.bofh.it> |
| In reply to | #1642664 |
On Tue, May 16, 2017 at 06:26:47PM +0200, Milian Wolff wrote:
> On Dienstag, 16. Mai 2017 18:17:26 CEST Milian Wolff wrote:
> > On Dienstag, 16. Mai 2017 16:38:29 CEST Namhyung Kim wrote:
> > > On Tue, May 16, 2017 at 10:59:51AM +0200, Milian Wolff wrote:
> > > > As the documentation for dwfl_frame_pc says, frames that
> > > > are no activation frames need to have their program counter
> > > > decremented by one to properly find the function of the caller.
> > > >
> > > > This fixes many cases where perf report currently attributes
> > > > the cost to the next line. I.e. I have code like this:
> > > >
> > > > ~~~~~~~~~~~~~~~
> > > >
> > > > #include <thread>
> > > > #include <chrono>
> > > >
> > > > using namespace std;
> > > >
> > > > int main()
> > > > {
> > > >
> > > > this_thread::sleep_for(chrono::milliseconds(1000));
> > > > this_thread::sleep_for(chrono::milliseconds(100));
> > > > this_thread::sleep_for(chrono::milliseconds(10));
> > > >
> > > > return 0;
> > > >
> > > > }
> > > >
> > > > ~~~~~~~~~~~~~~~
> > >
> > > It'd be nice if the test program has a signal frame for verification.
> >
> > I have pretty much zero experience about signals. Would it be enough to add
> > a signal handler for, say, SIGUSR1 to my test application and then trigger
> > a sleep when that signal is delivered? If that should be enough, I'll write
> > and test it out.
>
> ~~~~~~~~~~~~~~~
> #include <thread>
> #include <chrono>
> #include <signal.h>
>
> using namespace std;
>
> volatile bool run_loop = true;
>
> void my_handler(int signum)
> {
> this_thread::sleep_for(chrono::milliseconds(1000));
> this_thread::sleep_for(chrono::milliseconds(100));
> this_thread::sleep_for(chrono::milliseconds(10));
> run_loop = false;
> }
>
> int main()
> {
> signal(SIGUSR1, my_handler);
>
> while (run_loop) {}
>
> return 0;
> }
> ~~~~~~~~~~~~~~~
>
> This does not properly unwind neither before nor after this patch. I only ever
> get:
>
> 100.00% core.c:0
> |
> ---__schedule core.c:0
> schedule
> do_nanosleep hrtimer.c:0
> hrtimer_nanosleep
> sys_nanosleep
> entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
> __nanosleep_nocancel .:0
> std::this_thread::sleep_for<long, std::ratio<1l, 1000l> >
> thread:323
>
> So... should this work? Please tell me how to test this properly.
How did you send the SIGUSR1 to the process?
Anyway it does nothing to do with inlining, right? I just wrote a
test code below to burn a cpu with or without a signal frame.
$ nl -ba frame-addr.c
1 #include <stdio.h>
2 #include <stdlib.h>
3 #include <signal.h>
4
5 #define __noinline __attribute__((noinline))
6
7 __noinline void bar(void)
8 {
9 volatile long cnt = 0;
10
11 for (cnt = 0; cnt < 100000000; cnt++);
12 }
13
14 __noinline void foo(void)
15 {
16 bar();
17 }
18
19 void sig_handler(int sig)
20 {
21 foo();
22 }
23
24 int main(void)
25 {
26 signal(SIGUSR1, sig_handler);
27 raise(SIGUSR1);
28
29 foo();
30 return 0;
31 }
$ gcc -O2 -g -fno-optimize-sibling-calls -o frame-addr frame-addr.c
$ perf record --call-graph dwarf ./frame-addr
$ perf report -q -g srcline | head -15
99.88% frame-addr frame-addr [.] bar
|
---bar frame-addr.c:11
foo frame-addr.c:16
|
|--51.12%--main frame-addr.c:29
| __libc_start_main
| _start
|
--48.76%--sig_handler frame-addr.c:21
0x33a8f
raise .:0
main frame-addr.c:29 <--- bad
__libc_start_main
_start
Note that 'raise' was called at line 27. It seems that simply
checking current frame fixes it.
Thanks,
Namhyung
[toc] | [prev] | [next] | [standalone]
| From | Milian Wolff <milian.wolff@kdab.com> |
|---|---|
| Date | 2017-05-18 10:20 +0200 |
| Message-ID | <tIoP7-7E3-1@gated-at.bofh.it> |
| In reply to | #1642980 |
[Multipart message — attachments visible in raw view] — view raw
On Mittwoch, 17. Mai 2017 07:12:21 CEST Namhyung Kim wrote:
> On Tue, May 16, 2017 at 06:26:47PM +0200, Milian Wolff wrote:
> > On Dienstag, 16. Mai 2017 18:17:26 CEST Milian Wolff wrote:
> > > On Dienstag, 16. Mai 2017 16:38:29 CEST Namhyung Kim wrote:
> > > > On Tue, May 16, 2017 at 10:59:51AM +0200, Milian Wolff wrote:
> > > > > As the documentation for dwfl_frame_pc says, frames that
> > > > > are no activation frames need to have their program counter
> > > > > decremented by one to properly find the function of the caller.
> > > > >
> > > > > This fixes many cases where perf report currently attributes
> > > > > the cost to the next line. I.e. I have code like this:
> > > > >
> > > > > ~~~~~~~~~~~~~~~
> > > > >
> > > > > #include <thread>
> > > > > #include <chrono>
> > > > >
> > > > > using namespace std;
> > > > >
> > > > > int main()
> > > > > {
> > > > >
> > > > > this_thread::sleep_for(chrono::milliseconds(1000));
> > > > > this_thread::sleep_for(chrono::milliseconds(100));
> > > > > this_thread::sleep_for(chrono::milliseconds(10));
> > > > >
> > > > > return 0;
> > > > >
> > > > > }
> > > > >
> > > > > ~~~~~~~~~~~~~~~
> > > >
> > > > It'd be nice if the test program has a signal frame for verification.
> > >
> > > I have pretty much zero experience about signals. Would it be enough to
> > > add
> > > a signal handler for, say, SIGUSR1 to my test application and then
> > > trigger
> > > a sleep when that signal is delivered? If that should be enough, I'll
> > > write
> > > and test it out.
> >
> > ~~~~~~~~~~~~~~~
> > #include <thread>
> > #include <chrono>
> > #include <signal.h>
> >
> > using namespace std;
> >
> > volatile bool run_loop = true;
> >
> > void my_handler(int signum)
> > {
> >
> > this_thread::sleep_for(chrono::milliseconds(1000));
> > this_thread::sleep_for(chrono::milliseconds(100));
> > this_thread::sleep_for(chrono::milliseconds(10));
> > run_loop = false;
> >
> > }
> >
> > int main()
> > {
> >
> > signal(SIGUSR1, my_handler);
> >
> > while (run_loop) {}
> >
> > return 0;
> >
> > }
> > ~~~~~~~~~~~~~~~
> >
> > This does not properly unwind neither before nor after this patch. I only
> > ever>
> > get:
> > 100.00% core.c:0
> >
> > ---__schedule core.c:0
> >
> > schedule
> > do_nanosleep hrtimer.c:0
> > hrtimer_nanosleep
> > sys_nanosleep
> > entry_SYSCALL_64_fastpath .tmp_entry_64.o:0
> > __nanosleep_nocancel .:0
> > std::this_thread::sleep_for<long, std::ratio<1l, 1000l> >
> >
> > thread:323
> >
> > So... should this work? Please tell me how to test this properly.
>
> How did you send the SIGUSR1 to the process?
>
> Anyway it does nothing to do with inlining, right? I just wrote a
> test code below to burn a cpu with or without a signal frame.
>
> $ nl -ba frame-addr.c
> 1 #include <stdio.h>
> 2 #include <stdlib.h>
> 3 #include <signal.h>
> 4
> 5 #define __noinline __attribute__((noinline))
> 6
> 7 __noinline void bar(void)
> 8 {
> 9 volatile long cnt = 0;
> 10
> 11 for (cnt = 0; cnt < 100000000; cnt++);
> 12 }
> 13
> 14 __noinline void foo(void)
> 15 {
> 16 bar();
> 17 }
> 18
> 19 void sig_handler(int sig)
> 20 {
> 21 foo();
> 22 }
> 23
> 24 int main(void)
> 25 {
> 26 signal(SIGUSR1, sig_handler);
> 27 raise(SIGUSR1);
> 28
> 29 foo();
> 30 return 0;
> 31 }
>
> $ gcc -O2 -g -fno-optimize-sibling-calls -o frame-addr frame-addr.c
>
> $ perf record --call-graph dwarf ./frame-addr
>
> $ perf report -q -g srcline | head -15
> 99.88% frame-addr frame-addr [.] bar
>
> ---bar frame-addr.c:11
> foo frame-addr.c:16
>
> |--51.12%--main frame-addr.c:29
> |
> | __libc_start_main
> | _start
>
> --48.76%--sig_handler frame-addr.c:21
> 0x33a8f
> raise .:0
> main frame-addr.c:29 <--- bad
> __libc_start_main
> _start
>
> Note that 'raise' was called at line 27. It seems that simply
> checking current frame fixes it.
Got it - thanks for your test case. I fixed it and will resend v3 of this
patch shortly.
Thanks
--
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web