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

[PATCH v2 0/3] 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 crash caused by attempting to access an empty
callchain.

The third 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.

v2:
 - Consider case when return address is in R0 as pointed out by Ravi.
 - Add another patch to fix crash when callchain is empty.

Sandipan Das (3):
  perf tools powerpc: Fix callchain ip filtering
  perf tools powerpc: Fix crash if callchain is empty
  perf tests: Fix record+probe_libc_inet_pton.sh for powerpc64

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

-- 
2.14.3

[PATCH v2 1/3] 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 instruction that writes the return address
to the caller's stack frame. So, the call frame information will say
that the return address is undefined here and there will be no DWARF
operations to describe this.

Alternatively, if we place a probe in the function prologue at some
address after the LR value has been copied to R0 but before R0 is
written to the caller's stack frame, the call frame information will
say that the return address is available in R0 and there will be a
corresponding DWARF operation to describe this.

For both these cases, the return address is not available on the
stack which implies that 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.

 # objdump -d /usr/lib64/libc-2.26.so | less
 ...
 000000000015af20 <inet_pton>:
   15af20:       0b 00 4c 3c     addis   r2,r12,11
   15af24:       e0 c1 42 38     addi    r2,r2,-15904
   15af28:       a6 02 08 7c     mflr    r0
   15af2c:       f0 ff c1 fb     std     r30,-16(r1)
   15af30:       f8 ff e1 fb     std     r31,-8(r1)
   15af34:       78 1b 7f 7c     mr      r31,r3
   15af38:       78 23 83 7c     mr      r3,r4
   15af3c:       78 2b be 7c     mr      r30,r5
   15af40:       10 00 01 f8     std     r0,16(r1)
   15af44:       c1 ff 21 f8     stdu    r1,-64(r1)
   15af48:       28 00 81 f8     std     r4,40(r1)
 ...

 # readelf --debug-dump=frames-interp /usr/lib64/libc-2.26.so | less
 ...
 00027024 0000000000000024 00027028 FDE cie=00000000 pc=000000000015af20..000000000015af88
    LOC           CFA      r30   r31   ra
 000000000015af20 r1+0     u     u     u
 000000000015af34 r1+0     c-16  c-8   r0
 000000000015af48 r1+64    c-16  c-8   c+16
 000000000015af5c r1+0     c-16  c-8   c+16
 000000000015af78 r1+0     u     u
 ...

Case 1 - Probe at 0x15af28, return address is undefined.
 # 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

Case 2 - Probe at 0x15af38, return address is in R0.
 # perf probe -x /usr/lib64/libc-2.26.so -a 0x15af38
 # perf record -e probe_libc:abs_15af38/max-stack=3/ ping -6 -c 1 ::1
 # perf script

Output before applying this patch:

 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)

Output after applying this patch:

 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>
---
v2:
 - Consider case when return address is in R0 as pointed out by Ravi.
 - Rather than declaring a separate get_return_addr() function that
   ultimately calls check_return_addr() and since check_return_addr()
   is called only from get_return_addr(), integrate additional tasks
   such as finding DSO information inside check_return_addr() itself
   instead of having another function.
 - Update commit message with description of both cases and how to
   reproduce them.
---
 tools/perf/arch/powerpc/util/skip-callchain-idx.c | 72 ++++++++++++++---------
 1 file changed, 44 insertions(+), 28 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..d3a13f79d3ee 100644
--- a/tools/perf/arch/powerpc/util/skip-callchain-idx.c
+++ b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
@@ -61,7 +61,13 @@ static int check_return_reg(int ra_regno, Dwarf_Frame *frame)
 	 * Check if return address is on the stack.
 	 */
 	if (nops != 0 || ops != NULL)
-		return 0;
+		/*
+		 * Check if return address is not in R0. In that
+		 * case, it must be on the stack.
+		 */
+		if (nops != 1 || ops[0].atom != DW_OP_regx ||
+				ops[0].number != 0 || ops[0].number2 != 0)
+			return 0;
 
 	/*
 	 * Return address is in LR. Check if a frame was allocated
@@ -145,18 +151,32 @@ static Dwarf_Frame *get_dwarf_frame(Dwfl_Module *mod, Dwarf_Addr pc)
  *		yet used)
  *	-1 in case of errors
  */
-static int check_return_addr(struct dso *dso, u64 map_start, Dwarf_Addr pc)
+static int check_return_addr(struct thread *thread, Dwarf_Addr pc)
 {
-	int		rc = -1;
-	Dwfl		*dwfl;
-	Dwfl_Module	*mod;
-	Dwarf_Frame	*frame;
-	int		ra_regno;
-	Dwarf_Addr	start = pc;
-	Dwarf_Addr	end = pc;
-	bool		signalp;
-	const char	*exec_file = dso->long_name;
+	int			rc = -1;
+	Dwfl			*dwfl;
+	Dwfl_Module		*mod;
+	Dwarf_Frame		*frame;
+	int			ra_regno;
+	Dwarf_Addr		start = pc;
+	Dwarf_Addr		end = pc;
+	bool			signalp;
+	const char		*exec_file;
+	struct addr_location	al;
+	struct dso		*dso;
+	u64			map_start;
+
+	thread__find_addr_location(thread, PERF_RECORD_MISC_USER,
+			MAP__FUNCTION, pc, &al);
+
+	if (!al.map || !al.map->dso) {
+		pr_debug("%" PRIx64 " dso is NULL\n", pc);
+		return rc;
+	}
 
+	dso = al.map->dso;
+	map_start = al.map->start;
+	exec_file = dso->long_name;
 	dwfl = dso->dwfl;
 
 	if (!dwfl) {
@@ -209,6 +229,8 @@ static int check_return_addr(struct dso *dso, u64 map_start, Dwarf_Addr pc)
 	rc = check_return_reg(ra_regno, frame);
 
 out:
+	pr_debug("[DSO %s, sym %s, ip 0x%" PRIx64 "] rc %d\n",
+				dso->long_name, al.sym->name, pc, rc);
 	return rc;
 }
 
@@ -237,32 +259,26 @@ 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 = check_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 either in LR or R0 and is yet to be
+		 * written to the stack. This can be observed if the probe
+		 * is placed at an offset from the start of the function
+		 * that comes before the prologue code to write the return
+		 * address to the caller's stack frame.
+		 * So, an attempt to skip an entry based on chain->ips[2],
+		 * i.e. the LR value, must 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 = check_return_addr(thread, chain->ips[2]);
 
 	if (rc == 0) {
 		/*
-- 
2.14.3

[PATCH v2 2/3] perf tools powerpc: Fix crash if callchain is empty

[Sandipan Das]

For some cases, the callchain provided by the kernel may be
empty. So, the callchain ip filtering code will cause a crash
if we do not check whether the struct ip_callchain pointer is
NULL before accessing any members.

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

 # perf record -b -e cycles:u ls
 # perf report --branch-history
 perf: Segmentation fault
 -------- backtrace --------
 perf[0x1027615c]
 linux-vdso64.so.1(__kernel_sigtramp_rt64+0x0)[0x7fff856304d8]
 perf(arch_skip_callchain_idx+0x44)[0x10257c58]
 perf[0x1017f2e4]
 perf(thread__resolve_callchain+0x124)[0x1017ff5c]
 perf(sample__resolve_callchain+0xf0)[0x10172788]
 ...

Reported-by: Ravi Bangoria <ravi.bangoria@linux.vnet.ibm.com>
Signed-off-by: Sandipan Das <sandipan@linux.vnet.ibm.com>
---
 tools/perf/arch/powerpc/util/skip-callchain-idx.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/arch/powerpc/util/skip-callchain-idx.c b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
index d3a13f79d3ee..910db8762120 100644
--- a/tools/perf/arch/powerpc/util/skip-callchain-idx.c
+++ b/tools/perf/arch/powerpc/util/skip-callchain-idx.c
@@ -262,7 +262,7 @@ int arch_skip_callchain_idx(struct thread *thread, struct ip_callchain *chain)
 	int rc;
 	u64 skip_slot = -1;
 
-	if (chain->nr < 3)
+	if (!chain || chain->nr < 3)
 		return skip_slot;
 
 	rc = check_return_addr(thread, chain->ips[1]);
-- 
2.14.3

[PATCH v2 3/3] 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.

Output before applying this 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!

Output after applying this 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 v2 0/3] perf: Fixes for callchain ip handling on powerpc

[Arnaldo Carvalho de Melo]

Em Wed, Apr 18, 2018 at 04:28:57PM +0530, Sandipan Das escreveu:
> 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 crash caused by attempting to access an empty
> callchain.
> 
> The third 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.
 
> v2:
>  - Consider case when return address is in R0 as pointed out by Ravi.
>  - Add another patch to fix crash when callchain is empty.

Ravi, can you please take a look at these? The other two patches too,
please?

- Arnaldo

Re: [PATCH v2 0/3] perf: Fixes for callchain ip handling on powerpc

[Ravi Bangoria]

On 04/18/2018 04:28 PM, Sandipan Das wrote:
> 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 crash caused by attempting to access an empty
> callchain.
>
> The third 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.
>
> v2:
>  - Consider case when return address is in R0 as pointed out by Ravi.
>  - Add another patch to fix crash when callchain is empty.

Looks good. For the series,

Tested-by: Ravi Bangoria <ravi.bangoria@linux.ibm.com>

But there are few other cases, I've mentioned them in detail at the end,
which needs to be fixed. Arnaldo, if you are fine, can we push this series
and take care of other cases later on? No point in stretching this series.

I've used this simple test program to test it:

    int i = 10000000;
    void *ptr;

    while (i--) {
        ptr = malloc(i);
        free(ptr);
    }


Case 1:

Without Suka's and Sandipan's changes:

    perf  9207  3034.786828:   cycles:ppp:
                      10d66c power_pmu_enable (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      2e4f24 perf_event_exec (/lib/modules/4.17.0-rc1+/build/vmlinux)            <===== This one
                      4096cc setup_new_exec (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      494f38 load_elf_binary (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      40842c search_binary_handler (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      40924c do_execveat_common.isra.13 (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      40981c sys_execve (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       1b9e0 system_call (/lib/modules/4.17.0-rc1+/build/vmlinux)
                7fff9855b448 [unknown] ([unknown])

With only Suka's changes:

    perf  9207  3034.786828:   cycles:ppp:
                      10d66c power_pmu_enable (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      4096cc setup_new_exec (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      494f38 load_elf_binary (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      40842c search_binary_handler (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      40924c do_execveat_common.isra.13 (/lib/modules/4.17.0-rc1+/build/vmlinux)
                      40981c sys_execve (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       1b9e0 system_call (/lib/modules/4.17.0-rc1+/build/vmlinux)
                7fff9855b448 [unknown] ([unknown])

With both Suka's and Sandipan's changes:

     perf  9207  3034.786828:   cycles:ppp:
                       10d66c power_pmu_enable (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       4096cc setup_new_exec (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       494f38 load_elf_binary (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       40842c search_binary_handler (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       40924c do_execveat_common.isra.13 (/lib/modules/4.17.0-rc1+/build/vmlinux)
                       40981c sys_execve (/lib/modules/4.17.0-rc1+/build/vmlinux)
                        1b9e0 system_call (/lib/modules/4.17.0-rc1+/build/vmlinux)
                 7fff9855b448 [unknown] ([unknown])
   
perf_event_exec() is a valid entry, which is missing in last two output.


Case 2:

Without Suka's and Sandipan's changes:

    1854.720942:     568814 cycles:ppp:
         9cf3c _int_malloc (/usr/lib64/libc-2.26.so)
         9f838 malloc (/usr/lib64/libc-2.26.so)            <===== This one
             0 [unknown] ([unknown])
           624 main (/home/ravi/Workspace/malloc)
         236a0 generic_start_main.isra.0 (/usr/lib64/libc-2.26.so)
         23898 __libc_start_main (/usr/lib64/libc-2.26.so)

With only Suka's changes:

    1854.720942:     568814 cycles:ppp:
         9cf3c _int_malloc (/usr/lib64/libc-2.26.so)
             0 [unknown] ([unknown])
           624 main (/home/ravi/Workspace/malloc)
         236a0 generic_start_main.isra.0 (/usr/lib64/libc-2.26.so)
         23898 __libc_start_main (/usr/lib64/libc-2.26.so)

With both Suka's and Sandipan's changes:

    1854.720942:     568814 cycles:ppp:
         9cf3c _int_malloc (/usr/lib64/libc-2.26.so)
             0 [unknown] ([unknown])
           624 main (/home/ravi/Workspace/malloc)
         236a0 generic_start_main.isra.0 (/usr/lib64/libc-2.26.so)
         23898 __libc_start_main (/usr/lib64/libc-2.26.so)

malloc() is missing in last two output. Also, the pattern I've observed is,
all samples where malloc() is missing is followed by  0 [unknown] ([unknown]).

Thanks,
Ravi