* [PATCH] perf test: Add a new shell test for perf ftrace
@ 2024-08-08 4:49 Namhyung Kim
2024-08-08 13:01 ` Arnaldo Carvalho de Melo
0 siblings, 1 reply; 2+ messages in thread
From: Namhyung Kim @ 2024-08-08 4:49 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Ian Rogers, Kan Liang
Cc: Jiri Olsa, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Steven Rostedt
$ 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@kernel.org>
---
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]"
+}
+
+test_ftrace_list
+test_ftrace_trace
+test_ftrace_latency
+test_ftrace_profile
+
+cleanup
+exit 0
--
2.46.0.rc2.264.g509ed76dc8-goog
^ permalink raw reply related [flat|nested] 2+ messages in thread* Re: [PATCH] perf test: Add a new shell test for perf ftrace
2024-08-08 4:49 [PATCH] perf test: Add a new shell test for perf ftrace Namhyung Kim
@ 2024-08-08 13:01 ` Arnaldo Carvalho de Melo
0 siblings, 0 replies; 2+ messages in thread
From: Arnaldo Carvalho de Melo @ 2024-08-08 13:01 UTC (permalink / raw)
To: Namhyung Kim
Cc: Ian Rogers, Kan Liang, Jiri Olsa, Adrian Hunter, Peter Zijlstra,
Ingo Molnar, LKML, linux-perf-users, Steven Rostedt
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@kernel.org>
> ---
> 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]"
}
^ permalink raw reply related [flat|nested] 2+ messages in thread
end of thread, other threads:[~2024-08-08 13:01 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-08-08 4:49 [PATCH] perf test: Add a new shell test for perf ftrace Namhyung Kim
2024-08-08 13:01 ` Arnaldo Carvalho de Melo
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox