perf tests: Switch trace+probe_libc_inet_pton to use record
Jiri Olsa
reviewerPATCH 1/2 perf tests: Switch trace+probe_libc_inet_pton to use record
There's a problem with relying on backtrace data from perf trace the way the trace+probe_libc_inet_pton does. This test inserts uprobe within ping binary and checks that it gets its sample using perf trace.
It also checks it gets proper backtrace from sample and that's where the issue is.
The perf trace does not sort events (by definition) so it can happen that it processes the event sample before the ping binary memory map event. This can (very rarely) happen as proved by this events dump output (from custom added debug output):
...
7680/7680: [0x7f4e29718000(0x204000) @ 0 fd:00 33611321 4230892504]: r-xp /usr/lib64/libdl-2.17.so 7680/7680: [0x7f4e29502000(0x216000) @ 0 fd:00 33617257 2606846872]: r-xp /usr/lib64/libz.so.1.2.7 (IP, 0x2): 7680/7680: 0x7f4e29c2ed60 period: 1 addr: 0
7680/7680: [0x564842ef0000(0x233000) @ 0 fd:00 83 1989280200]: r-xp /usr/bin/ping 7680/7680: [0x7f4e2aca2000(0x224000) @ 0 fd:00 33611308 1219144940]: r-xp /usr/lib64/ld-2.17.so
...
In this case perf trace fails to resolve the last callchain IP (within the ping binary) because it does not know about the ping binary memory map yet and the test fails like this:
PING ::1(::1) 56 data bytes
64 bytes from ::1: icmp_seq=1 ttl=64 time=0.037 ms
--- ::1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.037/0.037/0.037/0.000 ms
0.000 probe_libc:inet_pton:(7f4e29c2ed60))
__GI___inet_pton (/usr/lib64/libc-2.17.so)
getaddrinfo (/usr/lib64/libc-2.17.so)
[0] ([unknown])
FAIL: expected backtrace entry 8 ".*\(.*/bin/ping.*\)$" got "[0] ([unknown])"
Switching the test to use perf record and perf script instead of perf trace.
--- .../perf/tests/shell/trace+probe_libc_inet_pton.sh | 30 +++++++++++----------- 1 file changed, 15 insertions(+), 15 deletions(-)
tools/perf/tests/shell/trace+probe_libc_inet_pton.sh +15 -15
@@ -15,30 +15,28 @@ nm -g $libc 2>/dev/null | fgrep -q inet_pton || exit 254 trace_libc_inet_pton_backtrace() { idx=0 - expected[0]="PING.*bytes" - expected[1]="64 bytes from ::1.*" - expected[2]=".*ping statistics.*" - expected[3]=".*packets transmitted.*" - expected[4]="rtt min.*" - expected[5]="[0-9]+\.[0-9]+[[:space:]]+probe_libc:inet_pton:\([[:xdigit:]]+\)" - expected[6]=".*inet_pton[[:space:]]\($libc|inlined\)$" + expected[0]="ping[][0-9 \.:]+probe_libc:inet_pton: \([[:xdigit:]]+\)" + expected[1]=".*inet_pton[[:space:]]\($libc\)$" case "$(uname -m)" in s390x) eventattr='call-graph=dwarf' - expected[7]="gaih_inet.*[[:space:]]\($libc|inlined\)$" - expected[8]="__GI_getaddrinfo[[:space:]]\($libc|inlined\)$" - expected[9]="main[[:space:]]\(.*/bin/ping.*\)$" - expected[10]="__libc_start_main[[:space:]]\($libc\)$" - expected[11]="_start[[:space:]]\(.*/bin/ping.*\)$" + expected[2]="gaih_inet.*[[:space:]]\($libc|inlined\)$" + expected[3]="__GI_getaddrinfo[[:space:]]\($libc|inlined\)$" + expected[4]="main[[:space:]]\(.*/bin/ping.*\)$" + expected[5]="__libc_start_main[[:space:]]\($libc\)$" + expected[6]="_start[[:space:]]\(.*/bin/ping.*\)$" ;; *) eventattr='max-stack=3' - expected[7]="getaddrinfo[[:space:]]\($libc\)$" - expected[8]=".*\(.*/bin/ping.*\)$" + expected[2]="getaddrinfo[[:space:]]\($libc\)$" + expected[3]=".*\(.*/bin/ping.*\)$" ;; esac - perf trace --no-syscalls -e probe_libc:inet_pton/$eventattr/ ping -6 -c 1 ::1 2>&1 | grep -v ^$ | while read line ; do + file=`mktemp -u /tmp/perf.data.XXX` + + perf record -e probe_libc:inet_pton/$eventattr/ -o $file ping -6 -c 1 ::1 > /dev/null 2>&1 + perf script -i $file | while read line ; do echo $line echo "$line" | egrep -q "${expected[$idx]}" if [ $? -ne 0 ] ; then
@@ -48,6 +46,8 @@ trace_libc_inet_pton_backtrace() { let idx+=1 [ -z "${expected[$idx]}" ] && break done + + rm -f $file } # Check for IPv6 interface existence
Signature · 1 line
2.13.6
Jiri Olsa
reviewerPATCH 2/2 perf tests: Rename trace+probe_libc_inet_pton to record+probe_libc_inet_pton
Because the test is no longer using perf trace but perf record instead.
--- .../tests/shell/record+probe_libc_inet_pton.sh | 62 ++++++++++++++++++++++ .../perf/tests/shell/trace+probe_libc_inet_pton.sh | 62 ---------------------- 2 files changed, 62 insertions(+), 62 deletions(-) create mode 100755 tools/perf/tests/shell/record+probe_libc_inet_pton.sh delete mode 100755 tools/perf/tests/shell/trace+probe_libc_inet_pton.sh
tools/perf/tests/shell/record+probe_libc_inet_pton.sh new file +62 -0
@@ -0,0 +1,62 @@ +# probe libc's inet_pton & backtrace it with ping + +# Installs a probe on libc's inet_pton function, that will use uprobes, +# then use 'perf trace' on a ping to localhost asking for just one packet +# with the a backtrace 3 levels deep, check that it is what we expect. +# This needs no debuginfo package, all is done using the libc ELF symtab +# and the CFI info in the binaries. + +# Arnaldo Carvalho de Melo <[email protected]>, 2017 + +. $(dirname $0)/lib/probe.sh + +libc=$(grep -w libc /proc/self/maps | head -1 | sed -r 's/.*[[:space:]](\/.*)/\1/g') +nm -g $libc 2>/dev/null | fgrep -q inet_pton || exit 254 + +trace_libc_inet_pton_backtrace() { + idx=0 + expected[0]="ping[][0-9 \.:]+probe_libc:inet_pton: \([[:xdigit:]]+\)" + expected[1]=".*inet_pton[[:space:]]\($libc\)$" + case "$(uname -m)" in + s390x) + eventattr='call-graph=dwarf' + expected[2]="gaih_inet.*[[:space:]]\($libc|inlined\)$" + expected[3]="__GI_getaddrinfo[[:space:]]\($libc|inlined\)$" + expected[4]="main[[:space:]]\(.*/bin/ping.*\)$" + expected[5]="__libc_start_main[[:space:]]\($libc\)$" + expected[6]="_start[[:space:]]\(.*/bin/ping.*\)$" + ;; + *) + eventattr='max-stack=3' + expected[2]="getaddrinfo[[:space:]]\($libc\)$" + expected[3]=".*\(.*/bin/ping.*\)$" + ;; + esac + + file=`mktemp -u /tmp/perf.data.XXX` + + perf record -e probe_libc:inet_pton/$eventattr/ -o $file ping -6 -c 1 ::1 > /dev/null 2>&1 + perf script -i $file | while read line ; do + echo $line + echo "$line" | egrep -q "${expected[$idx]}" + if [ $? -ne 0 ] ; then + printf "FAIL: expected backtrace entry %d \"%s\" got \"%s\"\n" $idx "${expected[$idx]}" "$line" + exit 1 + fi + let idx+=1 + [ -z "${expected[$idx]}" ] && break + done + + rm -f $file +} + +# Check for IPv6 interface existence +ip a sh lo | fgrep -q inet6 || exit 2 + +skip_if_no_perf_probe && \ +perf probe -q $libc inet_pton && \ +trace_libc_inet_pton_backtrace +err=$? +rm -f ${file} +perf probe -q -d probe_libc:inet_pton +exit $err
tools/perf/tests/shell/trace+probe_libc_inet_pton.sh deleted +0 -62
62 lines not on this page · raw message
Signature · 1 line
2.13.6
tip-bot for Jiri Olsa
merge bot[tip:perf/core] perf tests: Rename trace+probe_libc_inet_pton to record+probe_libc_inet_pton
perf tests: Rename trace+probe_libc_inet_pton to record+probe_libc_inet_pton
Commit-ID: 4f67336870f641daa485ea504777486e24a9aece Gitweb: https://git.kernel.org/tip/4f67336870f641daa485ea504777486e24a9aece Author: Jiri Olsa <[email protected]> AuthorDate: Thu, 1 Mar 2018 17:52:15 +0100 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Mon, 5 Mar 2018 09:58:42 -0300
perf tests: Rename trace+probe_libc_inet_pton to record+probe_libc_inet_pton
Because the test is no longer using perf trace but perf record instead.
---
.../{trace+probe_libc_inet_pton.sh => record+probe_libc_inet_pton.sh} | 0
1 file changed, 0 insertions(+), 0 deletions(-)tools/perf/tests/shell/record+probe_libc_inet_pton.sh renamed from tools/perf/tests/shell/trace+probe_libc_inet_pton.sh +0 -0
tip-bot for Jiri Olsa
merge botperf tests: Switch trace+probe_libc_inet_pton to use record
Commit-ID: a18ee796f8af5569628c324700b9a34b88884488 Gitweb: https://git.kernel.org/tip/a18ee796f8af5569628c324700b9a34b88884488 Author: Jiri Olsa <[email protected]> AuthorDate: Thu, 1 Mar 2018 17:52:14 +0100 Committer: Arnaldo Carvalho de Melo <[email protected]> CommitDate: Mon, 5 Mar 2018 09:58:42 -0300
perf tests: Switch trace+probe_libc_inet_pton to use record
There's a problem with relying on backtrace data from 'perf trace' the way the trace+probe_libc_inet_pton does. This test inserts uprobe within ping binary and checks that it gets its sample using 'perf trace'.
It also checks it gets proper backtrace from sample and that's where the issue is.
The 'perf trace' does not sort events (by definition) so it can happen that it processes the event sample before the ping binary memory map event. This can (very rarely) happen as proved by this events dump output (from custom added debug output):
...
7680/7680: [0x7f4e29718000(0x204000) @ 0 fd:00 33611321 4230892504]: r-xp /usr/lib64/libdl-2.17.so 7680/7680: [0x7f4e29502000(0x216000) @ 0 fd:00 33617257 2606846872]: r-xp /usr/lib64/libz.so.1.2.7 (IP, 0x2): 7680/7680: 0x7f4e29c2ed60 period: 1 addr: 0
7680/7680: [0x564842ef0000(0x233000) @ 0 fd:00 83 1989280200]: r-xp /usr/bin/ping 7680/7680: [0x7f4e2aca2000(0x224000) @ 0 fd:00 33611308 1219144940]: r-xp /usr/lib64/ld-2.17.so
...
In this case 'perf trace' fails to resolve the last callchain IP (within the ping binary) because it does not know about the ping binary memory map yet and the test fails like this:
PING ::1(::1) 56 data bytes
64 bytes from ::1: icmp_seq=1 ttl=64 time=0.037 ms
--- ::1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.037/0.037/0.037/0.000 ms
0.000 probe_libc:inet_pton:(7f4e29c2ed60))
__GI___inet_pton (/usr/lib64/libc-2.17.so)
getaddrinfo (/usr/lib64/libc-2.17.so)
[0] ([unknown])
FAIL: expected backtrace entry 8 ".*\(.*/bin/ping.*\)$" got "[0] ([unknown])"
Switching the test to use 'perf record' and 'perf script' instead of 'perf trace'.
--- .../perf/tests/shell/trace+probe_libc_inet_pton.sh | 30 +++++++++++----------- 1 file changed, 15 insertions(+), 15 deletions(-)
tools/perf/tests/shell/trace+probe_libc_inet_pton.sh +15 -15
@@ -15,30 +15,28 @@ nm -g $libc 2>/dev/null | fgrep -q inet_pton || exit 254 trace_libc_inet_pton_backtrace() { idx=0 - expected[0]="PING.*bytes" - expected[1]="64 bytes from ::1.*" - expected[2]=".*ping statistics.*" - expected[3]=".*packets transmitted.*" - expected[4]="rtt min.*" - expected[5]="[0-9]+\.[0-9]+[[:space:]]+probe_libc:inet_pton:\([[:xdigit:]]+\)" - expected[6]=".*inet_pton[[:space:]]\($libc|inlined\)$" + expected[0]="ping[][0-9 \.:]+probe_libc:inet_pton: \([[:xdigit:]]+\)" + expected[1]=".*inet_pton[[:space:]]\($libc\)$" case "$(uname -m)" in s390x) eventattr='call-graph=dwarf' - expected[7]="gaih_inet.*[[:space:]]\($libc|inlined\)$" - expected[8]="__GI_getaddrinfo[[:space:]]\($libc|inlined\)$" - expected[9]="main[[:space:]]\(.*/bin/ping.*\)$" - expected[10]="__libc_start_main[[:space:]]\($libc\)$" - expected[11]="_start[[:space:]]\(.*/bin/ping.*\)$" + expected[2]="gaih_inet.*[[:space:]]\($libc|inlined\)$" + expected[3]="__GI_getaddrinfo[[:space:]]\($libc|inlined\)$" + expected[4]="main[[:space:]]\(.*/bin/ping.*\)$" + expected[5]="__libc_start_main[[:space:]]\($libc\)$" + expected[6]="_start[[:space:]]\(.*/bin/ping.*\)$" ;; *) eventattr='max-stack=3' - expected[7]="getaddrinfo[[:space:]]\($libc\)$" - expected[8]=".*\(.*/bin/ping.*\)$" + expected[2]="getaddrinfo[[:space:]]\($libc\)$" + expected[3]=".*\(.*/bin/ping.*\)$" ;; esac - perf trace --no-syscalls -e probe_libc:inet_pton/$eventattr/ ping -6 -c 1 ::1 2>&1 | grep -v ^$ | while read line ; do + file=`mktemp -u /tmp/perf.data.XXX` + + perf record -e probe_libc:inet_pton/$eventattr/ -o $file ping -6 -c 1 ::1 > /dev/null 2>&1 + perf script -i $file | while read line ; do echo $line echo "$line" | egrep -q "${expected[$idx]}" if [ $? -ne 0 ] ; then
@@ -48,6 +46,8 @@ trace_libc_inet_pton_backtrace() { let idx+=1 [ -z "${expected[$idx]}" ] && break done + + rm -f $file } # Check for IPv6 interface existence