2024-12-15 11:07:10 -08:00
|
|
|
#!/bin/bash
|
|
|
|
# perf trace BTF general tests
|
|
|
|
# SPDX-License-Identifier: GPL-2.0
|
|
|
|
|
|
|
|
err=0
|
|
|
|
|
2025-01-06 16:42:58 +00:00
|
|
|
# shellcheck source=lib/probe.sh
|
2024-12-15 11:07:10 -08:00
|
|
|
. "$(dirname $0)"/lib/probe.sh
|
|
|
|
|
|
|
|
file1=$(mktemp /tmp/file1_XXXX)
|
|
|
|
file2=$(echo $file1 | sed 's/file1/file2/g')
|
|
|
|
|
|
|
|
buffer="buffer content"
|
|
|
|
perf_config_tmp=$(mktemp /tmp/.perfconfig_XXXXX)
|
|
|
|
|
|
|
|
trap cleanup EXIT TERM INT HUP
|
|
|
|
|
|
|
|
check_vmlinux() {
|
|
|
|
echo "Checking if vmlinux BTF exists"
|
|
|
|
if [ ! -f /sys/kernel/btf/vmlinux ]
|
|
|
|
then
|
|
|
|
echo "Skipped due to missing vmlinux BTF"
|
|
|
|
return 2
|
|
|
|
fi
|
|
|
|
return 0
|
|
|
|
}
|
|
|
|
|
|
|
|
trace_test_string() {
|
|
|
|
echo "Testing perf trace's string augmentation"
|
perf test trace: Use --sort-events in BTF general tests
Without the '--sort-events' flag, perf trace doesn't receive and process
events based on their arrival time, thus PERF_RECORD_COMM event that
assigns the correct comm to a PID, may be delivered and processed after
regular samples, causing trace outputs not having a 'comm', e.g.
'mv', instead, having the default PID placeholder, e.g. ':14514'.
Hopefully this answers Namhyung's question in [1].
You can simply justify the statement with this diff: [2].
Now, simply run this command multiple times:
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
And you should see two types of results:
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
[debug] deliver
[debug] machine__process_comm_event
[OVERRIDE] old :1221169 new mv str mv
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
0.000 ( 0.013 ms): mv/1221169 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
[debug] deliver
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
0.000 ( 0.014 ms): :1221398/1221398 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
[debug] deliver
[debug] deliver
[debug] machine__process_comm_event
[OVERRIDE] old :1221398 new mv str mv
[debug] deliver
[debug] deliver
[debug] deliver
Anyway, use --sort-events in BTF general tests to avoid :PID, a comm is
preferred.
[1]: https://lore.kernel.org/linux-perf-users/Z_AeswETE5xLcPT8@google.com/
[2]: https://gist.githubusercontent.com/Sberm/6b72b2a1cf1c62244f1f996481769baf/raw/529667bd74a2e7e1953bbd4be545bf875da8a3e7/unsorted.patch
Signed-off-by: Howard Chu <howardchu95@gmail.com>
Tested-by: Namhyung Kim <namhyung@kernel.org>
Link: https://lore.kernel.org/r/20250528191148.89118-6-howardchu95@gmail.com
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
2025-05-28 12:11:47 -07:00
|
|
|
output="$(perf trace --sort-events -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
|
2025-05-28 12:11:46 -07:00
|
|
|
if ! echo "$output" | grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
|
2024-12-15 11:07:10 -08:00
|
|
|
then
|
2025-05-28 12:11:46 -07:00
|
|
|
printf "String augmentation test failed, output:\n$output\n"
|
2024-12-15 11:07:10 -08:00
|
|
|
err=1
|
|
|
|
fi
|
|
|
|
}
|
|
|
|
|
|
|
|
trace_test_buffer() {
|
|
|
|
echo "Testing perf trace's buffer augmentation"
|
|
|
|
# echo will insert a newline (\10) at the end of the buffer
|
perf test trace: Use --sort-events in BTF general tests
Without the '--sort-events' flag, perf trace doesn't receive and process
events based on their arrival time, thus PERF_RECORD_COMM event that
assigns the correct comm to a PID, may be delivered and processed after
regular samples, causing trace outputs not having a 'comm', e.g.
'mv', instead, having the default PID placeholder, e.g. ':14514'.
Hopefully this answers Namhyung's question in [1].
You can simply justify the statement with this diff: [2].
Now, simply run this command multiple times:
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
And you should see two types of results:
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
[debug] deliver
[debug] machine__process_comm_event
[OVERRIDE] old :1221169 new mv str mv
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
0.000 ( 0.013 ms): mv/1221169 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
[debug] deliver
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
0.000 ( 0.014 ms): :1221398/1221398 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
[debug] deliver
[debug] deliver
[debug] machine__process_comm_event
[OVERRIDE] old :1221398 new mv str mv
[debug] deliver
[debug] deliver
[debug] deliver
Anyway, use --sort-events in BTF general tests to avoid :PID, a comm is
preferred.
[1]: https://lore.kernel.org/linux-perf-users/Z_AeswETE5xLcPT8@google.com/
[2]: https://gist.githubusercontent.com/Sberm/6b72b2a1cf1c62244f1f996481769baf/raw/529667bd74a2e7e1953bbd4be545bf875da8a3e7/unsorted.patch
Signed-off-by: Howard Chu <howardchu95@gmail.com>
Tested-by: Namhyung Kim <namhyung@kernel.org>
Link: https://lore.kernel.org/r/20250528191148.89118-6-howardchu95@gmail.com
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
2025-05-28 12:11:47 -07:00
|
|
|
output="$(perf trace --sort-events -e write --max-events=1 -- echo "${buffer}" 2>&1)"
|
2025-05-28 12:11:46 -07:00
|
|
|
if ! echo "$output" | grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
|
2024-12-15 11:07:10 -08:00
|
|
|
then
|
2025-05-28 12:11:46 -07:00
|
|
|
printf "Buffer augmentation test failed, output:\n$output\n"
|
2024-12-15 11:07:10 -08:00
|
|
|
err=1
|
|
|
|
fi
|
|
|
|
}
|
|
|
|
|
|
|
|
trace_test_struct_btf() {
|
|
|
|
echo "Testing perf trace's struct augmentation"
|
perf test trace: Use --sort-events in BTF general tests
Without the '--sort-events' flag, perf trace doesn't receive and process
events based on their arrival time, thus PERF_RECORD_COMM event that
assigns the correct comm to a PID, may be delivered and processed after
regular samples, causing trace outputs not having a 'comm', e.g.
'mv', instead, having the default PID placeholder, e.g. ':14514'.
Hopefully this answers Namhyung's question in [1].
You can simply justify the statement with this diff: [2].
Now, simply run this command multiple times:
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
And you should see two types of results:
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
[debug] deliver
[debug] machine__process_comm_event
[OVERRIDE] old :1221169 new mv str mv
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
0.000 ( 0.013 ms): mv/1221169 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
[debug] deliver
$ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
[debug] deliver
0.000 ( 0.014 ms): :1221398/1221398 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
[debug] deliver
[debug] deliver
[debug] machine__process_comm_event
[OVERRIDE] old :1221398 new mv str mv
[debug] deliver
[debug] deliver
[debug] deliver
Anyway, use --sort-events in BTF general tests to avoid :PID, a comm is
preferred.
[1]: https://lore.kernel.org/linux-perf-users/Z_AeswETE5xLcPT8@google.com/
[2]: https://gist.githubusercontent.com/Sberm/6b72b2a1cf1c62244f1f996481769baf/raw/529667bd74a2e7e1953bbd4be545bf875da8a3e7/unsorted.patch
Signed-off-by: Howard Chu <howardchu95@gmail.com>
Tested-by: Namhyung Kim <namhyung@kernel.org>
Link: https://lore.kernel.org/r/20250528191148.89118-6-howardchu95@gmail.com
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
2025-05-28 12:11:47 -07:00
|
|
|
output="$(perf trace --sort-events -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
|
perf test trace: Change the regex pattern in the struct test
Ian mentioned a reliably occurred failure in the trace_btf_general test
where he obtained trace output of:
sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0
But the regex pattern used for verification is
"^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, ..."
This lead to a mismatch.
The reason is, different sleep commands use different timespec data to
call clock_nanosleep, on my machine, the value of tv_nsec is 0.
~~~
$ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
0.000 (1000.196 ms): sleep/54261 clock_nanosleep(rqtp: { .tv_sec:
1, .tv_nsec: 0 }, rmtp: 0x7ffe13529550) = 0
~~~
While Ian had this trace log:
~~~
$ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
0.000 (1000.208 ms): sleep/1710732 clock_nanosleep(rqtp: {
.tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7ffc091f4090) = 0
~~~
Because sleep's behavior of setting 'tv_nsec' is not certain, and tv_sec
is most definitely 1, this patch relaxes the key regex pattern to
'\{1,.*\}' for a better chance of matching.
Signed-off-by: Howard Chu <howardchu95@gmail.com>
Tested-by: Namhyung Kim <namhyung@kernel.org>
Link: https://lore.kernel.org/r/20250528191148.89118-7-howardchu95@gmail.com
Reported-by: Ian Rogers <irogers@google.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
2025-05-28 12:11:48 -07:00
|
|
|
if ! echo "$output" | grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,.*\}, 0x[0-9a-f]+\) += +[0-9]+$"
|
2024-12-15 11:07:10 -08:00
|
|
|
then
|
2025-05-28 12:11:46 -07:00
|
|
|
printf "BTF struct augmentation test failed, output:\n$output\n"
|
2024-12-15 11:07:10 -08:00
|
|
|
err=1
|
|
|
|
fi
|
|
|
|
}
|
|
|
|
|
|
|
|
cleanup() {
|
|
|
|
rm -rf ${file1} ${file2} ${perf_config_tmp}
|
|
|
|
}
|
|
|
|
|
|
|
|
trap_cleanup() {
|
|
|
|
echo "Unexpected signal in ${FUNCNAME[1]}"
|
|
|
|
cleanup
|
|
|
|
exit 1
|
|
|
|
}
|
|
|
|
|
|
|
|
# don't overwrite user's perf config
|
|
|
|
trace_config() {
|
|
|
|
export PERF_CONFIG=${perf_config_tmp}
|
|
|
|
perf config trace.show_arg_names=false trace.show_duration=false \
|
|
|
|
trace.show_timestamp=false trace.args_alignment=0
|
|
|
|
}
|
|
|
|
|
|
|
|
skip_if_no_perf_trace || exit 2
|
|
|
|
check_vmlinux || exit 2
|
2025-03-03 18:28:34 -08:00
|
|
|
[ "$(id -u)" = 0 ] || exit 2
|
2024-12-15 11:07:10 -08:00
|
|
|
|
|
|
|
trace_config
|
|
|
|
|
|
|
|
trace_test_string
|
|
|
|
|
|
|
|
if [ $err = 0 ]; then
|
|
|
|
trace_test_buffer
|
|
|
|
fi
|
|
|
|
|
|
|
|
if [ $err = 0 ]; then
|
|
|
|
trace_test_struct_btf
|
|
|
|
fi
|
|
|
|
|
|
|
|
cleanup
|
|
|
|
|
|
|
|
exit $err
|