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;

}

Hi Arnaldo,

OK, I'll see what is going.

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]

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]

"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.

---
 tools/perf/util/dwarf-aux.c |   18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

index 57f3ef4..445f455 100644
@@ -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);
 

Em Wed, Aug 12, 2015 at 10:24:07AM +0900, Masami Hiramatsu escreveu:

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

Em Wed, Aug 12, 2015 at 10:23:55AM -0300, Arnaldo Carvalho de Melo escreveu:

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

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

Thanks!