Skip to contentSkip to conversation

perf test: Fix test case Merge cpu map

PATCH Applied Thomas Richter 3 participants 6 messages Jan 20, 2020 – Feb 5, 2020 perf events

lore
Share & tools
lore
#0 lore raw

PATCH v2 1/1 perf test: Fix test case Merge cpu map

V2: Added Reviewed-by statement

Commit a2408a70368a ("perf evlist: Maintain evlist->all_cpus") introduces a test case for cpumap merge operation, see functions perf_cpu_map__merge() and test__cpu_map_merge().

The test case fails on s390 with this error message:
[root@m35lp76 perf]# ./perf test -Fvvvvv 52
52: Merge cpu map :
--- start ---
cpumask list: 1-2,4-5,7
perf: /root/linux/tools/include/linux/refcount.h:131:\
refcount_sub_and_test: Assertion `!(new > val)' failed.
Aborted (core dumped)
[root@m35lp76 perf]#

The root cause is in the function test__cpu_map_merge():
It creates two cpu_maps named 'a' and 'b':

  struct perf_cpu_map *a = perf_cpu_map__new("4,2,1");
  struct perf_cpu_map *b = perf_cpu_map__new("4,5,7");

and creates a third map named 'c' which is the result of the merge of maps a and b:

  struct perf_cpu_map *c = perf_cpu_map__merge(a, b);

After some verifaction of the merged cpu_map all three of them are have their reference count reduced and are freed:

   perf_cpu_map__put(a); (1)
   perf_cpu_map__put(b);
   perf_cpu_map__put(c);

The release of perf_cpu_map__put(a) is wrong. The map is already released and free'ed as part of the function

  perf_cpu_map__merge(struct perf_cpu_map *orig,
  |	              struct perf_cpu_map *other)
  +--> perf_cpu_map__put(orig);
       |
       +--> cpu_map__delete(orig)

At the end perf_cpu_map_put() is called for map 'orig' alias 'a' and since the reference count is 1, the map is deleted, as can be seen by the following gdb trace:

(gdb) where
#0 tcache_put (tc_idx=0, chunk=0x156cc30) at malloc.c:2940 #1 _int_free (av=0x3fffd49ee80 <main_arena>, p=0x156cc30,

		     have_lock=<optimized out>) at malloc.c:4222
 #2  0x00000000012d5e78 in cpu_map__delete (map=0x156cc40) at cpumap.c:31
 #3  0x00000000012d5f7a in perf_cpu_map__put (map=0x156cc40) at cpumap.c:45
 #4  0x00000000012d723a in perf_cpu_map__merge (orig=0x156cc40,
     other=0x156cc60) at cpumap.c:343
 #5  0x000000000110cdd0 in test__cpu_map_merge (
     test=0x14ea6c8 <generic_tests+2856>, subtest=-1) at tests/cpumap.c:128

Thus the perf_cpu_map__put(a) (see (1) above) frees map 'a' a second time and causes the failure. Fix this be removing that function call.

Output after:
[root@m35lp76 perf]# ./perf test -Fvvvvv 52
52: Merge cpu map :
--- start ---
cpumask list: 1-2,4-5,7
---- end ----
Merge cpu map: Ok
[root@m35lp76 perf]#

---
 tools/perf/tests/cpumap.c | 1 -
 1 file changed, 1 deletion(-)
tools/perf/tests/cpumap.c +0 -1
index 4ac56741ac5f..29c793ac7d10 100644
@@ -131,7 +131,6 @@ int test__cpu_map_merge(struct test *test __maybe_unused, int subtest __maybe_un
 	TEST_ASSERT_VAL("failed to merge map: bad nr", c->nr == 5);
 	cpu_map__snprint(c, buf, sizeof(buf));
 	TEST_ASSERT_VAL("failed to merge map: bad result", !strcmp(buf, "1-2,4-5,7"));
-	perf_cpu_map__put(a);
 	perf_cpu_map__put(b);
 	perf_cpu_map__put(c);
 	return 0;
Signature · 1 line
2.21.0
#1 lore raw

PATCH v2 1/1 perf probe: Add ustring support for perf probe command

Kernel commit 88903c464321 ("tracing/probe: Add ustring type for user-space string") adds support for user-space strings when type 'ustring' is specified.

Here is an example using sysfs command line interface for kprobes:

Function to probe:
struct filename *
getname_flags(const char __user *filename, int flags, int *empty)

Setup:

  # cd /sys/kernel/debug/tracing/
  # echo 'p:tmr1 getname_flags +0(%r2):ustring' > kprobe_events
  # cat events/kprobes/tmr1/format | fgrep print
  print fmt: "(%lx) arg1=\"%s\"", REC->__probe_ip, REC->arg1
  # echo 1 > events/kprobes/tmr1/enable
  # touch /tmp/111
  # echo 0 > events/kprobes/tmr1/enable
  # cat trace|fgrep /tmp/111
  touch-5846  [005] d..2 255520.717960: tmr1:\
	  (getname_flags+0x0/0x400) arg1="/tmp/111"

Doing the same with the perf tool fails.
Using type 'string' succeeds:

 # perf probe "vfs_getname=getname_flags:72 pathname=filename:string"
 Added new event:
   probe:vfs_getname (on getname_flags:72 with pathname=filename:string)
   ....
 # perf probe -d probe:vfs_getname
 Removed event: probe:vfs_getname

However using type 'ustring' fails (output before):

 # perf probe "vfs_getname=getname_flags:72 pathname=filename:ustring"
 Failed to write event: Invalid argument
   Error: Failed to add events.
 #

Fix this by adding type 'ustring' in function
convert_variable_type().

Using ustring succeeds (output after):

 # ./perf probe "vfs_getname=getname_flags:72 pathname=filename:ustring"
 Added new event:
   probe:vfs_getname (on getname_flags:72 with pathname=filename:ustring)

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

perf record -e probe:vfs_getname -aR sleep 1

#

Note: This issue also exists on x86, it is not s390 specific.

---
 tools/perf/util/probe-finder.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
tools/perf/util/probe-finder.c +2 -1
index c470c49a804f..1c817add6ca4 100644
@@ -303,7 +303,8 @@ static int convert_variable_type(Dwarf_Die *vr_die,
 	char prefix;
 
 	/* TODO: check all types */
-	if (cast && strcmp(cast, "string") != 0 && strcmp(cast, "x") != 0 &&
+	if (cast && strcmp(cast, "string") != 0 && strcmp(cast, "ustring") &&
+	    strcmp(cast, "x") != 0 &&
 	    strcmp(cast, "s") != 0 && strcmp(cast, "u") != 0) {
 		/* Non string type is OK */
 		/* and respect signedness/hexadecimal cast */
Signature · 1 line
2.21.0
merge bot Applied
#2 lore raw

[tip: perf/urgent] perf probe: Add ustring support for perf probe command

The following commit has been merged into the perf/urgent branch of tip:

The following commit has been merged into the perf/urgent branch of tip:

Commit-ID:     1873f1547dde65c687de143938581347a9312207
Gitweb:        https://git.kernel.org/tip/1873f1547dde65c687de143938581347a9312207
Author:        Thomas Richter <[email protected]>
AuthorDate:    Mon, 20 Jan 2020 14:20:10 +01:00
Committer:     Arnaldo Carvalho de Melo <[email protected]>
CommitterDate: Fri, 31 Jan 2020 09:33:58 +01:00

perf probe: Add ustring support for perf probe command

Kernel commit 88903c464321 ("tracing/probe: Add ustring type for user-space string") adds support for user-space strings when type 'ustring' is specified.

Here is an example using sysfs command line interface for kprobes:

Function to probe:
struct filename *
getname_flags(const char __user *filename, int flags, int *empty)

Setup:

  # cd /sys/kernel/debug/tracing/
  # echo 'p:tmr1 getname_flags +0(%r2):ustring' > kprobe_events
  # cat events/kprobes/tmr1/format | fgrep print
  print fmt: "(%lx) arg1=\"%s\"", REC->__probe_ip, REC->arg1
  # echo 1 > events/kprobes/tmr1/enable
  # touch /tmp/111
  # echo 0 > events/kprobes/tmr1/enable
  # cat trace|fgrep /tmp/111
  touch-5846  [005] d..2 255520.717960: tmr1:\
	  (getname_flags+0x0/0x400) arg1="/tmp/111"

Doing the same with the perf tool fails.
Using type 'string' succeeds:

 # perf probe "vfs_getname=getname_flags:72 pathname=filename:string"
 Added new event:
   probe:vfs_getname (on getname_flags:72 with pathname=filename:string)
   ....
 # perf probe -d probe:vfs_getname
 Removed event: probe:vfs_getname

However using type 'ustring' fails (output before):

 # perf probe "vfs_getname=getname_flags:72 pathname=filename:ustring"
 Failed to write event: Invalid argument
   Error: Failed to add events.
 #

Fix this by adding type 'ustring' in function
convert_variable_type().

Using ustring succeeds (output after):

 # ./perf probe "vfs_getname=getname_flags:72 pathname=filename:ustring"
 Added new event:
   probe:vfs_getname (on getname_flags:72 with pathname=filename:ustring)

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

perf record -e probe:vfs_getname -aR sleep 1

#

Note: This issue also exists on x86, it is not s390 specific.

---
 tools/perf/util/probe-finder.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)
tools/perf/util/probe-finder.c +2 -1
index c470c49..1c817ad 100644
@@ -303,7 +303,8 @@ static int convert_variable_type(Dwarf_Die *vr_die,
 	char prefix;
 
 	/* TODO: check all types */
-	if (cast && strcmp(cast, "string") != 0 && strcmp(cast, "x") != 0 &&
+	if (cast && strcmp(cast, "string") != 0 && strcmp(cast, "ustring") &&
+	    strcmp(cast, "x") != 0 &&
 	    strcmp(cast, "s") != 0 && strcmp(cast, "u") != 0) {
 		/* Non string type is OK */
 		/* and respect signedness/hexadecimal cast */
#3 lore raw

PATCH v2 1/1 perf test: Fix test trace+probe_vfs_getname.sh

In reply to Thomas Richter

This test places a kprobe to function getname_flags() in the kernel which has the following prototype:

struct filename *
getname_flags(const char __user *filename, int flags, int *empty)

Variable filename points to a filename located in user space memory. Looking at
commit 88903c464321c ("tracing/probe: Add ustring type for user-space string") the kprobe should indicate that user space memory is accessed.

Fix this with a patch to specify user space memory access to parameter 'filename' and 'string' is replaced by 'ustring'.

---
 tools/perf/tests/shell/lib/probe_vfs_getname.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/tests/shell/lib/probe_vfs_getname.sh +2 -2
index 7cb99b433888..7ecf117651dd 100644
@@ -13,8 +13,8 @@ add_probe_vfs_getname() {
 	local verbose=$1
 	if [ $had_vfs_getname -eq 1 ] ; then
 		line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
-		perf probe -q       "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
-		perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
+		perf probe -q       "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
+		perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring"
 	fi
 }
 
Signature · 1 line
2.21.0
#4 lore raw

Re: [PATCH v2] perf test: Fix test trace+probe_vfs_getname.sh

Em Mon, Jan 20, 2020 at 02:20:11PM +0100, Thomas Richter escreveu:

Quoted 10 lines

This test places a kprobe to function getname_flags() in the kernel which has the following prototype:

struct filename *
getname_flags(const char __user *filename, int flags, int *empty)

Variable filename points to a filename located in user space memory. Looking at
commit 88903c464321c ("tracing/probe: Add ustring type for user-space string") the kprobe should indicate that user space memory is accessed.

We can't just replace it, right? I.e. this should continue to work with older kernels, i.e. the latest userspace tooling version should work when installed in an older kernel, i.e. please just add more fallbacks to cover the new cases.

- Arnaldo

Quoted 26 lines

Fix this with a patch to specify user space memory access to parameter 'filename' and 'string' is replaced by 'ustring'.

---
 tools/perf/tests/shell/lib/probe_vfs_getname.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
tools/perf/tests/shell/lib/probe_vfs_getname.sh +2 -2
index 7cb99b433888..7ecf117651dd 100644
@@ -13,8 +13,8 @@ add_probe_vfs_getname() {
 	local verbose=$1
 	if [ $had_vfs_getname -eq 1 ] ; then
 		line=$(perf probe -L getname_flags 2>&1 | egrep 'result.*=.*filename;' | sed -r 's/[[:space:]]+([[:digit:]]+)[[:space:]]+result->uptr.*/\1/')
-		perf probe -q       "vfs_getname=getname_flags:${line} pathname=result->name:string" || \
-		perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:string"
+		perf probe -q       "vfs_getname=getname_flags:${line} pathname=result->uptr:ustring" || \
+		perf probe $verbose "vfs_getname=getname_flags:${line} pathname=filename:ustring"
 	fi
 }
 
Signature · 1 line
2.21.0
Signature · 1 line
- Arnaldo
merge bot Applied
#5 lore raw
In reply to Thomas Richter
The following commit has been merged into the perf/urgent branch of tip:

The following commit has been merged into the perf/urgent branch of tip:

Commit-ID:     0dd1979f7f9981dcc5c497e68390f208580032ae
Gitweb:        https://git.kernel.org/tip/0dd1979f7f9981dcc5c497e68390f208580032ae
Author:        Thomas Richter <[email protected]>
AuthorDate:    Mon, 20 Jan 2020 14:20:09 +01:00
Committer:     Arnaldo Carvalho de Melo <[email protected]>
CommitterDate: Thu, 30 Jan 2020 11:55:02 +01:00

perf test: Fix test case Merge cpu map

Commit a2408a70368a ("perf evlist: Maintain evlist->all_cpus") introduces a test case for cpumap merge operation, see functions perf_cpu_map__merge() and test__cpu_map_merge().

The test case fails on s390 with this error message:

[root@m35lp76 perf]# ./perf test -Fvvvvv 52
52: Merge cpu map :
--- start ---
cpumask list: 1-2,4-5,7
perf: /root/linux/tools/include/linux/refcount.h:131:\
refcount_sub_and_test: Assertion `!(new > val)' failed.
Aborted (core dumped)
[root@m35lp76 perf]#

The root cause is in the function test__cpu_map_merge():
It creates two cpu_maps named 'a' and 'b':

  struct perf_cpu_map *a = perf_cpu_map__new("4,2,1");
  struct perf_cpu_map *b = perf_cpu_map__new("4,5,7");

and creates a third map named 'c' which is the result of the merge of maps a and b:

  struct perf_cpu_map *c = perf_cpu_map__merge(a, b);

After some verifaction of the merged cpu_map all three of them are have their reference count reduced and are freed:

   perf_cpu_map__put(a); (1)
   perf_cpu_map__put(b);
   perf_cpu_map__put(c);

The release of perf_cpu_map__put(a) is wrong. The map is already released and free'ed as part of the function

  perf_cpu_map__merge(struct perf_cpu_map *orig,
  |	              struct perf_cpu_map *other)
  +--> perf_cpu_map__put(orig);
       |
       +--> cpu_map__delete(orig)

At the end perf_cpu_map_put() is called for map 'orig' alias 'a' and since the reference count is 1, the map is deleted, as can be seen by the following gdb trace:

(gdb) where
#0 tcache_put (tc_idx=0, chunk=0x156cc30) at malloc.c:2940 #1 _int_free (av=0x3fffd49ee80 <main_arena>, p=0x156cc30,

		     have_lock=<optimized out>) at malloc.c:4222
 #2  0x00000000012d5e78 in cpu_map__delete (map=0x156cc40) at cpumap.c:31
 #3  0x00000000012d5f7a in perf_cpu_map__put (map=0x156cc40) at cpumap.c:45
 #4  0x00000000012d723a in perf_cpu_map__merge (orig=0x156cc40,
     other=0x156cc60) at cpumap.c:343
 #5  0x000000000110cdd0 in test__cpu_map_merge (
     test=0x14ea6c8 <generic_tests+2856>, subtest=-1) at tests/cpumap.c:128

Thus the perf_cpu_map__put(a) (see (1) above) frees map 'a' a second time and causes the failure. Fix this be removing that function call.

Output after:
[root@m35lp76 perf]# ./perf test -Fvvvvv 52
52: Merge cpu map :
--- start ---
cpumask list: 1-2,4-5,7
---- end ----
Merge cpu map: Ok
[root@m35lp76 perf]#

---
 tools/perf/tests/cpumap.c | 1 -
 1 file changed, 1 deletion(-)
tools/perf/tests/cpumap.c +0 -1
index 4ac5674..29c793a 100644
@@ -131,7 +131,6 @@ int test__cpu_map_merge(struct test *test __maybe_unused, int subtest __maybe_un
 	TEST_ASSERT_VAL("failed to merge map: bad nr", c->nr == 5);
 	cpu_map__snprint(c, buf, sizeof(buf));
 	TEST_ASSERT_VAL("failed to merge map: bad result", !strcmp(buf, "1-2,4-5,7"));
-	perf_cpu_map__put(a);
 	perf_cpu_map__put(b);
 	perf_cpu_map__put(c);
 	return 0;