[PATCH 0/2] perf: Fixes for callchain ip handling on powerpc

[PATCH 0/2] perf: Fixes for callchain ip handling on powerpc

[Sandipan Das]

The first patch fixes the callchain ip filtering mechanism for powerpc
from skipping entries in case the LR value is still valid and yet to
be written to the stack frame. This was previously posted as an RFC
here: https://lkml.org/lkml/2018/4/4/633

The second patch fixes a shell test which used to fail on powerpc as
the back trace from perf output did not match the expected pattern.
Also, because of the issue described in the first patch, some entries
from the callchain were incorrectly skipped. So, this has also been
readjusted to work with the fix in the first patch.

Sandipan Das (2):
  perf tools powerpc: Fix callchain ip filtering
  perf tests: Fix record+probe_libc_inet_pton.sh for powerpc64

 tools/perf/arch/powerpc/util/skip-callchain-idx.c  | 58 +++++++++++++++-------
 .../tests/shell/record+probe_libc_inet_pton.sh     |  8 +++
 2 files changed, 49 insertions(+), 17 deletions(-)

-- 
2.14.3

[PATCH 1/2] perf tools powerpc: Fix callchain ip filtering

[Sandipan Das]

For powerpc64, if a probe is added for a function without specifying
a line number, the corresponding trap instruction is placed at offset
0 (for big endian) or 8 (for little endian) from the start address of
the function. This address is in the function prologue and the trap
instruction preceeds the instructions to set up the stack frame.

Therefore, at this point during execution, the return address for the
function is yet to be written to its caller's stack frame. So, the LR
value at index 2 of the callchain ips provided by the kernel is still
valid and must not be skipped.

This can be observed on a powerpc64le system running Fedora 27 as
shown below.

 # perf probe -x /usr/lib64/libc-2.26.so -a inet_pton
 # perf record -e probe_libc:inet_pton/max-stack=3/ ping -6 -c 1 ::1
 # perf script

Without this patch, the output is:

 ping 27909 [007] 532219.943481: probe_libc:inet_pton: (7fff99b0af28)
                   15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
                   1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)

With this patch applied, the output is:

 ping 27909 [007] 532219.943481: probe_libc:inet_pton: (7fff99b0af28)
                   15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
                   10fa54 gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
                   1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)

Fixes: a60335ba3298 ("perf tools powerpc: Adjust callchain based on DWARF debug info")
Signed-off-by: Sandipan Das <sandipan@linux.vnet.ibm.com>
---
 tools/perf/arch/powerpc/util/skip-callchain-idx.c | 58 ++++++++++++++++-------
 1 file changed, 41 insertions(+), 17 deletions(-)

diff --git a/tools/perf/arch/powerpc/util/skip-callchain-idx.c b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
index 0c370f81e002..f5179f5bb306 100644
--- a/tools/perf/arch/powerpc/util/skip-callchain-idx.c
+++ b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
@@ -212,6 +212,37 @@ static int check_return_addr(struct dso *dso, u64 map_start, Dwarf_Addr pc)
 	return rc;
 }
 
+/*
+ * Return:
+ *	0 if return address for the program counter @pc is on stack
+ *	1 if return address is in LR and no new stack frame was allocated
+ *	2 if return address is in LR and a new frame was allocated (but not
+ *		yet used)
+ *	-1 in case of errors
+ */
+static int get_return_addr(struct thread *thread, u64 ip)
+{
+	struct addr_location al;
+	struct dso *dso = NULL;
+	int rc = -1;
+
+	thread__find_addr_location(thread, PERF_RECORD_MISC_USER,
+			MAP__FUNCTION, ip, &al);
+
+	if (!al.map || !al.map->dso) {
+		pr_debug("%" PRIx64 " dso is NULL\n", ip);
+		return rc;
+	}
+
+	dso = al.map->dso;
+	rc = check_return_addr(dso, al.map->start, ip);
+
+	pr_debug("[DSO %s, sym %s, ip 0x%" PRIx64 "] rc %d\n",
+				dso->long_name, al.sym->name, ip, rc);
+
+	return rc;
+}
+
 /*
  * The callchain saved by the kernel always includes the link register (LR).
  *
@@ -237,32 +268,25 @@ static int check_return_addr(struct dso *dso, u64 map_start, Dwarf_Addr pc)
  */
 int arch_skip_callchain_idx(struct thread *thread, struct ip_callchain *chain)
 {
-	struct addr_location al;
-	struct dso *dso = NULL;
 	int rc;
-	u64 ip;
 	u64 skip_slot = -1;
 
 	if (chain->nr < 3)
 		return skip_slot;
 
-	ip = chain->ips[2];
+	rc = get_return_addr(thread, chain->ips[1]);
 
-	thread__find_addr_location(thread, PERF_RECORD_MISC_USER,
-			MAP__FUNCTION, ip, &al);
-
-	if (al.map)
-		dso = al.map->dso;
-
-	if (!dso) {
-		pr_debug("%" PRIx64 " dso is NULL\n", ip);
+	if (rc == 1)
+		/* Return address is still in LR and has not been updated
+		 * in caller's stack frame. This is because the probe was
+		 * placed at an offset from the start of the function that
+		 * comes before the prologue code to set up the stack frame.
+		 * So, an attempt to skip an entry based on chain->ips[2],
+		 * i.e. the LR value, should not be made.
+		 */
 		return skip_slot;
-	}
 
-	rc = check_return_addr(dso, al.map->start, ip);
-
-	pr_debug("[DSO %s, sym %s, ip 0x%" PRIx64 "] rc %d\n",
-				dso->long_name, al.sym->name, ip, rc);
+	rc = get_return_addr(thread, chain->ips[2]);
 
 	if (rc == 0) {
 		/*
-- 
2.14.3

[PATCH 2/2] perf tests: Fix record+probe_libc_inet_pton.sh for powerpc64

[Sandipan Das]

For powerpc64, this test currently fails due to a mismatch in
the expected output.

Before applying patch:

  62: probe libc's inet_pton & backtrace it with ping       :
  --- start ---
  test child forked, pid 27723
  ping 27740 [012] 607801.690493: probe_libc:inet_pton: (7fff936caf28)
  15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
  10fa54 gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
  FAIL: expected backtrace entry 2 "getaddrinfo[[:space:]]\(/usr/lib64/libc-2.26.so\)$" got "10fa54 gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)"
  test child finished with -1
  ---- end ----
  probe libc's inet_pton & backtrace it with ping: FAILED!

After applying patch:

  62: probe libc's inet_pton & backtrace it with ping       :
  --- start ---
  test child forked, pid 28782
  ping 28799 [017] 608933.853323: probe_libc:inet_pton: (7fff891baf28)
  15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
  10fa54 gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
  1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)
  2d70 _init (/usr/bin/ping)
  test child finished with 0
  ---- end ----
  probe libc's inet_pton & backtrace it with ping: Ok

Fixes: e07d585e2454 ("perf tests: Switch trace+probe_libc_inet_pton to use record")
Signed-off-by: Sandipan Das <sandipan@linux.vnet.ibm.com>
---
 tools/perf/tests/shell/record+probe_libc_inet_pton.sh | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
index 1ecc1f0ff84a..b45afc59edc6 100755
--- a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
+++ b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
@@ -26,6 +26,14 @@ trace_libc_inet_pton_backtrace() {
 		expected[5]="__libc_start_main[[:space:]]\($libc\)$"
 		expected[6]="_start[[:space:]]\(.*/bin/ping.*\)$"
 		;;
+	ppc64)
+		;&
+	ppc64le)
+		eventattr='max-stack=4'
+		expected[2]="gaih_inet.*[[:space:]]\($libc\)$"
+		expected[3]="getaddrinfo[[:space:]]\($libc\)$"
+		expected[4]=".*\(.*/bin/ping.*\)$"
+		;;
 	*)
 		eventattr='max-stack=3'
 		expected[2]="getaddrinfo[[:space:]]\($libc\)$"
-- 
2.14.3

Re: [PATCH 1/2] perf tools powerpc: Fix callchain ip filtering

[Arnaldo Carvalho de Melo]

Em Thu, Apr 12, 2018 at 10:41:28PM +0530, Sandipan Das escreveu:
> For powerpc64, if a probe is added for a function without specifying
> a line number, the corresponding trap instruction is placed at offset
> 0 (for big endian) or 8 (for little endian) from the start address of
> the function. This address is in the function prologue and the trap
> instruction preceeds the instructions to set up the stack frame.

So, the author for the fixed-by patch here is Sukadev Bhattiprolu
<sukadev@linux.vnet.ibm.com>, and the reporter for the problem that
patch fixed is Maynard Johnson <maynard@us.ibm.com>, who also tested
that patch, I think it'd be better if they get CCed to have the
opportunity to ack/comment, but since everybody is at IBM, perhaps
those guys are not anymore involved with ppc at IBM?

I'm CCing anyway :-)

- Arnaldo
 
> Therefore, at this point during execution, the return address for the
> function is yet to be written to its caller's stack frame. So, the LR
> value at index 2 of the callchain ips provided by the kernel is still
> valid and must not be skipped.
> 
> This can be observed on a powerpc64le system running Fedora 27 as
> shown below.
> 
>  # perf probe -x /usr/lib64/libc-2.26.so -a inet_pton
>  # perf record -e probe_libc:inet_pton/max-stack=3/ ping -6 -c 1 ::1
>  # perf script
> 
> Without this patch, the output is:
> 
>  ping 27909 [007] 532219.943481: probe_libc:inet_pton: (7fff99b0af28)
>                    15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
>                    1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)
> 
> With this patch applied, the output is:
> 
>  ping 27909 [007] 532219.943481: probe_libc:inet_pton: (7fff99b0af28)
>                    15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
>                    10fa54 gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
>                    1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)
> 
> Fixes: a60335ba3298 ("perf tools powerpc: Adjust callchain based on DWARF debug info")
> Signed-off-by: Sandipan Das <sandipan@linux.vnet.ibm.com>
> ---
>  tools/perf/arch/powerpc/util/skip-callchain-idx.c | 58 ++++++++++++++++-------
>  1 file changed, 41 insertions(+), 17 deletions(-)
> 
> diff --git a/tools/perf/arch/powerpc/util/skip-callchain-idx.c b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
> index 0c370f81e002..f5179f5bb306 100644
> --- a/tools/perf/arch/powerpc/util/skip-callchain-idx.c
> +++ b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
> @@ -212,6 +212,37 @@ static int check_return_addr(struct dso *dso, u64 map_start, Dwarf_Addr pc)
>  	return rc;
>  }
>  
> +/*
> + * Return:
> + *	0 if return address for the program counter @pc is on stack
> + *	1 if return address is in LR and no new stack frame was allocated
> + *	2 if return address is in LR and a new frame was allocated (but not
> + *		yet used)
> + *	-1 in case of errors
> + */
> +static int get_return_addr(struct thread *thread, u64 ip)
> +{
> +	struct addr_location al;
> +	struct dso *dso = NULL;
> +	int rc = -1;
> +
> +	thread__find_addr_location(thread, PERF_RECORD_MISC_USER,
> +			MAP__FUNCTION, ip, &al);
> +
> +	if (!al.map || !al.map->dso) {
> +		pr_debug("%" PRIx64 " dso is NULL\n", ip);
> +		return rc;
> +	}
> +
> +	dso = al.map->dso;
> +	rc = check_return_addr(dso, al.map->start, ip);
> +
> +	pr_debug("[DSO %s, sym %s, ip 0x%" PRIx64 "] rc %d\n",
> +				dso->long_name, al.sym->name, ip, rc);
> +
> +	return rc;
> +}
> +
>  /*
>   * The callchain saved by the kernel always includes the link register (LR).
>   *
> @@ -237,32 +268,25 @@ static int check_return_addr(struct dso *dso, u64 map_start, Dwarf_Addr pc)
>   */
>  int arch_skip_callchain_idx(struct thread *thread, struct ip_callchain *chain)
>  {
> -	struct addr_location al;
> -	struct dso *dso = NULL;
>  	int rc;
> -	u64 ip;
>  	u64 skip_slot = -1;
>  
>  	if (chain->nr < 3)
>  		return skip_slot;
>  
> -	ip = chain->ips[2];
> +	rc = get_return_addr(thread, chain->ips[1]);
>  
> -	thread__find_addr_location(thread, PERF_RECORD_MISC_USER,
> -			MAP__FUNCTION, ip, &al);
> -
> -	if (al.map)
> -		dso = al.map->dso;
> -
> -	if (!dso) {
> -		pr_debug("%" PRIx64 " dso is NULL\n", ip);
> +	if (rc == 1)
> +		/* Return address is still in LR and has not been updated
> +		 * in caller's stack frame. This is because the probe was
> +		 * placed at an offset from the start of the function that
> +		 * comes before the prologue code to set up the stack frame.
> +		 * So, an attempt to skip an entry based on chain->ips[2],
> +		 * i.e. the LR value, should not be made.
> +		 */
>  		return skip_slot;
> -	}
>  
> -	rc = check_return_addr(dso, al.map->start, ip);
> -
> -	pr_debug("[DSO %s, sym %s, ip 0x%" PRIx64 "] rc %d\n",
> -				dso->long_name, al.sym->name, ip, rc);
> +	rc = get_return_addr(thread, chain->ips[2]);
>  
>  	if (rc == 0) {
>  		/*
> -- 
> 2.14.3

Re: [PATCH 1/2] perf tools powerpc: Fix callchain ip filtering

[Sandipan Das]

On 04/13/2018 12:13 AM, Arnaldo Carvalho de Melo wrote:
> 
> So, the author for the fixed-by patch here is Sukadev Bhattiprolu
> <sukadev@linux.vnet.ibm.com>, and the reporter for the problem that
> patch fixed is Maynard Johnson <maynard@us.ibm.com>, who also tested
> that patch, I think it'd be better if they get CCed to have the
> opportunity to ack/comment, but since everybody is at IBM, perhaps
> those guys are not anymore involved with ppc at IBM?
> 
> I'm CCing anyway :-)
> 
> - Arnaldo
> 

Sorry I missed that. Thanks for adding them :-)

- Sandipan

Re: [PATCH 1/2] perf tools powerpc: Fix callchain ip filtering

[Ravi Bangoria]

On 04/12/2018 10:41 PM, Sandipan Das wrote:
> For powerpc64, if a probe is added for a function without specifying
> a line number, the corresponding trap instruction is placed at offset
> 0 (for big endian) or 8 (for little endian) from the start address of
> the function. This address is in the function prologue and the trap
> instruction preceeds the instructions to set up the stack frame.
>
> Therefore, at this point during execution, the return address for the
> function is yet to be written to its caller's stack frame. So, the LR
> value at index 2 of the callchain ips provided by the kernel is still
> valid and must not be skipped.
>
> This can be observed on a powerpc64le system running Fedora 27 as
> shown below.
>
>  # perf probe -x /usr/lib64/libc-2.26.so -a inet_pton
>  # perf record -e probe_libc:inet_pton/max-stack=3/ ping -6 -c 1 ::1
>  # perf script
>
> Without this patch, the output is:
>
>  ping 27909 [007] 532219.943481: probe_libc:inet_pton: (7fff99b0af28)
>                    15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
>                    1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)
>
> With this patch applied, the output is:
>
>  ping 27909 [007] 532219.943481: probe_libc:inet_pton: (7fff99b0af28)
>                    15af28 __GI___inet_pton (/usr/lib64/libc-2.26.so)
>                    10fa54 gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
>                    1105b4 getaddrinfo (/usr/lib64/libc-2.26.so)
>
> Fixes: a60335ba3298 ("perf tools powerpc: Adjust callchain based on DWARF debug info")
> Signed-off-by: Sandipan Das <sandipan@linux.vnet.ibm.com>
> ---

This change looks good to me but seems it fixed the issue
partially.Ex,

    # readelf --debug-dump=frames-interp /lib64/libc-2.26.so | less
    ...
    00005778 0000000000000024 0000577c FDE cie=00000000 pc=0000000000048b30..0000000000048c64
       LOC           CFA      r31   ra   
    0000000000048b30 r1+0     u     u    
    0000000000048b40 r1+0     c-8   r0   
    0000000000048b58 r1+64    c-8   c+16 
    0000000000048bd8 r1+0     c-8   c+16 
    0000000000048be4 r1+0     u    
    0000000000048bf0 r1+64    c-8   c+16 

0000000000048b30..0000000000048c64 is arandom() function from libc:

    0000000000048b30 <random>:
       48b30:       1c 00 4c 3c     addis   r2,r12,28
       48b34:       d0 e5 42 38     addi    r2,r2,-6704
       48b38:       a6 02 08 7c     mflr    r0
       48b3c:       f8 ff e1 fb     std     r31,-8(r1)
       48b40:       00 00 00 60     nop
       48b44:       00 00 20 39     li      r9,0
       48b48:       80 b5 e2 3b     addi    r31,r2,-19072
       48b4c:       01 00 00 39     li      r8,1
       48b50:       10 00 01 f8     std     r0,16(r1)
       48b54:       c1 ff 21 f8     stdu    r1,-64(r1)
       48b58:       f0 8f 4d e9     ld      r10,-28688(r13)
       ...

Your change fixed the issue for 48b30..48b40. But not for
48b40..48b58.

I probed at 0x48b40.

    # ./perf record -g -e probe_libc:abs_48b40 ~/rand

perf report without Suka's and your change:

    # Children      Self  Trace output 
    # ........  ........  ..............
    #
       100.00%   100.00%  (7fffb7d28b40)
                |
                ---0
                   __libc_start_main
                   generic_start_main.isra.0
                   main
                   rand
                   __random

perf report with only Suka's change:

    # Children      Self  Trace output 
    # ........  ........  ..............
    #
       100.00%   100.00%  (7fffb7d28b40)
                |
                ---0
                   __libc_start_main
                   generic_start_main.isra.0
                   main
                   __random

perf report with Suka's and your change:

    # Children      Self  Trace output 
    # ........  ........  ..............
    #
       100.00%   100.00%  (7fffb7d28b40)
                |
                ---0
                   __libc_start_main
                   generic_start_main.isra.0
                   main
                   __random

I think rand() is a valid entry which is missing in last two cases.

Re: [PATCH 1/2] perf tools powerpc: Fix callchain ip filtering

[Sandipan Das]

On 04/17/2018 12:29 PM, Ravi Bangoria wrote:
> 
> This change looks good to me but seems it fixed the issue
> partially.Ex,
> 
>     # readelf --debug-dump=frames-interp /lib64/libc-2.26.so | less
>     ...
>     00005778 0000000000000024 0000577c FDE cie=00000000 pc=0000000000048b30..0000000000048c64
>        LOC           CFA      r31   ra   
>     0000000000048b30 r1+0     u     u    
>     0000000000048b40 r1+0     c-8   r0   
>     0000000000048b58 r1+64    c-8   c+16 
>     0000000000048bd8 r1+0     c-8   c+16 
>     0000000000048be4 r1+0     u    
>     0000000000048bf0 r1+64    c-8   c+16 
> 
> 0000000000048b30..0000000000048c64 is arandom() function from libc:
> 
>     0000000000048b30 <random>:
>        48b30:       1c 00 4c 3c     addis   r2,r12,28
>        48b34:       d0 e5 42 38     addi    r2,r2,-6704
>        48b38:       a6 02 08 7c     mflr    r0
>        48b3c:       f8 ff e1 fb     std     r31,-8(r1)
>        48b40:       00 00 00 60     nop
>        48b44:       00 00 20 39     li      r9,0
>        48b48:       80 b5 e2 3b     addi    r31,r2,-19072
>        48b4c:       01 00 00 39     li      r8,1
>        48b50:       10 00 01 f8     std     r0,16(r1)
>        48b54:       c1 ff 21 f8     stdu    r1,-64(r1)
>        48b58:       f0 8f 4d e9     ld      r10,-28688(r13)
>        ...
> 
> Your change fixed the issue for 48b30..48b40. But not for
> 48b40..48b58.
> 
> I probed at 0x48b40.
> 
>     # ./perf record -g -e probe_libc:abs_48b40 ~/rand
> 
> perf report without Suka's and your change:
> 
>     # Children      Self  Trace output 
>     # ........  ........  ..............
>     #
>        100.00%   100.00%  (7fffb7d28b40)
>                 |
>                 ---0
>                    __libc_start_main
>                    generic_start_main.isra.0
>                    main
>                    rand
>                    __random
> 
> perf report with only Suka's change:
> 
>     # Children      Self  Trace output 
>     # ........  ........  ..............
>     #
>        100.00%   100.00%  (7fffb7d28b40)
>                 |
>                 ---0
>                    __libc_start_main
>                    generic_start_main.isra.0
>                    main
>                    __random
> 
> perf report with Suka's and your change:
> 
>     # Children      Self  Trace output 
>     # ........  ........  ..............
>     #
>        100.00%   100.00%  (7fffb7d28b40)
>                 |
>                 ---0
>                    __libc_start_main
>                    generic_start_main.isra.0
>                    main
>                    __random
> 
> I think rand() is a valid entry which is missing in last two cases.
> 
> 

Ah, good catch and thanks for the review. Will address these problems in v2.

- Sandipan