perf probe -L sys_select or sys_poll

perf probe -L sys_select or sys_poll

[Arnaldo Carvalho de Melo]

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;
  }

RE: perf probe -L sys_select or sys_poll

[平松雅巳 / HIRAMATU，MASAMI]

Hi Arnaldo,

> From: Arnaldo Carvalho de Melo [mailto:acme@kernel.org]
> 
> 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: masami.hiramatsu.pt@hitachi.com

RE: perf probe -L sys_select or sys_poll

[平松雅巳 / HIRAMATU，MASAMI]

> From: Arnaldo Carvalho de Melo [mailto:acme@kernel.org]
> 
> 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: masami.hiramatsu.pt@hitachi.com

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

[Masami Hiramatsu]

"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 <acme@kernel.org>
Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
---
 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);
 

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

[Arnaldo Carvalho de Melo]

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 <acme@kernel.org>
> Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
> ---
>  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);
>  

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

[Arnaldo Carvalho de Melo]

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

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

[平松雅巳 / HIRAMATU，MASAMI]

> From: Arnaldo Carvalho de Melo [mailto:acme@kernel.org]
> 
> 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!

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

[tip-bot for Masami Hiramatsu]

Commit-ID:  75186a9b09e47072f442f43e292cd47180b67b5c
Gitweb:     http://git.kernel.org/tip/75186a9b09e47072f442f43e292cd47180b67b5c
Author:     Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
AuthorDate: Wed, 12 Aug 2015 10:24:07 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
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 <acme@kernel.org>
Signed-off-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Link: http://lkml.kernel.org/r/20150812012406.11811.94691.stgit@localhost.localdomain
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 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);