Re: [PATCH] perf test: Add a new shell test for perf ftrace

[Arnaldo Carvalho de Melo <acme@kernel.org>]

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]"
 }