2015-08-11 14:18:35

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: perf probe -L sys_select or sys_poll

Hi Masami,

Have you noticed that sys_select or sys_poll stops after the
first few lines? Please let me know if you need more info than is below.

[root@zoo ~]# perf probe -L sys_select
<SyS_select@/home/git/linux/fs/select.c:0>
0 SYSCALL_DEFINE5(select, int, n, fd_set __user *, inp, fd_set __user *, outp,
fd_set __user *, exp, struct timeval __user *, tvp)
{
struct timespec end_time, *to = NULL;

[root@zoo ~]# perf probe -L sys_poll
<SyS_poll@/home/git/linux/fs/select.c:0>
0 SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
int, timeout_msecs)
{
struct timespec end_time, *to = NULL;

[root@zoo ~]#

I haven't investigated it too much, if there is some trouble that makes
'perf probe -L' to stop like that maybe we should warn the user somehow?

Using -v didn't helped that much:

[root@zoo ~]# perf probe -v -L sys_poll
Using /root/.debug/.build-id/a8/26726b5ddacfab1f0bade868f1a7924f6b20c4 for symbols
Open Debuginfo file: /root/.debug/.build-id/a8/26726b5ddacfab1f0bade868f1a7924f6b20c4
path: (null)
Symbol sys_poll address found : ffffffff812297e0
fname: /home/git/linux/fs/select.c, lineno:957
New line range: 957 to 2147483647
path: /home/git/linux/fs/select.c
<SyS_poll@/home/git/linux/fs/select.c:0>
0 SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
int, timeout_msecs)
{
struct timespec end_time, *to = NULL;

[root@zoo ~]#

[acme@zoo linux]$ cat /etc/fedora-release
Fedora release 21 (Twenty One)
[acme@zoo linux]$ rpm -q elfutils
elfutils-0.163-1.fc21.x86_64
[acme@zoo linux]$

[acme@zoo linux]$ uname -a
Linux zoo 4.2.0-rc5+ #1 SMP Tue Aug 4 16:55:11 BRT 2015 x86_64 x86_64 x86_64 GNU/Linux

objdump --start-address=0xffffffff812297e0 -dS /root/.debug/.build-id/a8/26726b5ddacfab1f0bade868f1a7924f6b20c4 | less
/root/.debug/.build-id/a8/26726b5ddacfab1f0bade868f1a7924f6b20c4: file format elf64-x86-64


Disassembly of section .text:

ffffffff812297e0 <SyS_poll>:
ret = -ERESTART_RESTARTBLOCK;
}
return ret;
}

SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
ffffffff812297e0: e8 4b af 53 00 callq ffffffff81764730 <__fentry__>
ffffffff812297e5: 55 push %rbp
ffffffff812297e6: 48 89 d1 mov %rdx,%rcx
ffffffff812297e9: 48 89 e5 mov %rsp,%rbp
ffffffff812297ec: 41 54 push %r12
ffffffff812297ee: 53 push %rbx
ffffffff812297ef: 49 89 fc mov %rdi,%r12
ffffffff812297f2: 48 89 f3 mov %rsi,%rbx
ffffffff812297f5: 48 83 ec 20 sub $0x20,%rsp
ffffffff812297f9: 65 48 8b 04 25 28 00 mov %gs:0x28,%rax
ffffffff81229800: 00 00
ffffffff81229802: 48 89 45 e8 mov %rax,-0x18(%rbp)
ffffffff81229806: 31 c0 xor %eax,%eax
int, timeout_msecs)
{
struct timespec end_time, *to = NULL;
int ret;

if (timeout_msecs >= 0) {
ffffffff81229808: 85 d2 test %edx,%edx
ffffffff8122980a: 78 64 js ffffffff81229870 <SyS_poll+0x90>
to = &end_time;
poll_select_set_timeout(to, timeout_msecs / MSEC_PER_SEC,
NSEC_PER_MSEC * (timeout_msecs % MSEC_PER_SEC));
ffffffff8122980c: 89 c8 mov %ecx,%eax
ffffffff8122980e: ba d3 4d 62 10 mov $0x10624dd3,%edx
struct timespec end_time, *to = NULL;
int ret;

if (timeout_msecs >= 0) {
to = &end_time;
poll_select_set_timeout(to, timeout_msecs / MSEC_PER_SEC,
ffffffff81229813: 48 8d 7d d8 lea -0x28(%rbp),%rdi
NSEC_PER_MSEC * (timeout_msecs % MSEC_PER_SEC));
ffffffff81229817: f7 ea imul %edx
ffffffff81229819: 89 c8 mov %ecx,%eax
ffffffff8122981b: c1 f8 1f sar $0x1f,%eax
ffffffff8122981e: c1 fa 06 sar $0x6,%edx
ffffffff81229821: 89 d6 mov %edx,%esi
ffffffff81229823: 29 c6 sub %eax,%esi
ffffffff81229825: 69 c6 e8 03 00 00 imul $0x3e8,%esi,%eax
struct timespec end_time, *to = NULL;
int ret;

if (timeout_msecs >= 0) {
to = &end_time;
poll_select_set_timeout(to, timeout_msecs / MSEC_PER_SEC,
ffffffff8122982b: 48 63 f6 movslq %esi,%rsi
NSEC_PER_MSEC * (timeout_msecs % MSEC_PER_SEC));
ffffffff8122982e: 29 c1 sub %eax,%ecx
ffffffff81229830: 48 63 c9 movslq %ecx,%rcx
struct timespec end_time, *to = NULL;
int ret;

if (timeout_msecs >= 0) {
to = &end_time;
poll_select_set_timeout(to, timeout_msecs / MSEC_PER_SEC,
ffffffff81229833: 48 69 d1 40 42 0f 00 imul $0xf4240,%rcx,%rdx
ffffffff8122983a: e8 21 eb ff ff callq ffffffff81228360 <poll_select_set_timeout>
NSEC_PER_MSEC * (timeout_msecs % MSEC_PER_SEC));
}

ret = do_sys_poll(ufds, nfds, to);
ffffffff8122983f: 48 8d 55 d8 lea -0x28(%rbp),%rdx
ffffffff81229843: 89 de mov %ebx,%esi
ffffffff81229845: 4c 89 e7 mov %r12,%rdi
ffffffff81229848: e8 73 f9 ff ff callq ffffffff812291c0 <do_sys_poll>

if (ret == -EINTR) {
ffffffff8122984d: 83 f8 fc cmp $0xfffffffc,%eax
ffffffff81229850: 74 5c je ffffffff812298ae <SyS_poll+0xce>
ret = -ERESTART_RESTARTBLOCK;
}
return ret;
}

SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
ffffffff81229852: 48 8b 5d e8 mov -0x18(%rbp),%rbx
ffffffff81229856: 65 48 33 1c 25 28 00 xor %gs:0x28,%rbx
ffffffff8122985d: 00 00
} else
restart_block->poll.has_timeout = 0;

ret = -ERESTART_RESTARTBLOCK;
}
return ret;
ffffffff8122985f: 48 98 cltq
ret = -ERESTART_RESTARTBLOCK;
}
return ret;
}

SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
ffffffff81229861: 0f 85 92 00 00 00 jne ffffffff812298f9 <SyS_poll+0x119>
ffffffff81229867: 48 83 c4 20 add $0x20,%rsp
ffffffff8122986b: 5b pop %rbx
ffffffff8122986c: 41 5c pop %r12
ffffffff8122986e: 5d pop %rbp
ffffffff8122986f: c3 retq
to = &end_time;
poll_select_set_timeout(to, timeout_msecs / MSEC_PER_SEC,
NSEC_PER_MSEC * (timeout_msecs % MSEC_PER_SEC));
}

ret = do_sys_poll(ufds, nfds, to);
ffffffff81229870: 31 d2 xor %edx,%edx
ffffffff81229872: e8 49 f9 ff ff callq ffffffff812291c0 <do_sys_poll>

if (ret == -EINTR) {
ffffffff81229877: 83 f8 fc cmp $0xfffffffc,%eax
ffffffff8122987a: 75 d6 jne ffffffff81229852 <SyS_poll+0x72>

DECLARE_PER_CPU(struct task_struct *, current_task);

static __always_inline struct task_struct *get_current(void)
{
return this_cpu_read_stable(current_task);
ffffffff8122987c: 65 48 8b 04 25 40 b9 mov %gs:0xb940,%rax
ffffffff81229883: 00 00
struct restart_block *restart_block;

restart_block = &current->restart_block;
restart_block->fn = do_restart_poll;
ffffffff81229885: 48 c7 80 58 03 00 00 movq $0xffffffff81229760,0x358(%rax)
ffffffff8122988c: 60 97 22 81
restart_block->poll.ufds = ufds;
ffffffff81229890: 4c 89 a0 60 03 00 00 mov %r12,0x360(%rax)
restart_block->poll.nfds = nfds;
ffffffff81229897: 89 98 68 03 00 00 mov %ebx,0x368(%rax)
if (timeout_msecs >= 0) {
restart_block->poll.tv_sec = end_time.tv_sec;
restart_block->poll.tv_nsec = end_time.tv_nsec;
restart_block->poll.has_timeout = 1;
} else
restart_block->poll.has_timeout = 0;
ffffffff8122989d: c7 80 6c 03 00 00 00 movl $0x0,0x36c(%rax)
ffffffff812298a4: 00 00 00

ret = -ERESTART_RESTARTBLOCK;
ffffffff812298a7: b8 fc fd ff ff mov $0xfffffdfc,%eax
ffffffff812298ac: eb a4 jmp ffffffff81229852 <SyS_poll+0x72>
restart_block->fn = do_restart_poll;
restart_block->poll.ufds = ufds;
restart_block->poll.nfds = nfds;

if (timeout_msecs >= 0) {
restart_block->poll.tv_sec = end_time.tv_sec;
ffffffff812298ae: 48 8b 55 d8 mov -0x28(%rbp),%rdx
ffffffff812298b2: 65 48 8b 04 25 40 b9 mov %gs:0xb940,%rax
ffffffff812298b9: 00 00

if (ret == -EINTR) {
struct restart_block *restart_block;

restart_block = &current->restart_block;
restart_block->fn = do_restart_poll;
ffffffff812298bb: 48 c7 80 58 03 00 00 movq $0xffffffff81229760,0x358(%rax)
ffffffff812298c2: 60 97 22 81
restart_block->poll.ufds = ufds;
ffffffff812298c6: 4c 89 a0 60 03 00 00 mov %r12,0x360(%rax)
restart_block->poll.nfds = nfds;

if (timeout_msecs >= 0) {
restart_block->poll.tv_sec = end_time.tv_sec;
ffffffff812298cd: 48 89 90 70 03 00 00 mov %rdx,0x370(%rax)
restart_block->poll.tv_nsec = end_time.tv_nsec;
ffffffff812298d4: 48 8b 55 e0 mov -0x20(%rbp),%rdx
struct restart_block *restart_block;

restart_block = &current->restart_block;
restart_block->fn = do_restart_poll;
restart_block->poll.ufds = ufds;
restart_block->poll.nfds = nfds;
ffffffff812298d8: 89 98 68 03 00 00 mov %ebx,0x368(%rax)

if (timeout_msecs >= 0) {
restart_block->poll.tv_sec = end_time.tv_sec;
restart_block->poll.tv_nsec = end_time.tv_nsec;
restart_block->poll.has_timeout = 1;
ffffffff812298de: c7 80 6c 03 00 00 01 movl $0x1,0x36c(%rax)
ffffffff812298e5: 00 00 00
restart_block->poll.ufds = ufds;
restart_block->poll.nfds = nfds;

if (timeout_msecs >= 0) {
restart_block->poll.tv_sec = end_time.tv_sec;
restart_block->poll.tv_nsec = end_time.tv_nsec;
ffffffff812298e8: 48 89 90 78 03 00 00 mov %rdx,0x378(%rax)
restart_block->poll.has_timeout = 1;
} else
restart_block->poll.has_timeout = 0;

ret = -ERESTART_RESTARTBLOCK;
ffffffff812298ef: b8 fc fd ff ff mov $0xfffffdfc,%eax
ffffffff812298f4: e9 59 ff ff ff jmpq ffffffff81229852 <SyS_poll+0x72>
ret = -ERESTART_RESTARTBLOCK;
}
return ret;
}

SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
ffffffff812298f9: e8 02 0d e7 ff callq ffffffff8109a600 <__stack_chk_fail>
ffffffff812298fe: 66 90 xchg %ax,%ax

ffffffff81229900 <SyS_ppoll>:
ret = -ERESTART_RESTARTBLOCK;
}
return ret;
}


Subject: RE: perf probe -L sys_select or sys_poll

Hi Arnaldo,

> From: Arnaldo Carvalho de Melo [mailto:[email protected]]
>
> Hi Masami,
>
> Have you noticed that sys_select or sys_poll stops after the
> first few lines? Please let me know if you need more info than is below.

OK, I'll see what is going.

>
> [root@zoo ~]# perf probe -L sys_select
> <SyS_select@/home/git/linux/fs/select.c:0>
> 0 SYSCALL_DEFINE5(select, int, n, fd_set __user *, inp, fd_set __user *, outp,
> fd_set __user *, exp, struct timeval __user *, tvp)
> {
> struct timespec end_time, *to = NULL;
>
> [root@zoo ~]# perf probe -L sys_poll
> <SyS_poll@/home/git/linux/fs/select.c:0>
> 0 SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
> int, timeout_msecs)
> {
> struct timespec end_time, *to = NULL;
>
> [root@zoo ~]#
>
> I haven't investigated it too much, if there is some trouble that makes
> 'perf probe -L' to stop like that maybe we should warn the user somehow?

It seems a bug of -L, since it works correctly with fs/select.c:957.

$ ./perf probe -L fs/select.c:957
</home/mhiramat/ksrc/linux-3/fs/select.c:957>
957 SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds$
int, timeout_msecs)
{
960 struct timespec end_time, *to = NULL;
int ret;

963 if (timeout_msecs >= 0) {
964 to = &end_time;
965 poll_select_set_timeout(to, timeout_msecs / MSEC_PER_SE$
966 NSEC_PER_MSEC * (timeout_msecs % MSEC_PER_SEC))$
}

969 ret = do_sys_poll(ufds, nfds, to);

971 if (ret == -EINTR) {
struct restart_block *restart_block;

So, something goes wrong when processing syscall functions.

Thanks!



--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]

Subject: RE: perf probe -L sys_select or sys_poll

> From: Arnaldo Carvalho de Melo [mailto:[email protected]]
>
> Hi Masami,
>
> Have you noticed that sys_select or sys_poll stops after the
> first few lines? Please let me know if you need more info than is below.
>
> [root@zoo ~]# perf probe -L sys_select
> <SyS_select@/home/git/linux/fs/select.c:0>
> 0 SYSCALL_DEFINE5(select, int, n, fd_set __user *, inp, fd_set __user *, outp,
> fd_set __user *, exp, struct timeval __user *, tvp)
> {
> struct timespec end_time, *to = NULL;
>
> [root@zoo ~]# perf probe -L sys_poll
> <SyS_poll@/home/git/linux/fs/select.c:0>
> 0 SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
> int, timeout_msecs)
> {
> struct timespec end_time, *to = NULL;
>
> [root@zoo ~]#
>
> I haven't investigated it too much, if there is some trouble that makes
> 'perf probe -L' to stop like that maybe we should warn the user somehow?
>
> Using -v didn't helped that much:
>
> [root@zoo ~]# perf probe -v -L sys_poll
> Using /root/.debug/.build-id/a8/26726b5ddacfab1f0bade868f1a7924f6b20c4 for symbols
> Open Debuginfo file: /root/.debug/.build-id/a8/26726b5ddacfab1f0bade868f1a7924f6b20c4
> path: (null)
> Symbol sys_poll address found : ffffffff812297e0
> fname: /home/git/linux/fs/select.c, lineno:957
> New line range: 957 to 2147483647
> path: /home/git/linux/fs/select.c
> <SyS_poll@/home/git/linux/fs/select.c:0>
> 0 SYSCALL_DEFINE3(poll, struct pollfd __user *, ufds, unsigned int, nfds,
> int, timeout_msecs)
> {
> struct timespec end_time, *to = NULL;
>
> [root@zoo ~]#

OK, I got what was wrong.
I've ingestigated and found that SYSCALL_DEFINE macro is doing

SYSCALL_DEFINE*(foo,...)
{
body;
}

is expanded as below (on debuginfo)

static inline int SYSC_foo(...)
{
body;
}
int SyS_foo(...) <- is an alias of sys_foo.
{
return SYSC_foo(...);
}

"perf probe -L sys_foo" decodes SyS_foo function and it also
skips inlined functions inside the target function because
those functions are usually defined somewhere else.
Thus, it shows only the first line of sys_foo.
BTW, since SYSC_foo doesn't have no instance, "perf probe -L SYSC_foo"
doesn't show anything.

I think we can avoid this problem by checking whether the inlined function
is defined at the same point of the target function definition.

Thank you,

--
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: [email protected]

Subject: [BUGFIX PATCH perf/core ] perf-probe: Fix to show lines of sys_ functions correctly

"perf probe --lines sys_poll" shows only the first line of
sys_poll, because the SYSCALL_DEFINE macro
----
SYSCALL_DEFINE*(foo,...)
{
body;
}
----
is expanded as below (on debuginfo)

----
static inline int SYSC_foo(...)
{
body;
}
int SyS_foo(...) <- is an alias of sys_foo.
{
return SYSC_foo(...);
}
----

So, "perf probe --lines sys_foo" decodes SyS_foo function and
it also skips inlined functions(SYSC_foo) inside the target
function because those functions are usually defined somewhere
else.

To fix this issue, this fix checks whether the inlined function
is defined at the same point of the target function, and if so,
it doesn't skip the inline function.

Reported-by: Arnaldo Carvalho de Melo <[email protected]>
Signed-off-by: Masami Hiramatsu <[email protected]>
---
tools/perf/util/dwarf-aux.c | 18 +++++++++++++-----
1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/tools/perf/util/dwarf-aux.c b/tools/perf/util/dwarf-aux.c
index 57f3ef4..445f455 100644
--- a/tools/perf/util/dwarf-aux.c
+++ b/tools/perf/util/dwarf-aux.c
@@ -734,15 +734,18 @@ int die_walk_lines(Dwarf_Die *rt_die, line_walk_callback_t callback, void *data)
Dwarf_Lines *lines;
Dwarf_Line *line;
Dwarf_Addr addr;
- const char *fname;
+ const char *fname, *decf = NULL;
int lineno, ret = 0;
+ int decl = 0, inl;
Dwarf_Die die_mem, *cu_die;
size_t nlines, i;

/* Get the CU die */
- if (dwarf_tag(rt_die) != DW_TAG_compile_unit)
+ if (dwarf_tag(rt_die) != DW_TAG_compile_unit) {
cu_die = dwarf_diecu(rt_die, &die_mem, NULL, NULL);
- else
+ dwarf_decl_line(rt_die, &decl);
+ decf = dwarf_decl_file(rt_die);
+ } else
cu_die = rt_die;
if (!cu_die) {
pr_debug2("Failed to get CU from given DIE.\n");
@@ -773,9 +776,14 @@ int die_walk_lines(Dwarf_Die *rt_die, line_walk_callback_t callback, void *data)
* The line is included in given function, and
* no inline block includes it.
*/
- if (!dwarf_haspc(rt_die, addr) ||
- die_find_inlinefunc(rt_die, addr, &die_mem))
+ if (!dwarf_haspc(rt_die, addr))
continue;
+ if (die_find_inlinefunc(rt_die, addr, &die_mem)) {
+ dwarf_decl_line(&die_mem, &inl);
+ if (inl != decl ||
+ decf != dwarf_decl_file(&die_mem))
+ continue;
+ }
/* Get source line */
fname = dwarf_linesrc(line, NULL, NULL);

2015-08-12 13:24:01

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [BUGFIX PATCH perf/core ] perf-probe: Fix to show lines of sys_ functions correctly

Em Wed, Aug 12, 2015 at 10:24:07AM +0900, Masami Hiramatsu escreveu:
> "perf probe --lines sys_poll" shows only the first line of
> sys_poll, because the SYSCALL_DEFINE macro
> ----

Thanks! Just try prefixing those ---- lines one space so that git-am
works on your messages :-)

Now to build and test, will report here the results.

Thanks again,

- Arnaldo

> SYSCALL_DEFINE*(foo,...)
> {
> body;
> }
> ----
> is expanded as below (on debuginfo)
>
> ----
> static inline int SYSC_foo(...)
> {
> body;
> }
> int SyS_foo(...) <- is an alias of sys_foo.
> {
> return SYSC_foo(...);
> }
> ----
>
> So, "perf probe --lines sys_foo" decodes SyS_foo function and
> it also skips inlined functions(SYSC_foo) inside the target
> function because those functions are usually defined somewhere
> else.
>
> To fix this issue, this fix checks whether the inlined function
> is defined at the same point of the target function, and if so,
> it doesn't skip the inline function.
>
> Reported-by: Arnaldo Carvalho de Melo <[email protected]>
> Signed-off-by: Masami Hiramatsu <[email protected]>
> ---
> tools/perf/util/dwarf-aux.c | 18 +++++++++++++-----
> 1 file changed, 13 insertions(+), 5 deletions(-)
>
> diff --git a/tools/perf/util/dwarf-aux.c b/tools/perf/util/dwarf-aux.c
> index 57f3ef4..445f455 100644
> --- a/tools/perf/util/dwarf-aux.c
> +++ b/tools/perf/util/dwarf-aux.c
> @@ -734,15 +734,18 @@ int die_walk_lines(Dwarf_Die *rt_die, line_walk_callback_t callback, void *data)
> Dwarf_Lines *lines;
> Dwarf_Line *line;
> Dwarf_Addr addr;
> - const char *fname;
> + const char *fname, *decf = NULL;
> int lineno, ret = 0;
> + int decl = 0, inl;
> Dwarf_Die die_mem, *cu_die;
> size_t nlines, i;
>
> /* Get the CU die */
> - if (dwarf_tag(rt_die) != DW_TAG_compile_unit)
> + if (dwarf_tag(rt_die) != DW_TAG_compile_unit) {
> cu_die = dwarf_diecu(rt_die, &die_mem, NULL, NULL);
> - else
> + dwarf_decl_line(rt_die, &decl);
> + decf = dwarf_decl_file(rt_die);
> + } else
> cu_die = rt_die;
> if (!cu_die) {
> pr_debug2("Failed to get CU from given DIE.\n");
> @@ -773,9 +776,14 @@ int die_walk_lines(Dwarf_Die *rt_die, line_walk_callback_t callback, void *data)
> * The line is included in given function, and
> * no inline block includes it.
> */
> - if (!dwarf_haspc(rt_die, addr) ||
> - die_find_inlinefunc(rt_die, addr, &die_mem))
> + if (!dwarf_haspc(rt_die, addr))
> continue;
> + if (die_find_inlinefunc(rt_die, addr, &die_mem)) {
> + dwarf_decl_line(&die_mem, &inl);
> + if (inl != decl ||
> + decf != dwarf_decl_file(&die_mem))
> + continue;
> + }
> /* Get source line */
> fname = dwarf_linesrc(line, NULL, NULL);
>

2015-08-12 13:40:50

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [BUGFIX PATCH perf/core ] perf-probe: Fix to show lines of sys_ functions correctly

Em Wed, Aug 12, 2015 at 10:23:55AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Wed, Aug 12, 2015 at 10:24:07AM +0900, Masami Hiramatsu escreveu:
> > "perf probe --lines sys_poll" shows only the first line of
> > sys_poll, because the SYSCALL_DEFINE macro
> > ----

> Thanks! Just try prefixing those ---- lines one space so that git-am
> works on your messages :-)

> Now to build and test, will report here the results.

Ok, now -L works:

[root@zoo ~]# perf probe -L sys_select
<SyS_select@/home/git/linux/fs/select.c:0>
0 SYSCALL_DEFINE5(select, int, n, fd_set __user *, inp, fd_set __user *, outp,
fd_set __user *, exp, struct timeval __user *, tvp)
{
3 struct timespec end_time, *to = NULL;
struct timeval tv;
int ret;

7 if (tvp) {
8 if (copy_from_user(&tv, tvp, sizeof(tv)))
9 return -EFAULT;

11 to = &end_time;
12 if (poll_select_set_timeout(to,
tv.tv_sec + (tv.tv_usec / USEC_PER_SEC),
14 (tv.tv_usec % USEC_PER_SEC) * NSEC_PER_USEC))
15 return -EINVAL;
}

18 ret = core_sys_select(n, inp, outp, exp, to);
19 ret = poll_select_copy_remaining(&end_time, tvp, 1, ret);

21 return ret;
}

static long do_pselect(int n, fd_set __user *inp, fd_set __user *outp,

But then adding a probe doesn't work on sys_select, even with -L stating that I
can add a probe at that line, maybe the code you added to make -L work needs to
be shared with the other operations in 'perf probe'?

[root@zoo ~]#
[root@zoo ~]# perf probe 'get_timeval=sys_select:11 tv_sec=tv.tv_sec tv_usec=tv.tv_usec'
Probe point 'sys_select:11' not found.
Error: Failed to add events.
[root@zoo ~]#

[root@zoo ~]# perf probe -V sys_select
Available variables at sys_select
@<SyS_select+0>
long int exp
long int inp
long int n
long int outp
long int tvp
[root@zoo ~]# perf probe -V sys_select:11
Failed to find the address of sys_select:11
Error: Failed to show vars.
[root@zoo ~]#

While this works:

[root@zoo ~]# perf probe 'vfs_getname=getname_flags:72 pathname=filename:string'
Added new event:
probe:vfs_getname (on getname_flags:72 with pathname=filename:string)

You can now use it in all perf tools, such as:

perf record -e probe:vfs_getname -aR sleep 1

- Arnaldo

Subject: Re: [BUGFIX PATCH perf/core ] perf-probe: Fix to show lines of sys_ functions correctly

> From: Arnaldo Carvalho de Melo [mailto:[email protected]]
>
> Em Wed, Aug 12, 2015 at 10:23:55AM -0300, Arnaldo Carvalho de Melo escreveu:
> > Em Wed, Aug 12, 2015 at 10:24:07AM +0900, Masami Hiramatsu escreveu:
> > > "perf probe --lines sys_poll" shows only the first line of
> > > sys_poll, because the SYSCALL_DEFINE macro
> > > ----
>
> > Thanks! Just try prefixing those ---- lines one space so that git-am
> > works on your messages :-)
>
> > Now to build and test, will report here the results.
>
> Ok, now -L works:
>
> [root@zoo ~]# perf probe -L sys_select
> <SyS_select@/home/git/linux/fs/select.c:0>
> 0 SYSCALL_DEFINE5(select, int, n, fd_set __user *, inp, fd_set __user *, outp,
> fd_set __user *, exp, struct timeval __user *, tvp)
> {
> 3 struct timespec end_time, *to = NULL;
> struct timeval tv;
> int ret;
>
> 7 if (tvp) {
> 8 if (copy_from_user(&tv, tvp, sizeof(tv)))
> 9 return -EFAULT;
>
> 11 to = &end_time;
> 12 if (poll_select_set_timeout(to,
> tv.tv_sec + (tv.tv_usec / USEC_PER_SEC),
> 14 (tv.tv_usec % USEC_PER_SEC) * NSEC_PER_USEC))
> 15 return -EINVAL;
> }
>
> 18 ret = core_sys_select(n, inp, outp, exp, to);
> 19 ret = poll_select_copy_remaining(&end_time, tvp, 1, ret);
>
> 21 return ret;
> }
>
> static long do_pselect(int n, fd_set __user *inp, fd_set __user *outp,
>
> But then adding a probe doesn't work on sys_select, even with -L stating that I
> can add a probe at that line, maybe the code you added to make -L work needs to
> be shared with the other operations in 'perf probe'?

Oops, I missed a {} around new if statement...
I'll update the patch asap.

Thanks!

Subject: [tip:perf/core] perf probe: Fix to show lines of sys_ functions correctly

Commit-ID: 75186a9b09e47072f442f43e292cd47180b67b5c
Gitweb: http://git.kernel.org/tip/75186a9b09e47072f442f43e292cd47180b67b5c
Author: Masami Hiramatsu <[email protected]>
AuthorDate: Wed, 12 Aug 2015 10:24:07 +0900
Committer: Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Wed, 12 Aug 2015 13:20:27 -0300

perf probe: Fix to show lines of sys_ functions correctly

"perf probe --lines sys_poll" shows only the first line of sys_poll,
because the SYSCALL_DEFINE macro:

----
SYSCALL_DEFINE*(foo,...)
{
body;
}
----

is expanded as below (on debuginfo)

----

static inline int SYSC_foo(...)
{
body;
}
int SyS_foo(...) <- is an alias of sys_foo.
{
return SYSC_foo(...);
}
----

So, "perf probe --lines sys_foo" decodes SyS_foo function and it also skips
inlined functions(SYSC_foo) inside the target function because those functions
are usually defined somewhere else.

To fix this issue, this fix checks whether the inlined function is defined at
the same point of the target function, and if so, it doesn't skip the inline
function.

Reported-by: Arnaldo Carvalho de Melo <[email protected]>
Signed-off-by: Masami Hiramatsu <[email protected]>
Tested-by: Arnaldo Carvalho de Melo <[email protected]>
Cc: David Ahern <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
---
tools/perf/util/dwarf-aux.c | 18 +++++++++++++-----
1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/tools/perf/util/dwarf-aux.c b/tools/perf/util/dwarf-aux.c
index 57f3ef4..445f455 100644
--- a/tools/perf/util/dwarf-aux.c
+++ b/tools/perf/util/dwarf-aux.c
@@ -734,15 +734,18 @@ int die_walk_lines(Dwarf_Die *rt_die, line_walk_callback_t callback, void *data)
Dwarf_Lines *lines;
Dwarf_Line *line;
Dwarf_Addr addr;
- const char *fname;
+ const char *fname, *decf = NULL;
int lineno, ret = 0;
+ int decl = 0, inl;
Dwarf_Die die_mem, *cu_die;
size_t nlines, i;

/* Get the CU die */
- if (dwarf_tag(rt_die) != DW_TAG_compile_unit)
+ if (dwarf_tag(rt_die) != DW_TAG_compile_unit) {
cu_die = dwarf_diecu(rt_die, &die_mem, NULL, NULL);
- else
+ dwarf_decl_line(rt_die, &decl);
+ decf = dwarf_decl_file(rt_die);
+ } else
cu_die = rt_die;
if (!cu_die) {
pr_debug2("Failed to get CU from given DIE.\n");
@@ -773,9 +776,14 @@ int die_walk_lines(Dwarf_Die *rt_die, line_walk_callback_t callback, void *data)
* The line is included in given function, and
* no inline block includes it.
*/
- if (!dwarf_haspc(rt_die, addr) ||
- die_find_inlinefunc(rt_die, addr, &die_mem))
+ if (!dwarf_haspc(rt_die, addr))
continue;
+ if (die_find_inlinefunc(rt_die, addr, &die_mem)) {
+ dwarf_decl_line(&die_mem, &inl);
+ if (inl != decl ||
+ decf != dwarf_decl_file(&die_mem))
+ continue;
+ }
/* Get source line */
fname = dwarf_linesrc(line, NULL, NULL);