Patches here add 'time=<N>ms' in the diagnostic data of the TAP output, e.g.
ok 1 - pm_netlink: defaults addr list # time=9ms
This addition is useful to quickly identify which subtests are taking a longer time than the others, or more than expected.
Note that there are no specific formats to follow to show this time according to the TAP 13, TAP 14 and KTAP specifications, but we follow the format being parsed by NIPA [1].
Patch 1 modifies mptcp_lib.sh to add this support to all MPTCP selftests.
Patch 2 removes the now duplicated info in mptcp_connect.sh
Patch 3 slightly improves the precision of the first subtests in all MPTCP subtests.
Link: https://github.com/linux-netdev/nipa/pull/36 Signed-off-by: Matthieu Baerts (NGI0) matttbe@kernel.org --- Matthieu Baerts (NGI0) (3): selftests: mptcp: lib: add time per subtests in TAP output sefltests: mptcp: connect: remote time in TAP output selftests: mptcp: reset the last TS before the first test
tools/testing/selftests/net/mptcp/mptcp_connect.sh | 3 ++- tools/testing/selftests/net/mptcp/mptcp_join.sh | 3 ++- tools/testing/selftests/net/mptcp/mptcp_lib.sh | 17 ++++++++++++++++- tools/testing/selftests/net/mptcp/mptcp_sockopt.sh | 1 + tools/testing/selftests/net/mptcp/pm_netlink.sh | 2 ++ tools/testing/selftests/net/mptcp/simult_flows.sh | 1 + tools/testing/selftests/net/mptcp/userspace_pm.sh | 1 + 7 files changed, 25 insertions(+), 3 deletions(-) --- base-commit: 221f9cce949ac8042f65b71ed1fde13b99073256 change-id: 20240902-net-next-mptcp-ksft-subtest-time-a83cec43d894
Best regards,
It adds 'time=<N>ms' in the diagnostic data of the TAP output, e.g.
ok 1 - pm_netlink: defaults addr list # time=9ms
This addition is useful to quickly identify which subtests are taking a longer time than the others, or more than expected.
Note that there are no specific formats to follow to show this time according to the TAP 13 [1], TAP 14 [2] and KTAP [3] specifications. Let's then define this one here.
Link: https://testanything.org/tap-version-13-specification.html [1] Link: https://testanything.org/tap-version-14-specification.html [2] Link: https://docs.kernel.org/dev-tools/ktap.html [3] Reviewed-by: Mat Martineau martineau@kernel.org Signed-off-by: Matthieu Baerts (NGI0) matttbe@kernel.org --- tools/testing/selftests/net/mptcp/mptcp_lib.sh | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-)
diff --git a/tools/testing/selftests/net/mptcp/mptcp_lib.sh b/tools/testing/selftests/net/mptcp/mptcp_lib.sh index 4578a331041e..975d4d4c862a 100644 --- a/tools/testing/selftests/net/mptcp/mptcp_lib.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_lib.sh @@ -29,6 +29,7 @@ declare -rx MPTCP_LIB_AF_INET6=10 MPTCP_LIB_SUBTESTS=() MPTCP_LIB_SUBTESTS_DUPLICATED=0 MPTCP_LIB_SUBTEST_FLAKY=0 +MPTCP_LIB_SUBTESTS_LAST_TS_MS= MPTCP_LIB_TEST_COUNTER=0 MPTCP_LIB_TEST_FORMAT="%02u %-50s" MPTCP_LIB_IP_MPTCP=0 @@ -205,6 +206,11 @@ mptcp_lib_kversion_ge() { mptcp_lib_fail_if_expected_feature "kernel version ${1} lower than ${v}" }
+mptcp_lib_subtests_last_ts_reset() { + MPTCP_LIB_SUBTESTS_LAST_TS_MS="$(date +%s%3N)" +} +mptcp_lib_subtests_last_ts_reset + __mptcp_lib_result_check_duplicated() { local subtest
@@ -219,13 +225,22 @@ __mptcp_lib_result_check_duplicated() {
__mptcp_lib_result_add() { local result="${1}" + local time="time=" + local ts_prev_ms shift
local id=$((${#MPTCP_LIB_SUBTESTS[@]} + 1))
__mptcp_lib_result_check_duplicated "${*}"
- MPTCP_LIB_SUBTESTS+=("${result} ${id} - ${KSFT_TEST}: ${*}") + # not to add two '#' + [[ "${*}" != *"#"* ]] && time="# ${time}" + + ts_prev_ms="${MPTCP_LIB_SUBTESTS_LAST_TS_MS}" + mptcp_lib_subtests_last_ts_reset + time+="$((MPTCP_LIB_SUBTESTS_LAST_TS_MS - ts_prev_ms))ms" + + MPTCP_LIB_SUBTESTS+=("${result} ${id} - ${KSFT_TEST}: ${*} ${time}") }
# $1: test name
It is now added by the MPTCP lib automatically, see the parent commit.
The time in the TAP output might be sligly different from the one displayed before, but that's OK.
Reviewed-by: Mat Martineau martineau@kernel.org Signed-off-by: Matthieu Baerts (NGI0) matttbe@kernel.org --- tools/testing/selftests/net/mptcp/mptcp_connect.sh | 1 - 1 file changed, 1 deletion(-)
diff --git a/tools/testing/selftests/net/mptcp/mptcp_connect.sh b/tools/testing/selftests/net/mptcp/mptcp_connect.sh index b77fb7065bfb..f61e2f5870ea 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_connect.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_connect.sh @@ -431,7 +431,6 @@ do_transfer()
local duration duration=$((stop-start)) - result_msg+=" # time=${duration}ms" printf "(duration %05sms) " "${duration}" if [ ${rets} -ne 0 ] || [ ${retc} -ne 0 ]; then mptcp_lib_pr_fail "client exit code $retc, server $rets"
On Mon, 02 Sep 2024 13:13:05 +0200 Matthieu Baerts (NGI0) wrote:
Subject: [PATCH net-next 2/3] sefltests: mptcp: connect: remote time in TAP output
nit: typo in the subject
Just to slightly improve the precision of the duration of the first test.
In mptcp_join.sh, the last append_prev_results is now done as soon as the last test is over: this will add the last result in the list, and get a more precise time for this last test.
Reviewed-by: Mat Martineau martineau@kernel.org Signed-off-by: Matthieu Baerts (NGI0) matttbe@kernel.org --- tools/testing/selftests/net/mptcp/mptcp_connect.sh | 2 ++ tools/testing/selftests/net/mptcp/mptcp_join.sh | 3 ++- tools/testing/selftests/net/mptcp/mptcp_sockopt.sh | 1 + tools/testing/selftests/net/mptcp/pm_netlink.sh | 2 ++ tools/testing/selftests/net/mptcp/simult_flows.sh | 1 + tools/testing/selftests/net/mptcp/userspace_pm.sh | 1 + 6 files changed, 9 insertions(+), 1 deletion(-)
diff --git a/tools/testing/selftests/net/mptcp/mptcp_connect.sh b/tools/testing/selftests/net/mptcp/mptcp_connect.sh index f61e2f5870ea..49d90c4dbc01 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_connect.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_connect.sh @@ -847,6 +847,8 @@ stop_if_error() make_file "$cin" "client" make_file "$sin" "server"
+mptcp_lib_subtests_last_ts_reset + check_mptcp_disabled
stop_if_error "The kernel configuration is not valid for MPTCP" diff --git a/tools/testing/selftests/net/mptcp/mptcp_join.sh b/tools/testing/selftests/net/mptcp/mptcp_join.sh index a4762c49a878..c31387b74010 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_join.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_join.sh @@ -3883,9 +3883,11 @@ if [ ${#tests[@]} -eq 0 ]; then tests=("${all_tests_names[@]}") fi
+mptcp_lib_subtests_last_ts_reset for subtests in "${tests[@]}"; do "${subtests}" done +append_prev_results
if [ ${ret} -ne 0 ]; then echo @@ -3896,7 +3898,6 @@ if [ ${ret} -ne 0 ]; then echo fi
-append_prev_results mptcp_lib_result_print_all_tap
exit $ret diff --git a/tools/testing/selftests/net/mptcp/mptcp_sockopt.sh b/tools/testing/selftests/net/mptcp/mptcp_sockopt.sh index 68899a303a1a..5e8d5b83e2d0 100755 --- a/tools/testing/selftests/net/mptcp/mptcp_sockopt.sh +++ b/tools/testing/selftests/net/mptcp/mptcp_sockopt.sh @@ -349,6 +349,7 @@ init make_file "$cin" "client" 1 make_file "$sin" "server" 1 trap cleanup EXIT +mptcp_lib_subtests_last_ts_reset
run_tests $ns1 $ns2 10.0.1.1 run_tests $ns1 $ns2 dead:beef:1::1 diff --git a/tools/testing/selftests/net/mptcp/pm_netlink.sh b/tools/testing/selftests/net/mptcp/pm_netlink.sh index 2757378b1b13..2e6648a2b2c0 100755 --- a/tools/testing/selftests/net/mptcp/pm_netlink.sh +++ b/tools/testing/selftests/net/mptcp/pm_netlink.sh @@ -137,6 +137,8 @@ check() fi }
+mptcp_lib_subtests_last_ts_reset + check "show_endpoints" "" "defaults addr list"
default_limits="$(get_limits)" diff --git a/tools/testing/selftests/net/mptcp/simult_flows.sh b/tools/testing/selftests/net/mptcp/simult_flows.sh index f74e1c3c126d..8fa77c8e9b65 100755 --- a/tools/testing/selftests/net/mptcp/simult_flows.sh +++ b/tools/testing/selftests/net/mptcp/simult_flows.sh @@ -286,6 +286,7 @@ while getopts "bcdhi" option;do done
setup +mptcp_lib_subtests_last_ts_reset run_test 10 10 0 0 "balanced bwidth" run_test 10 10 1 25 "balanced bwidth with unbalanced delay"
diff --git a/tools/testing/selftests/net/mptcp/userspace_pm.sh b/tools/testing/selftests/net/mptcp/userspace_pm.sh index 9cb05978269d..3651f73451cf 100755 --- a/tools/testing/selftests/net/mptcp/userspace_pm.sh +++ b/tools/testing/selftests/net/mptcp/userspace_pm.sh @@ -150,6 +150,7 @@ mptcp_lib_events "${ns2}" "${client_evts}" client_evts_pid server_evts=$(mktemp) mptcp_lib_events "${ns1}" "${server_evts}" server_evts_pid sleep 0.5 +mptcp_lib_subtests_last_ts_reset
print_title "Init" print_test "Created network namespaces ns1, ns2"
On Mon, 02 Sep 2024 13:13:03 +0200 Matthieu Baerts (NGI0) wrote:
Patches here add 'time=<N>ms' in the diagnostic data of the TAP output, e.g.
ok 1 - pm_netlink: defaults addr list # time=9ms
Looking closer, this:
# ok 3 - mptcp[...] MPTCP # time=7184ms # ok 4 - mptcp[...] TCP # time=6458ms
Makes NIPA unhappy. The match results for regexps look like this:
(None, '4', ' -', 'mptcp[...] MPTCP', ' # ', 'time=6173ms') (None, '4', ' -', 'mptcp[...] TC', None, 'P # time=6173ms')
IOW the first one is neat, second one gepooped. The regex really wants there to be no more than a single space before the #. KTAP definition doesn't say that description must not have trailing white space.
Best I could come up with is:
diff --git a/contest/remote/vmksft-p.py b/contest/remote/vmksft-p.py index fe9e87abdb5c..a37245bd5b30 100755 --- a/contest/remote/vmksft-p.py +++ b/contest/remote/vmksft-p.py @@ -73,7 +73,7 @@ group3 testV skip tests = [] nested_tests = False
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( # )?([^ ].*)?$") + result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( +# )?([^ ].*)?$") time_re = re.compile(r"time=(\d+)ms")
for line in full_run.split('\n'):
Thoughts?
On Tue, 3 Sep 2024 16:22:17 -0700 Jakub Kicinski wrote:
(None, '4', ' -', 'mptcp[...] MPTCP', ' # ', 'time=6173ms') (None, '4', ' -', 'mptcp[...] TC', None, 'P # time=6173ms')
Sorry I fumbled copy/pasting the results, ignore the exact time values in the last group, but the mis-parsing stands.
Hi Jakub,
On 04/09/2024 01:22, Jakub Kicinski wrote:
On Mon, 02 Sep 2024 13:13:03 +0200 Matthieu Baerts (NGI0) wrote:
Patches here add 'time=<N>ms' in the diagnostic data of the TAP output, e.g.
ok 1 - pm_netlink: defaults addr list # time=9ms
Looking closer, this:
# ok 3 - mptcp[...] MPTCP # time=7184ms # ok 4 - mptcp[...] TCP # time=6458ms
Makes NIPA unhappy. The match results for regexps look like this:
(None, '4', ' -', 'mptcp[...] MPTCP', ' # ', 'time=6173ms') (None, '4', ' -', 'mptcp[...] TC', None, 'P # time=6173ms')
IOW the first one is neat, second one gepooped. The regex really wants there to be no more than a single space before the #.
Good catch!
KTAP definition doesn't say that description must not have trailing white space.
Indeed. Same for TAP 13. (TAP 14 is clearer about that and allows multiple spaces)
Best I could come up with is:
diff --git a/contest/remote/vmksft-p.py b/contest/remote/vmksft-p.py index fe9e87abdb5c..a37245bd5b30 100755 --- a/contest/remote/vmksft-p.py +++ b/contest/remote/vmksft-p.py @@ -73,7 +73,7 @@ group3 testV skip tests = [] nested_tests = False
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( # )?([^ ].*)?$")
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( +# )?([^ ].*)?$")
Looks good to me. While at it, we can add a '+' for the spaces after the '#':
( +# +)
I see you didn't commit the previous modification. I can open a PR if it helps.
time_re = re.compile(r"time=(\d+)ms")for line in full_run.split('\n'):
Thoughts?
In my v2, I will also strip these trailing whitespaces in the selftests, they don't need to be there.
Cheers, Matt
On Wed, 4 Sep 2024 18:15:09 +0200 Matthieu Baerts wrote:
Best I could come up with is:
diff --git a/contest/remote/vmksft-p.py b/contest/remote/vmksft-p.py index fe9e87abdb5c..a37245bd5b30 100755 --- a/contest/remote/vmksft-p.py +++ b/contest/remote/vmksft-p.py @@ -73,7 +73,7 @@ group3 testV skip tests = [] nested_tests = False
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( # )?([^ ].*)?$")
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( +# )?([^ ].*)?$")
Looks good to me. While at it, we can add a '+' for the spaces after the '#':
( +# +)
👍️
I see you didn't commit the previous modification. I can open a PR if it helps.
I was just playing with the regexps in the interpreter. If you could send a PR that'd perfect.
time_re = re.compile(r"time=(\d+)ms")for line in full_run.split('\n'):
Thoughts?
In my v2, I will also strip these trailing whitespaces in the selftests, they don't need to be there.
Up to you - it doesn't violate the KTAP format and the visual alignment is nice. But it may trip up more regexps..
Hi Jakub,
Thank you for your reply!
On 04/09/2024 21:40, Jakub Kicinski wrote:
On Wed, 4 Sep 2024 18:15:09 +0200 Matthieu Baerts wrote:
Best I could come up with is:
diff --git a/contest/remote/vmksft-p.py b/contest/remote/vmksft-p.py index fe9e87abdb5c..a37245bd5b30 100755 --- a/contest/remote/vmksft-p.py +++ b/contest/remote/vmksft-p.py @@ -73,7 +73,7 @@ group3 testV skip tests = [] nested_tests = False
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( # )?([^ ].*)?$")
- result_re = re.compile(r"(not )?ok (\d+)( -)? ([^#]*[^ ])( +# )?([^ ].*)?$")
Looks good to me. While at it, we can add a '+' for the spaces after the '#':
( +# +)
👍️
I see you didn't commit the previous modification. I can open a PR if it helps.
I was just playing with the regexps in the interpreter. If you could send a PR that'd perfect.
Sure, done:
https://github.com/linux-netdev/nipa/pull/38
time_re = re.compile(r"time=(\d+)ms")for line in full_run.split('\n'):
Thoughts?
In my v2, I will also strip these trailing whitespaces in the selftests, they don't need to be there.
Up to you - it doesn't violate the KTAP format and the visual alignment is nice. But it may trip up more regexps..
Yes, better be safe... I will keep the visual alignment for the non-TAP output.
Cheers, Matt
linux-kselftest-mirror@lists.linaro.org
-
Jakub Kicinski -
Matthieu Baerts -
Matthieu Baerts (NGI0)