perf test '84: probe libc's inet_pton & backtrace it with ping'
fails on s390. Debugging revealed a changed stack trace for the
ping command using probes:
ping 35729 [002] 8006.365063: probe_libc:inet_pton: (3ff9603e7c0)
13e7c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
---> 104371 text_to_binary_address+0xef1 (inlined)
104371 gaih_inet+0xef1 (inlined)
104371 __GI_getaddrinfo+0xef1 (inlined)
5d4b main+0x139b (/usr/bin/ping)
The line ---> text_to_binary_address ...
is new. It was introduced with glibc version 2.36.7.2 released
with Fedora 37 for s390.
Output before
# ./perf test 84
84: probe libc's inet_pton & backtrace it with ping : FAILED!
#
Output after:
# ./perf test 84
84: probe libc's inet_pton & backtrace it with ping : Ok
#
Signed-off-by: Thomas Richter <[email protected]>
---
tools/perf/tests/shell/record+probe_libc_inet_pton.sh | 1 +
1 file changed, 1 insertion(+)
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 34c400ccbe04..4e9de55d871a 100755
--- a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
+++ b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
@@ -37,6 +37,7 @@ trace_libc_inet_pton_backtrace() {
case "$(uname -m)" in
s390x)
eventattr='call-graph=dwarf,max-stack=4'
+ echo "text_to_binary_address.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
echo "gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
echo "(__GI_)?getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
echo "main\+0x[[:xdigit:]]+[[:space:]]\(.*/bin/ping.*\)$" >> $expected
--
2.38.1
From: Thomas Richter <[email protected]>
perf test '89: probe libc's inet_pton & backtrace it with ping'
fails on x86. Debugging revealed a changed stack trace for the
ping command using probes:
ping 35729 [002] 8006.365063: probe_libc:inet_pton: (3ff9603e7c0)
12be50 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
4fca main+0x139b (/usr/bin/ping)
The line getaddrinfo.... in the call stack is gone.
It was introduced with glibc version 2.36.8 released
with Fedora 37.
To make the test case more robust to glibc changes resulting in changed
call stacks, redesign the test completely.
Read the output lines from the perf probe of the ping command.
Create an array of expected patterns. Each array entry specifies a
pattern that may appear in the perf probe output.
Check that each probe output line is matched in the expected
patterns array. If there is no match it is an error.
However not every pattern in the expected pattern array must be hit
as there may be redundant entries.
This scheme does not test the sequence of the call stack entries
but the patterns itself are long and complicated enough.
Also each perf probe output line has to be in the expected pattern
array for the test to pass
Output before on x86
# ./perf test 89
89: probe libc's inet_pton & backtrace it with ping : FAILED!
#
Output after on x86
# ./perf test 89
89: probe libc's inet_pton & backtrace it with ping : Ok
#
Signed-off-by: Thomas Richter <[email protected]>
---
.../shell/record+probe_libc_inet_pton.sh | 70 +++++++++++++------
1 file changed, 47 insertions(+), 23 deletions(-)
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 4e9de55d871a..3baef1aa92f5 100755
--- a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
+++ b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
@@ -30,28 +30,37 @@ add_libc_inet_pton_event() {
trace_libc_inet_pton_backtrace() {
- expected=`mktemp -u /tmp/expected.XXX`
+ declare -a expected
+ local -i idx=0 hit maxstack=4
- echo "ping[][0-9 \.:]+$event_name: \([[:xdigit:]]+\)" > $expected
- echo ".*inet_pton\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
+ expected[0]='ping[][0-9 \.:]+'"$event_name"': \([[:xdigit:]]+\)'
+ expected[1]='.*inet_pton\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'|inlined\)$'
case "$(uname -m)" in
s390x)
- eventattr='call-graph=dwarf,max-stack=4'
- echo "text_to_binary_address.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
- echo "gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
- echo "(__GI_)?getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
- echo "main\+0x[[:xdigit:]]+[[:space:]]\(.*/bin/ping.*\)$" >> $expected
+ eventattr='call-graph=dwarf,max-stack='"$maxstack"
+ expected[2]='text_to_binary_address.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$'
+ expected[3]='gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'|inlined\)$'
+ expected[4]='(__GI_)?getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'|inlined\)$'
+ expected[5]='main\+0x[[:xdigit:]]+[[:space:]]\(.*/bin/ping.*\)$'
;;
ppc64|ppc64le)
- eventattr='max-stack=4'
- echo "gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\($libc\)$" >> $expected
- echo "getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc\)$" >> $expected
- echo ".*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$" >> $expected
+ eventattr='max-stack='"$maxstack"
+ expected[2]='gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'\)$'
+ expected[3]='getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'\)$'
+ # Line valid with glibc 2.35.x with fedora 36
+ expected[4]='.*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$'
+ # New line introduced with glibc 2.36.x with fedora 37, replaces previous line
+ expected[5]='[[:xdigit:]]+[[:space:]](\[unknown\]|main)\+0x[[:xdigit:]]+.*\(.*/bin/ping.*\)$'
;;
*)
- eventattr='max-stack=3'
- echo "getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc\)$" >> $expected
- echo ".*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$" >> $expected
+ maxstack=3
+ eventattr='max-stack='"$maxstack"
+ expected[2]='getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'\)$'
+ # Line valid with glibc 2.35.x with fedora 36
+ expected[3]='.*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$'
+ # New lines introduced with glibc 2.36.x with fedora 37, replaces previous line
+ expected[4]='[[:xdigit:]]+[[:space:]](\[unknown\]|main)\+0x[[:xdigit:]]+.*\(.*/bin/ping.*\)$'
+ expected[5]='.*main\+0x[[:xdigit:]]+.*\('"$libc"'\)$'
;;
esac
@@ -60,16 +69,31 @@ trace_libc_inet_pton_backtrace() {
perf record -e $event_name/$eventattr/ -o $perf_data ping -6 -c 1 ::1 > /dev/null 2>&1
perf script -i $perf_data > $perf_script
+ # To make the call stack checking more robust to changes in the glibc
+ # just check that each probe output line appears in the expected
+ # patterns array.
+ # This scheme does not check the sequence as before but tests
+ # that every line in the call stack is expected. Considering the
+ # long patterns this should be save too.
exec 3<$perf_script
- exec 4<$expected
- while read line <&3 && read -r pattern <&4; do
- [ -z "$pattern" ] && break
- echo $line
- echo "$line" | grep -E -q "$pattern"
- if [ $? -ne 0 ] ; then
- printf "FAIL: expected backtrace entry \"%s\" got \"%s\"\n" "$pattern" "$line"
+
+ # Number of input lines to check, take value from max-stack attribute
+ while read line <&3; do
+ [ "$idx" -ge "$maxstack" ] && break
+ [ -z "$line" ] && break
+
+ hit=0
+ for pattern in "${expected[@]}"
+ do
+ echo "$line" | egrep -q "$pattern"
+ [ $? -eq 0 ] && { hit=1; break; }
+ done
+ if [ "$hit" -eq 0 ]
+ then
+ printf "FAIL: missing backtrace entry for line \"%s\"\n" "$line"
return 1
fi
+ ((++idx))
done
# If any statements are executed from this point onwards,
@@ -92,6 +116,6 @@ skip_if_no_perf_probe && \
add_libc_inet_pton_event && \
trace_libc_inet_pton_backtrace
err=$?
-rm -f ${perf_data} ${perf_script} ${expected}
+rm -f ${perf_data} ${perf_script}
delete_libc_inet_pton_event
exit $err
--
2.38.1
Em Wed, Dec 28, 2022 at 03:57:04PM +0100, Thomas Richter escreveu:
> From: Thomas Richter <[email protected]>
>
> perf test '89: probe libc's inet_pton & backtrace it with ping'
> fails on x86. Debugging revealed a changed stack trace for the
> ping command using probes:
>
> ping 35729 [002] 8006.365063: probe_libc:inet_pton: (3ff9603e7c0)
> 12be50 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
> 4fca main+0x139b (/usr/bin/ping)
>
> The line getaddrinfo.... in the call stack is gone.
> It was introduced with glibc version 2.36.8 released
> with Fedora 37.
Humm, I'm testing and invetigating this issue and by looking at the
backtraces I see that it is just on the first entry that the getaddrinfo
isn't present, i.e. now there are two inet_pton() calls, one of them
doesn't come from getaddrinfo():
[root@quaco ~]# cat /tmp/perf.script.IUC
ping 623883 [006] 265438.471610: probe_libc:inet_pton: (7f32bcf314c0)
1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
29510 __libc_start_call_main+0x80 (/usr/lib64/libc.so.6)
ping 623883 [006] 265438.471664: probe_libc:inet_pton: (7f32bcf314c0)
1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
fa6c6 getaddrinfo+0x126 (/usr/lib64/libc.so.6)
491e [unknown] (/usr/bin/ping)
The above is the temp file for the perf script output from the collected
perf.data file See the second entry? Its as we expect:
[root@quaco ~]# cat /tmp/expected.aT6
ping[][0-9 \.:]+probe_libc:inet_pton: \([[:xdigit:]]+\)
.*inet_pton\+0x[[:xdigit:]]+[[:space:]]\(/usr/lib64/libc.so.6|inlined\)$
getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\(/usr/lib64/libc.so.6\)$
.*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$
[root@quaco ~]#
But if I just ignore that first one and match against the second event
instance:
[root@quaco ~]# perf test inet_pton
90: probe libc's inet_pton & backtrace it with ping : Ok
[root@quaco ~]# perf test -v inet_pton
90: probe libc's inet_pton & backtrace it with ping :
--- start ---
test child forked, pid 626199
ping 626222 [007] 266979.123047: probe_libc:inet_pton_1: (7f0650d314c0)
1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
fa6c6 getaddrinfo+0x126 (/usr/lib64/libc.so.6)
491e n (/usr/bin/ping)
test child finished with 0
---- end ----
probe libc's inet_pton & backtrace it with ping: Ok
[root@quaco ~]#
So, can you try with the following patch in your s/390 system?
I wish 'perf script' had a --skip option that allowed us to ask for just
the second event, not having that I did a trick with tac + grep -m1 -B :-)
We can try to revisit your approach for the next merge window, as at
this point, for 6.2 we want for fixes to be as minimal as possible.
It works for me on Fedora 36, glibc 2.35-20.fc36, where it was failing,
I'll now try on a arm64 machine, thanks.
- Arnaldo
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 34c400ccbe046b59..216b6b64caa3011e 100755
--- a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
+++ b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
@@ -57,7 +57,7 @@ trace_libc_inet_pton_backtrace() {
perf_data=`mktemp -u /tmp/perf.data.XXX`
perf_script=`mktemp -u /tmp/perf.script.XXX`
perf record -e $event_name/$eventattr/ -o $perf_data ping -6 -c 1 ::1 > /dev/null 2>&1
- perf script -i $perf_data > $perf_script
+ perf script -i $perf_data | tac | grep -m1 ^ping -B9 | tac > $perf_script
exec 3<$perf_script
exec 4<$expected
> To make the test case more robust to glibc changes resulting in changed
> call stacks, redesign the test completely.
> Read the output lines from the perf probe of the ping command.
> Create an array of expected patterns. Each array entry specifies a
> pattern that may appear in the perf probe output.
> Check that each probe output line is matched in the expected
> patterns array. If there is no match it is an error.
> However not every pattern in the expected pattern array must be hit
> as there may be redundant entries.
>
> This scheme does not test the sequence of the call stack entries
> but the patterns itself are long and complicated enough.
> Also each perf probe output line has to be in the expected pattern
> array for the test to pass
>
> Output before on x86
> # ./perf test 89
> 89: probe libc's inet_pton & backtrace it with ping : FAILED!
> #
>
> Output after on x86
> # ./perf test 89
> 89: probe libc's inet_pton & backtrace it with ping : Ok
> #
>
> Signed-off-by: Thomas Richter <[email protected]>
> ---
> .../shell/record+probe_libc_inet_pton.sh | 70 +++++++++++++------
> 1 file changed, 47 insertions(+), 23 deletions(-)
>
> 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 4e9de55d871a..3baef1aa92f5 100755
> --- a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
> +++ b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
> @@ -30,28 +30,37 @@ add_libc_inet_pton_event() {
>
> trace_libc_inet_pton_backtrace() {
>
> - expected=`mktemp -u /tmp/expected.XXX`
> + declare -a expected
> + local -i idx=0 hit maxstack=4
>
> - echo "ping[][0-9 \.:]+$event_name: \([[:xdigit:]]+\)" > $expected
> - echo ".*inet_pton\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
> + expected[0]='ping[][0-9 \.:]+'"$event_name"': \([[:xdigit:]]+\)'
> + expected[1]='.*inet_pton\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'|inlined\)$'
> case "$(uname -m)" in
> s390x)
> - eventattr='call-graph=dwarf,max-stack=4'
> - echo "text_to_binary_address.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
> - echo "gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
> - echo "(__GI_)?getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$" >> $expected
> - echo "main\+0x[[:xdigit:]]+[[:space:]]\(.*/bin/ping.*\)$" >> $expected
> + eventattr='call-graph=dwarf,max-stack='"$maxstack"
> + expected[2]='text_to_binary_address.*\+0x[[:xdigit:]]+[[:space:]]\($libc|inlined\)$'
> + expected[3]='gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'|inlined\)$'
> + expected[4]='(__GI_)?getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'|inlined\)$'
> + expected[5]='main\+0x[[:xdigit:]]+[[:space:]]\(.*/bin/ping.*\)$'
> ;;
> ppc64|ppc64le)
> - eventattr='max-stack=4'
> - echo "gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\($libc\)$" >> $expected
> - echo "getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc\)$" >> $expected
> - echo ".*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$" >> $expected
> + eventattr='max-stack='"$maxstack"
> + expected[2]='gaih_inet.*\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'\)$'
> + expected[3]='getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'\)$'
> + # Line valid with glibc 2.35.x with fedora 36
> + expected[4]='.*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$'
> + # New line introduced with glibc 2.36.x with fedora 37, replaces previous line
> + expected[5]='[[:xdigit:]]+[[:space:]](\[unknown\]|main)\+0x[[:xdigit:]]+.*\(.*/bin/ping.*\)$'
> ;;
> *)
> - eventattr='max-stack=3'
> - echo "getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\($libc\)$" >> $expected
> - echo ".*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$" >> $expected
> + maxstack=3
> + eventattr='max-stack='"$maxstack"
> + expected[2]='getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\('"$libc"'\)$'
> + # Line valid with glibc 2.35.x with fedora 36
> + expected[3]='.*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$'
> + # New lines introduced with glibc 2.36.x with fedora 37, replaces previous line
> + expected[4]='[[:xdigit:]]+[[:space:]](\[unknown\]|main)\+0x[[:xdigit:]]+.*\(.*/bin/ping.*\)$'
> + expected[5]='.*main\+0x[[:xdigit:]]+.*\('"$libc"'\)$'
> ;;
> esac
>
> @@ -60,16 +69,31 @@ trace_libc_inet_pton_backtrace() {
> perf record -e $event_name/$eventattr/ -o $perf_data ping -6 -c 1 ::1 > /dev/null 2>&1
> perf script -i $perf_data > $perf_script
>
> + # To make the call stack checking more robust to changes in the glibc
> + # just check that each probe output line appears in the expected
> + # patterns array.
> + # This scheme does not check the sequence as before but tests
> + # that every line in the call stack is expected. Considering the
> + # long patterns this should be save too.
> exec 3<$perf_script
> - exec 4<$expected
> - while read line <&3 && read -r pattern <&4; do
> - [ -z "$pattern" ] && break
> - echo $line
> - echo "$line" | grep -E -q "$pattern"
> - if [ $? -ne 0 ] ; then
> - printf "FAIL: expected backtrace entry \"%s\" got \"%s\"\n" "$pattern" "$line"
> +
> + # Number of input lines to check, take value from max-stack attribute
> + while read line <&3; do
> + [ "$idx" -ge "$maxstack" ] && break
> + [ -z "$line" ] && break
> +
> + hit=0
> + for pattern in "${expected[@]}"
> + do
> + echo "$line" | egrep -q "$pattern"
> + [ $? -eq 0 ] && { hit=1; break; }
> + done
> + if [ "$hit" -eq 0 ]
> + then
> + printf "FAIL: missing backtrace entry for line \"%s\"\n" "$line"
> return 1
> fi
> + ((++idx))
> done
>
> # If any statements are executed from this point onwards,
> @@ -92,6 +116,6 @@ skip_if_no_perf_probe && \
> add_libc_inet_pton_event && \
> trace_libc_inet_pton_backtrace
> err=$?
> -rm -f ${perf_data} ${perf_script} ${expected}
> +rm -f ${perf_data} ${perf_script}
> delete_libc_inet_pton_event
> exit $err
> --
> 2.38.1
--
- Arnaldo
Em Tue, Jan 03, 2023 at 10:20:42AM -0300, Arnaldo Carvalho de Melo escreveu:
> It works for me on Fedora 36, glibc 2.35-20.fc36, where it was failing,
> I'll now try on a arm64 machine, thanks.
Works as well there, see the full commit log so far:
From e697ea1f4c481fbb87bbcd27ed1be8e1b7616046 Mon Sep 17 00:00:00 2001
From: Arnaldo Carvalho de Melo <[email protected]>
Date: Tue, 3 Jan 2023 10:21:01 -0300
Subject: [PATCH 1/1] perf test record_probe_libc_inet_pton: Fix failure due to
extra inet_pton() backtrace in glibc >= 2.35
Starting with glibc 2.35 there are extra inet_pton() calls when doing a
IPv6 ping as in one of the 'perf test' entry, which makes it fail:
# perf test inet_pton
89: probe libc's inet_pton & backtrace it with ping : FAILED!
#
If we look at what this script is expecting (commenting out the removal
of the temporary files in it):
# cat /tmp/expected.aT6
ping[][0-9 \.:]+probe_libc:inet_pton: \([[:xdigit:]]+\)
.*inet_pton\+0x[[:xdigit:]]+[[:space:]]\(/usr/lib64/libc.so.6|inlined\)$
getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\(/usr/lib64/libc.so.6\)$
.*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$
#
And looking at what we are getting out of 'perf script', to match with
the above:
# cat /tmp/perf.script.IUC
ping 623883 [006] 265438.471610: probe_libc:inet_pton: (7f32bcf314c0)
1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
29510 __libc_start_call_main+0x80 (/usr/lib64/libc.so.6)
ping 623883 [006] 265438.471664: probe_libc:inet_pton: (7f32bcf314c0)
1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
fa6c6 getaddrinfo+0x126 (/usr/lib64/libc.so.6)
491e [unknown] (/usr/bin/ping)
#
We see that its just the first call to inet_pton() that didn't came thru
getaddrinfo(), so if we ignore the first the script matches what it
expects, testing that using 'perf probe' + 'perf record' + 'perf script'
with callchains on userspace targets is producing the expected results.
Since we don't have a 'perf script --skip' to help us here, use tac +
grep to do that, resulting in a one liner that makes this script work on
both older glibc versions as well as with 2.35.
With it, on fedora 36, x86, glibc 2.35:
# perf test inet_pton
90: probe libc's inet_pton & backtrace it with ping : Ok
# perf test -v inet_pton
90: probe libc's inet_pton & backtrace it with ping :
--- start ---
test child forked, pid 627197
ping 627220 1 267956.962402: probe_libc:inet_pton_1: (7f488bf314c0)
1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
fa6c6 getaddrinfo+0x126 (/usr/lib64/libc.so.6)
491e n (/usr/bin/ping)
test child finished with 0
---- end ----
probe libc's inet_pton & backtrace it with ping: Ok
#
And on Ubuntu on a Libre Computer ROC-RK3399-PC arm64 system:
Before this patch it works (see that the script used has no 'tac' to
remove the first event):
root@roc-rk3399-pc:~# dpkg -l | grep libc-bin
ii libc-bin 2.35-0ubuntu3.1 arm64 GNU C Library: Binaries
root@roc-rk3399-pc:~# grep -w tac ~acme/libexec/perf-core/tests/shell/record+probe_libc_inet_pton.sh
root@roc-rk3399-pc:~# perf test inet_pton
86: probe libc's inet_pton & backtrace it with ping : Ok
root@roc-rk3399-pc:~# perf test -v inet_pton
86: probe libc's inet_pton & backtrace it with ping :
--- start ---
test child forked, pid 1375
ping 1399 [000] 4114.417450: probe_libc:inet_pton: (ffffb3e26120)
106120 inet_pton+0x0 (/usr/lib/aarch64-linux-gnu/libc.so.6)
d18bc getaddrinfo+0xec (/usr/lib/aarch64-linux-gnu/libc.so.6)
2b68 [unknown] (/usr/bin/ping)
test child finished with 0
---- end ----
probe libc's inet_pton & backtrace it with ping: Ok
root@roc-rk3399-pc:~#
And after it continues to work:
root@roc-rk3399-pc:~# grep -w tac ~acme/libexec/perf-core/tests/shell/record+probe_libc_inet_pton.sh
perf script -i $perf_data | tac | grep -m1 ^ping -B9 | tac > $perf_script
root@roc-rk3399-pc:~# perf test inet_pton
86: probe libc's inet_pton & backtrace it with ping : Ok
root@roc-rk3399-pc:~# perf test -v inet_pton
86: probe libc's inet_pton & backtrace it with ping :
--- start ---
test child forked, pid 6995
ping 7019 [005] 4832.160741: probe_libc:inet_pton: (ffffa62e6120)
106120 inet_pton+0x0 (/usr/lib/aarch64-linux-gnu/libc.so.6)
d18bc getaddrinfo+0xec (/usr/lib/aarch64-linux-gnu/libc.so.6)
2b68 [unknown] (/usr/bin/ping)
test child finished with 0
---- end ----
probe libc's inet_pton & backtrace it with ping: Ok
root@roc-rk3399-pc:~#
Reported-by: Thomas Richter <[email protected]>
Cc: Adrian Hunter <[email protected]>
Cc: Heiko Carstens <[email protected]>
Cc: Ian Rogers <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: Sumanth Korikkar <[email protected]>
Cc: Sven Schnelle <[email protected]>
Cc: Vasily Gorbik <[email protected]>
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
---
tools/perf/tests/shell/record+probe_libc_inet_pton.sh | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
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 34c400ccbe046b59..216b6b64caa3011e 100755
--- a/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
+++ b/tools/perf/tests/shell/record+probe_libc_inet_pton.sh
@@ -57,7 +57,7 @@ trace_libc_inet_pton_backtrace() {
perf_data=`mktemp -u /tmp/perf.data.XXX`
perf_script=`mktemp -u /tmp/perf.script.XXX`
perf record -e $event_name/$eventattr/ -o $perf_data ping -6 -c 1 ::1 > /dev/null 2>&1
- perf script -i $perf_data > $perf_script
+ perf script -i $perf_data | tac | grep -m1 ^ping -B9 | tac > $perf_script
exec 3<$perf_script
exec 4<$expected
--
2.39.0
On 1/3/23 14:20, Arnaldo Carvalho de Melo wrote:
> Em Wed, Dec 28, 2022 at 03:57:04PM +0100, Thomas Richter escreveu:
>> From: Thomas Richter <[email protected]>
>>
>> perf test '89: probe libc's inet_pton & backtrace it with ping'
>> fails on x86. Debugging revealed a changed stack trace for the
>> ping command using probes:
>>
>> ping 35729 [002] 8006.365063: probe_libc:inet_pton: (3ff9603e7c0)
>> 12be50 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
>> 4fca main+0x139b (/usr/bin/ping)
>>
>> The line getaddrinfo.... in the call stack is gone.
>> It was introduced with glibc version 2.36.8 released
>> with Fedora 37.
>
> Humm, I'm testing and invetigating this issue and by looking at the
> backtraces I see that it is just on the first entry that the getaddrinfo
> isn't present, i.e. now there are two inet_pton() calls, one of them
> doesn't come from getaddrinfo():
>
> [root@quaco ~]# cat /tmp/perf.script.IUC
> ping 623883 [006] 265438.471610: probe_libc:inet_pton: (7f32bcf314c0)
> 1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
> 29510 __libc_start_call_main+0x80 (/usr/lib64/libc.so.6)
>
> ping 623883 [006] 265438.471664: probe_libc:inet_pton: (7f32bcf314c0)
> 1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
> fa6c6 getaddrinfo+0x126 (/usr/lib64/libc.so.6)
> 491e [unknown] (/usr/bin/ping)
>
> The above is the temp file for the perf script output from the collected
> perf.data file See the second entry? Its as we expect:
>
> [root@quaco ~]# cat /tmp/expected.aT6
> ping[][0-9 \.:]+probe_libc:inet_pton: \([[:xdigit:]]+\)
> .*inet_pton\+0x[[:xdigit:]]+[[:space:]]\(/usr/lib64/libc.so.6|inlined\)$
> getaddrinfo\+0x[[:xdigit:]]+[[:space:]]\(/usr/lib64/libc.so.6\)$
> .*(\+0x[[:xdigit:]]+|\[unknown\])[[:space:]]\(.*/bin/ping.*\)$
> [root@quaco ~]#
>
> But if I just ignore that first one and match against the second event
> instance:
>
> [root@quaco ~]# perf test inet_pton
> 90: probe libc's inet_pton & backtrace it with ping : Ok
> [root@quaco ~]# perf test -v inet_pton
> 90: probe libc's inet_pton & backtrace it with ping :
> --- start ---
> test child forked, pid 626199
> ping 626222 [007] 266979.123047: probe_libc:inet_pton_1: (7f0650d314c0)
> 1314c0 __GI___inet_pton+0x0 (/usr/lib64/libc.so.6)
> fa6c6 getaddrinfo+0x126 (/usr/lib64/libc.so.6)
> 491e n (/usr/bin/ping)
> test child finished with 0
> ---- end ----
> probe libc's inet_pton & backtrace it with ping: Ok
> [root@quaco ~]#
>
> So, can you try with the following patch in your s/390 system?
Thanks Arnaldo,
your patch also works on my s390 system. I applied patch 1/2 which is
necessary and then your change:
# ./perf test 85
85: probe libc's inet_pton & backtrace it with ping : FAILED!
# git am your-patch
# ./perf test 85
85: probe libc's inet_pton & backtrace it with ping : Ok
#
So for patch 2/2 your have my
Tested-by: Thomas Richter <[email protected]>
>
> I wish 'perf script' had a --skip option that allowed us to ask for just
> the second event, not having that I did a trick with tac + grep -m1 -B :-)
>
> We can try to revisit your approach for the next merge window, as at
> this point, for 6.2 we want for fixes to be as minimal as possible.
>
Yes that would be good to make this test case more rebust.
--
Thomas Richter, Dept 3303, IBM s390 Linux Development, Boeblingen, Germany
--
Vorsitzender des Aufsichtsrats: Gregor Pillen
Geschäftsführung: David Faller
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294