* [PATCH v2] perf report: fix off-by-one for non-activation frames
@ 2017-05-16 8:59 Milian Wolff
2017-05-16 14:38 ` Namhyung Kim
0 siblings, 1 reply; 6+ messages in thread
From: Milian Wolff @ 2017-05-16 8:59 UTC (permalink / raw)
To: Linux-kernel
Cc: linux-perf-users, Milian Wolff, Arnaldo Carvalho de Melo,
David Ahern, Namhyung Kim, Peter Zijlstra, Yao Jin
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
^ permalink raw reply related [flat|nested] 6+ messages in thread* Re: [PATCH v2] perf report: fix off-by-one for non-activation frames
2017-05-16 8:59 [PATCH v2] perf report: fix off-by-one for non-activation frames Milian Wolff
@ 2017-05-16 14:38 ` Namhyung Kim
2017-05-16 16:17 ` Milian Wolff
0 siblings, 1 reply; 6+ messages in thread
From: Namhyung Kim @ 2017-05-16 14:38 UTC (permalink / raw)
To: Milian Wolff
Cc: Linux-kernel, linux-perf-users, Arnaldo Carvalho de Melo,
David Ahern, Peter Zijlstra, Yao Jin, kernel-team
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
>
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH v2] perf report: fix off-by-one for non-activation frames
2017-05-16 14:38 ` Namhyung Kim
@ 2017-05-16 16:17 ` Milian Wolff
2017-05-16 16:26 ` Milian Wolff
0 siblings, 1 reply; 6+ messages in thread
From: Milian Wolff @ 2017-05-16 16:17 UTC (permalink / raw)
To: Namhyung Kim
Cc: Linux-kernel, linux-perf-users, Arnaldo Carvalho de Melo,
David Ahern, Peter Zijlstra, Yao Jin, kernel-team
[-- Attachment #1: Type: text/plain, Size: 2512 bytes --]
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
[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH v2] perf report: fix off-by-one for non-activation frames
2017-05-16 16:17 ` Milian Wolff
@ 2017-05-16 16:26 ` Milian Wolff
2017-05-17 5:12 ` Namhyung Kim
0 siblings, 1 reply; 6+ messages in thread
From: Milian Wolff @ 2017-05-16 16:26 UTC (permalink / raw)
To: Namhyung Kim
Cc: Linux-kernel, linux-perf-users, Arnaldo Carvalho de Melo,
David Ahern, Peter Zijlstra, Yao Jin, kernel-team
[-- Attachment #1: Type: text/plain, Size: 2441 bytes --]
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
[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH v2] perf report: fix off-by-one for non-activation frames
2017-05-16 16:26 ` Milian Wolff
@ 2017-05-17 5:12 ` Namhyung Kim
2017-05-18 8:19 ` Milian Wolff
0 siblings, 1 reply; 6+ messages in thread
From: Namhyung Kim @ 2017-05-17 5:12 UTC (permalink / raw)
To: Milian Wolff
Cc: Linux-kernel, linux-perf-users, Arnaldo Carvalho de Melo,
David Ahern, Peter Zijlstra, Yao Jin, kernel-team
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
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: [PATCH v2] perf report: fix off-by-one for non-activation frames
2017-05-17 5:12 ` Namhyung Kim
@ 2017-05-18 8:19 ` Milian Wolff
0 siblings, 0 replies; 6+ messages in thread
From: Milian Wolff @ 2017-05-18 8:19 UTC (permalink / raw)
To: Namhyung Kim
Cc: Linux-kernel, linux-perf-users, Arnaldo Carvalho de Melo,
David Ahern, Peter Zijlstra, Yao Jin, kernel-team
[-- Attachment #1: Type: text/plain, Size: 4759 bytes --]
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
[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2017-05-18 8:19 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-05-16 8:59 [PATCH v2] perf report: fix off-by-one for non-activation frames Milian Wolff
2017-05-16 14:38 ` Namhyung Kim
2017-05-16 16:17 ` Milian Wolff
2017-05-16 16:26 ` Milian Wolff
2017-05-17 5:12 ` Namhyung Kim
2017-05-18 8:19 ` Milian Wolff
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).