Re: [PATCH] perf test: Add a new shell test for perf ftrace
From: Arnaldo Carvalho de Melo
Date: Thu Aug 08 2024 - 09:01:35 EST
On Wed, Aug 07, 2024 at 09:49:54PM -0700, Namhyung Kim wrote:
> $ sudo ./perf test ftrace -vv
> 86: perf ftrace tests:
> --- start ---
> test child forked, pid 1772223
> perf ftrace list test
> syscalls for sleep:
> __x64_sys_nanosleep
> __ia32_sys_nanosleep
> __x64_sys_clock_nanosleep
> __ia32_sys_clock_nanosleep
> perf ftrace list test [Success]
> perf ftrace trace test
> # tracer: function_graph
> #
> # CPU DURATION FUNCTION CALLS
> # | | | | | | |
> 0) | __x64_sys_clock_nanosleep() {
> 0) | common_nsleep() {
> 0) | hrtimer_nanosleep() {
> 0) | do_nanosleep() {
> perf ftrace trace test [Success]
> perf ftrace latency test
> target function: __x64_sys_clock_nanosleep
> # DURATION | COUNT | GRAPH |
> 32 - 64 ms | 1 | ############################################## |
> perf ftrace latency test [Success]
> perf ftrace profile test
> # Total (us) Avg (us) Max (us) Count Function
> 100136.400 100136.400 100136.400 1 __x64_sys_clock_nanosleep
> 100135.200 100135.200 100135.200 1 common_nsleep
> 100134.700 100134.700 100134.700 1 hrtimer_nanosleep
> 100133.700 100133.700 100133.700 1 do_nanosleep
> 100130.600 100130.600 100130.600 1 schedule
> 166.868 55.623 80.299 3 scheduler_tick
> 5.926 5.926 5.926 1 native_smp_send_reschedule
> 301.941 301.941 301.941 1 __x64_sys_execve
> 295.786 295.786 295.786 1 do_execveat_common.isra.0
> 71.397 35.699 46.403 2 bprm_execve
> 2.519 1.260 1.547 2 sched_mm_cid_before_execve
> 1.098 0.549 0.686 2 sched_mm_cid_after_execve
> perf ftrace profile test [Success]
> ---- end(0) ----
> 86: perf ftrace tests : Ok
>
> Signed-off-by: Namhyung Kim <namhyung@xxxxxxxxxx>
> ---
> tools/perf/tests/shell/ftrace.sh | 84 ++++++++++++++++++++++++++++++++
> 1 file changed, 84 insertions(+)
> create mode 100755 tools/perf/tests/shell/ftrace.sh
>
> diff --git a/tools/perf/tests/shell/ftrace.sh b/tools/perf/tests/shell/ftrace.sh
> new file mode 100755
> index 000000000000..b1c36d30559a
> --- /dev/null
> +++ b/tools/perf/tests/shell/ftrace.sh
> @@ -0,0 +1,84 @@
> +#!/bin/sh
> +# perf ftrace tests
> +# SPDX-License-Identifier: GPL-2.0
> +
> +set -e
> +
> +# perf ftrace commands only works for root
> +if [ "$(id -u)" != 0 ]; then
> + echo "perf ftrace test [Skipped: no permission]"
> + exit 2
> +fi
> +
> +output=$(mktemp /tmp/__perf_test.ftrace.XXXXXX)
> +
> +cleanup() {
> + rm -f "${output}"
> +
> + trap - EXIT TERM INT
> +}
> +
> +trap_cleanup() {
> + cleanup
> + exit 1
> +}
> +trap trap_cleanup EXIT TERM INT
> +
> +# this will be set in test_ftrace_trace()
> +target_function=
> +
> +test_ftrace_list() {
> + echo "perf ftrace list test"
> + perf ftrace -F > "${output}"
> + # this will be used in test_ftrace_trace()
> + sleep_functions=$(grep 'sys_.*sleep$' "${output}")
> + echo "syscalls for sleep:"
> + echo "${sleep_functions}"
> + echo "perf ftrace list test [Success]"
> +}
> +
> +test_ftrace_trace() {
> + echo "perf ftrace trace test"
> + perf ftrace trace --graph-opts depth=5 sleep 0.1 > "${output}"
> + # it should have some function name contains 'sleep'
> + grep "^#" "${output}"
> + grep -F 'sleep()' "${output}"
> + # find actual syscall function name
> + for FN in ${sleep_functions}; do
> + if grep -q "${FN}" "${output}"; then
> + target_function="${FN}"
> + echo "perf ftrace trace test [Success]"
> + return
> + fi
> + done
> +
> + echo "perf ftrace trace test [Failure: sleep syscall not found]"
> + exit 1
> +}
> +
> +test_ftrace_latency() {
> + echo "perf ftrace latency test"
> + echo "target function: ${target_function}"
> + perf ftrace latency -T "${target_function}" sleep 0.1 > "${output}"
> + grep "^#" "${output}"
> + grep "###" "${output}"
> + echo "perf ftrace latency test [Success]"
> +}
> +
> +test_ftrace_profile() {
> + echo "perf ftrace profile test"
> + perf ftrace profile sleep 0.1 > "${output}"
> + grep ^# "${output}"
> + grep sleep "${output}"
> + grep schedule "${output}"
> + grep execve "${output}"
> + echo "perf ftrace profile test [Success]"
> +}
I think this will cover the problem I reported to you, i.e. strange
times:
root@x1:~# perf ftrace profile sleep 1s > a
root@x1:~# time_re="[[:space:]]+100[[:digit:]]{4}\.[[:digit:]]{3}"
root@x1:~# grep -E "^${time_re}${time_re}${time_re}[[:space:]]+1[[:space:]]+.*clock_nanosleep" a
1000171.000 1000171.000 1000171.000 1 __x64_sys_clock_nanosleep
root@x1:~#
I.e. we know that we will have just one call to *clock_nanosleep and
that it will take a bit more than 1 second (100 followed by 4 digits to
get to something like 1000171).
So I cooked up the following patch, on top of yours, I tested it
replacing the '10' in the time_re with 20 and it fails, with '10', as
expected, it passes.
- Arnaldo
diff --git a/tools/perf/tests/shell/ftrace.sh b/tools/perf/tests/shell/ftrace.sh
index b1c36d30559a900a..a6ee740f0d7eca07 100755
--- a/tools/perf/tests/shell/ftrace.sh
+++ b/tools/perf/tests/shell/ftrace.sh
@@ -72,6 +72,11 @@ test_ftrace_profile() {
grep sleep "${output}"
grep schedule "${output}"
grep execve "${output}"
+ time_re="[[:space:]]+10[[:digit:]]{4}\.[[:digit:]]{3}"
+ # 100283.000 100283.000 100283.000 1 __x64_sys_clock_nanosleep
+ # Check for one *clock_nanosleep line with a Count of just 1 that takes a bit more than 0.1 seconds
+ # Strip the _x64_sys part to work with other architectures
+ grep -E "^${time_re}${time_re}${time_re}[[:space:]]+1[[:space:]]+.*clock_nanosleep" "${output}"
echo "perf ftrace profile test [Success]"
}