* [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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.