[PATCH mptcp-next v3 0/3] display "last time" actions info

[PATCH mptcp-next v3 0/3] display "last time" actions info

[Geliang Tang]

From: Geliang Tang <tanggeliang@kylinos.cn>

v3:
 - address Matt's comments for patch 3 (thanks)
 - add "dport", "sleep", and mptcp_lib_expect_all_features.

v2:
 - address Mat's comments for v1 (thanks)
 - set msk->last_data_sent only if err > 0
 - set last_data_recv in __mptcp_move_skbs_from_subflow
 - add three reserved bytes after mptcpi_subflows_total
 - move selftests from mptcp_join.sh to diag.sh and check that the
timestamps move forward.

Closes: https://github.com/multipath-tcp/mptcp_net-next/issues/446

Geliang Tang (3):
  mptcp: add last time fields in mptcp_sock
  mptcp: add last time fields in mptcp_info
  selftests: mptcp: add last time actions tests

 include/uapi/linux/mptcp.h                |  4 ++++
 net/mptcp/options.c                       |  1 +
 net/mptcp/protocol.c                      |  7 ++++++
 net/mptcp/protocol.h                      |  3 +++
 net/mptcp/sockopt.c                       |  5 ++++
 tools/testing/selftests/net/mptcp/diag.sh | 29 +++++++++++++++++++++++
 6 files changed, 49 insertions(+)

-- 
2.40.1

[PATCH mptcp-next v3 1/3] mptcp: add last time fields in mptcp_sock

[Geliang Tang]

From: Geliang Tang <tanggeliang@kylinos.cn>

This patch adds "last time" fields last_data_sent, last_data_recv and
last_ack_recv in struct mptcp_sock to record the last time data_sent,
data_recv and ack_recv happened. They all are initialized as
tcp_jiffies32 in __mptcp_init_sock(), but updated as tcp_jiffies32 too
when data is sent in __subflow_push_pending(), data is received in
__mptcp_move_skbs_from_subflow(), and ack is received in ack_update_msk().

Signed-off-by: Geliang Tang <tanggeliang@kylinos.cn>
---
 net/mptcp/options.c  | 1 +
 net/mptcp/protocol.c | 7 +++++++
 net/mptcp/protocol.h | 3 +++
 3 files changed, 11 insertions(+)

diff --git a/net/mptcp/options.c b/net/mptcp/options.c
index 5926955625cf..c0832df3b0a3 100644
--- a/net/mptcp/options.c
+++ b/net/mptcp/options.c
@@ -1069,6 +1069,7 @@ static void ack_update_msk(struct mptcp_sock *msk,
 		__mptcp_snd_una_update(msk, new_snd_una);
 		__mptcp_data_acked(sk);
 	}
+	msk->last_ack_recv = tcp_jiffies32;
 	mptcp_data_unlock(sk);
 
 	trace_ack_update_msk(mp_opt->data_ack,
diff --git a/net/mptcp/protocol.c b/net/mptcp/protocol.c
index 556b3b95c537..43318aa5f991 100644
--- a/net/mptcp/protocol.c
+++ b/net/mptcp/protocol.c
@@ -706,6 +706,8 @@ static bool __mptcp_move_skbs_from_subflow(struct mptcp_sock *msk,
 		}
 	} while (more_data_avail);
 
+	if (moved > 0)
+		msk->last_data_recv = tcp_jiffies32;
 	*bytes += moved;
 	return done;
 }
@@ -1556,6 +1558,8 @@ static int __subflow_push_pending(struct sock *sk, struct sock *ssk,
 	err = copied;
 
 out:
+	if (err > 0)
+		msk->last_data_sent = tcp_jiffies32;
 	return err;
 }
 
@@ -2793,6 +2797,9 @@ static void __mptcp_init_sock(struct sock *sk)
 	WRITE_ONCE(msk->allow_infinite_fallback, true);
 	msk->recovery = false;
 	msk->subflow_id = 1;
+	msk->last_data_sent = tcp_jiffies32;
+	msk->last_data_recv = tcp_jiffies32;
+	msk->last_ack_recv = tcp_jiffies32;
 
 	mptcp_pm_data_init(msk);
 
diff --git a/net/mptcp/protocol.h b/net/mptcp/protocol.h
index 5a4538205fd6..3a3fed3642dd 100644
--- a/net/mptcp/protocol.h
+++ b/net/mptcp/protocol.h
@@ -282,6 +282,9 @@ struct mptcp_sock {
 	u64		bytes_acked;
 	u64		snd_una;
 	u64		wnd_end;
+	u32		last_data_sent;
+	u32		last_data_recv;
+	u32		last_ack_recv;
 	unsigned long	timer_ival;
 	u32		token;
 	int		rmem_released;
-- 
2.40.1

[PATCH mptcp-next v3 2/3] mptcp: add last time fields in mptcp_info

[Geliang Tang]

From: Geliang Tang <tanggeliang@kylinos.cn>

Similar to tcpi_last_data_sent, tcpi_last_data_recv and tcpi_last_ack_recv
exposed with TCP, this patch exposes the last time "an action happened" for
MPTCP in mptcp_info, named mptcpi_last_data_sent, mptcpi_last_data_recv and
mptcpi_last_ack_recv, calculated in mptcp_diag_fill_info() as the time
deltas between now and the newly added last time fields in mptcp_sock.

Also add three reserved bytes in struct mptcp_info.

Closes: https://github.com/multipath-tcp/mptcp_net-next/issues/446
Signed-off-by: Geliang Tang <tanggeliang@kylinos.cn>
---
 include/uapi/linux/mptcp.h | 4 ++++
 net/mptcp/sockopt.c        | 5 +++++
 2 files changed, 9 insertions(+)

diff --git a/include/uapi/linux/mptcp.h b/include/uapi/linux/mptcp.h
index 74cfe496891e..67d015df8893 100644
--- a/include/uapi/linux/mptcp.h
+++ b/include/uapi/linux/mptcp.h
@@ -58,6 +58,10 @@ struct mptcp_info {
 	__u64	mptcpi_bytes_received;
 	__u64	mptcpi_bytes_acked;
 	__u8	mptcpi_subflows_total;
+	__u8	reserved[3];
+	__u32	mptcpi_last_data_sent;
+	__u32	mptcpi_last_data_recv;
+	__u32	mptcpi_last_ack_recv;
 };
 
 /* MPTCP Reset reason codes, rfc8684 */
diff --git a/net/mptcp/sockopt.c b/net/mptcp/sockopt.c
index dcd1c76d2a3b..1e74851614e8 100644
--- a/net/mptcp/sockopt.c
+++ b/net/mptcp/sockopt.c
@@ -898,6 +898,7 @@ void mptcp_diag_fill_info(struct mptcp_sock *msk, struct mptcp_info *info)
 	struct sock *sk = (struct sock *)msk;
 	u32 flags = 0;
 	bool slow;
+	u32 now;
 
 	memset(info, 0, sizeof(*info));
 
@@ -942,6 +943,10 @@ void mptcp_diag_fill_info(struct mptcp_sock *msk, struct mptcp_info *info)
 	info->mptcpi_bytes_retrans = msk->bytes_retrans;
 	info->mptcpi_subflows_total = info->mptcpi_subflows +
 		__mptcp_has_initial_subflow(msk);
+	now = tcp_jiffies32;
+	info->mptcpi_last_data_sent = jiffies_to_msecs(now - msk->last_data_sent);
+	info->mptcpi_last_data_recv = jiffies_to_msecs(now - msk->last_data_recv);
+	info->mptcpi_last_ack_recv = jiffies_to_msecs(now - msk->last_ack_recv);
 	unlock_sock_fast(sk, slow);
 }
 EXPORT_SYMBOL_GPL(mptcp_diag_fill_info);
-- 
2.40.1

Re: [PATCH mptcp-next v3 2/3] mptcp: add last time fields in mptcp_info

[Mat Martineau]

On Sat, 30 Mar 2024, Geliang Tang wrote:

> From: Geliang Tang <tanggeliang@kylinos.cn>
>
> Similar to tcpi_last_data_sent, tcpi_last_data_recv and tcpi_last_ack_recv
> exposed with TCP, this patch exposes the last time "an action happened" for
> MPTCP in mptcp_info, named mptcpi_last_data_sent, mptcpi_last_data_recv and
> mptcpi_last_ack_recv, calculated in mptcp_diag_fill_info() as the time
> deltas between now and the newly added last time fields in mptcp_sock.
>
> Also add three reserved bytes in struct mptcp_info.
>
> Closes: https://github.com/multipath-tcp/mptcp_net-next/issues/446
> Signed-off-by: Geliang Tang <tanggeliang@kylinos.cn>
> ---
> include/uapi/linux/mptcp.h | 4 ++++
> net/mptcp/sockopt.c        | 5 +++++
> 2 files changed, 9 insertions(+)
>
> diff --git a/include/uapi/linux/mptcp.h b/include/uapi/linux/mptcp.h
> index 74cfe496891e..67d015df8893 100644
> --- a/include/uapi/linux/mptcp.h
> +++ b/include/uapi/linux/mptcp.h
> @@ -58,6 +58,10 @@ struct mptcp_info {
> 	__u64	mptcpi_bytes_received;
> 	__u64	mptcpi_bytes_acked;
> 	__u8	mptcpi_subflows_total;
> +	__u8	reserved[3];
> +	__u32	mptcpi_last_data_sent;
> +	__u32	mptcpi_last_data_recv;
> +	__u32	mptcpi_last_ack_recv;
> };
>
> /* MPTCP Reset reason codes, rfc8684 */
> diff --git a/net/mptcp/sockopt.c b/net/mptcp/sockopt.c
> index dcd1c76d2a3b..1e74851614e8 100644
> --- a/net/mptcp/sockopt.c
> +++ b/net/mptcp/sockopt.c
> @@ -898,6 +898,7 @@ void mptcp_diag_fill_info(struct mptcp_sock *msk, struct mptcp_info *info)
> 	struct sock *sk = (struct sock *)msk;
> 	u32 flags = 0;
> 	bool slow;
> +	u32 now;
>
> 	memset(info, 0, sizeof(*info));
>
> @@ -942,6 +943,10 @@ void mptcp_diag_fill_info(struct mptcp_sock *msk, struct mptcp_info *info)
> 	info->mptcpi_bytes_retrans = msk->bytes_retrans;
> 	info->mptcpi_subflows_total = info->mptcpi_subflows +
> 		__mptcp_has_initial_subflow(msk);
> +	now = tcp_jiffies32;
> +	info->mptcpi_last_data_sent = jiffies_to_msecs(now - msk->last_data_sent);
> +	info->mptcpi_last_data_recv = jiffies_to_msecs(now - msk->last_data_recv);
> +	info->mptcpi_last_ack_recv = jiffies_to_msecs(now - msk->last_ack_recv);

Hi Geliang -

msk->last_ack_recv is protected by mptcp_data_lock, not the msk socket 
lock, so this line should be moved to the data_lock protected section 
earlier in mptcp_diag_fill_info().

Thanks,

Mat

> 	unlock_sock_fast(sk, slow);
> }
> EXPORT_SYMBOL_GPL(mptcp_diag_fill_info);
> -- 
> 2.40.1
>
>
>

[PATCH mptcp-next v3 3/3] selftests: mptcp: add last time actions tests

[Geliang Tang]

From: Geliang Tang <tanggeliang@kylinos.cn>

This patch adds a new helper chk_msk_info() to show the counters in
mptcp_info of the given infos, and check that the timestamps move
forward. Use it to show newly added last_data_sent, last_data_recv
and last_ack_recv in mptcp_info in diag.sh.

Signed-off-by: Geliang Tang <tanggeliang@kylinos.cn>
---
 tools/testing/selftests/net/mptcp/diag.sh | 29 +++++++++++++++++++++++
 1 file changed, 29 insertions(+)

diff --git a/tools/testing/selftests/net/mptcp/diag.sh b/tools/testing/selftests/net/mptcp/diag.sh
index bc97ab33a00e..2f9f734015b4 100755
--- a/tools/testing/selftests/net/mptcp/diag.sh
+++ b/tools/testing/selftests/net/mptcp/diag.sh
@@ -200,6 +200,34 @@ chk_msk_cestab()
 		 "${expected}" "${msg}" ""
 }
 
+chk_msk_info()
+{
+	local port="${1}"
+	local info
+
+	for info in "${@:2}"; do
+		local cnt1 cnt2 msg
+
+		cnt1=$(ss -N ${ns} -inHM dport ${port} | mptcp_lib_get_info_value "$info" "$info")
+		sleep 0.5
+		cnt2=$(ss -N ${ns} -inHM dport ${port} | mptcp_lib_get_info_value "$info" "$info")
+		msg="....chk ${info}"
+		mptcp_lib_print_title "${msg}"
+		if { [ -z "${cnt1}" ] || [ -z "${cnt2}" ]; } &&
+		   ! mptcp_lib_expect_all_features; then
+			mptcp_lib_pr_skip "Feature probably not supported"
+			mptcp_lib_result_skip "${msg}"
+		elif [ "$((cnt1 + 500))" -lt "${cnt2}" ]; then
+			mptcp_lib_pr_ok
+			mptcp_lib_result_pass "${msg}"
+		else
+			mptcp_lib_pr_fail "expected $((cnt1 + 500)) < $cnt2"
+			mptcp_lib_result_fail "${msg}"
+			ret=${KSFT_FAIL}
+		fi
+	done
+}
+
 wait_connected()
 {
 	local listener_ns="${1}"
@@ -233,6 +261,7 @@ echo "b" | \
 				127.0.0.1 >/dev/null &
 wait_connected $ns 10000
 chk_msk_nr 2 "after MPC handshake "
+chk_msk_info 10000 last_data_sent last_data_recv last_ack_recv
 chk_msk_remote_key_nr 2 "....chk remote_key"
 chk_msk_fallback_nr 0 "....chk no fallback"
 chk_msk_inuse 2
-- 
2.40.1

Re: [PATCH mptcp-next v3 3/3] selftests: mptcp: add last time actions tests

[Mat Martineau]

On Sat, 30 Mar 2024, Geliang Tang wrote:

> From: Geliang Tang <tanggeliang@kylinos.cn>
>
> This patch adds a new helper chk_msk_info() to show the counters in
> mptcp_info of the given infos, and check that the timestamps move
> forward. Use it to show newly added last_data_sent, last_data_recv
> and last_ack_recv in mptcp_info in diag.sh.
>
> Signed-off-by: Geliang Tang <tanggeliang@kylinos.cn>
> ---
> tools/testing/selftests/net/mptcp/diag.sh | 29 +++++++++++++++++++++++
> 1 file changed, 29 insertions(+)
>
> diff --git a/tools/testing/selftests/net/mptcp/diag.sh b/tools/testing/selftests/net/mptcp/diag.sh
> index bc97ab33a00e..2f9f734015b4 100755
> --- a/tools/testing/selftests/net/mptcp/diag.sh
> +++ b/tools/testing/selftests/net/mptcp/diag.sh
> @@ -200,6 +200,34 @@ chk_msk_cestab()
> 		 "${expected}" "${msg}" ""
> }
>
> +chk_msk_info()
> +{
> +	local port="${1}"
> +	local info
> +
> +	for info in "${@:2}"; do
> +		local cnt1 cnt2 msg
> +
> +		cnt1=$(ss -N ${ns} -inHM dport ${port} | mptcp_lib_get_info_value "$info" "$info")
> +		sleep 0.5

Hi Geliang -

With the loop structured this way, it sleeps 3 times. You could collect 
the first timestamp for all three values (last_data_sent last_data_recv 
last_ack_recv), then sleep once, then get all 3 "after" timestamps.

(Unless Matthieu doesn't care about the extra test time :) )

> +		cnt2=$(ss -N ${ns} -inHM dport ${port} | mptcp_lib_get_info_value "$info" "$info")
> +		msg="....chk ${info}"
> +		mptcp_lib_print_title "${msg}"
> +		if { [ -z "${cnt1}" ] || [ -z "${cnt2}" ]; } &&
> +		   ! mptcp_lib_expect_all_features; then
> +			mptcp_lib_pr_skip "Feature probably not supported"
> +			mptcp_lib_result_skip "${msg}"
> +		elif [ "$((cnt1 + 500))" -lt "${cnt2}" ]; then

Using 500 here is likely to make this test flaky - Matthieu had suggested 
250ms as a way to make sure the value moved forward but would not be 
sensitive to small changes in packet timing.

Also please add a local "delta_ms" variable instead of the magic number 
500.

> +			mptcp_lib_pr_ok
> +			mptcp_lib_result_pass "${msg}"
> +		else
> +			mptcp_lib_pr_fail "expected $((cnt1 + 500)) < $cnt2"

Suggest rephrasing: "value of ${info} changed by $((cnt2 - cnt1))ms, 
expected at least ${delta_ms}ms"

- Mat

> +			mptcp_lib_result_fail "${msg}"
> +			ret=${KSFT_FAIL}
> +		fi
> +	done
> +}
> +
> wait_connected()
> {
> 	local listener_ns="${1}"
> @@ -233,6 +261,7 @@ echo "b" | \
> 				127.0.0.1 >/dev/null &
> wait_connected $ns 10000
> chk_msk_nr 2 "after MPC handshake "
> +chk_msk_info 10000 last_data_sent last_data_recv last_ack_recv
> chk_msk_remote_key_nr 2 "....chk remote_key"
> chk_msk_fallback_nr 0 "....chk no fallback"
> chk_msk_inuse 2
> -- 
> 2.40.1
>
>
>

Re: [PATCH mptcp-next v3 3/3] selftests: mptcp: add last time actions tests

[Matthieu Baerts]

Hi Mat,

On 01/04/2024 20:21, Mat Martineau wrote:
> On Sat, 30 Mar 2024, Geliang Tang wrote:
> 
>> From: Geliang Tang <tanggeliang@kylinos.cn>
>>
>> This patch adds a new helper chk_msk_info() to show the counters in
>> mptcp_info of the given infos, and check that the timestamps move
>> forward. Use it to show newly added last_data_sent, last_data_recv
>> and last_ack_recv in mptcp_info in diag.sh.
>>
>> Signed-off-by: Geliang Tang <tanggeliang@kylinos.cn>
>> ---
>> tools/testing/selftests/net/mptcp/diag.sh | 29 +++++++++++++++++++++++
>> 1 file changed, 29 insertions(+)
>>
>> diff --git a/tools/testing/selftests/net/mptcp/diag.sh b/tools/
>> testing/selftests/net/mptcp/diag.sh
>> index bc97ab33a00e..2f9f734015b4 100755
>> --- a/tools/testing/selftests/net/mptcp/diag.sh
>> +++ b/tools/testing/selftests/net/mptcp/diag.sh
>> @@ -200,6 +200,34 @@ chk_msk_cestab()
>>          "${expected}" "${msg}" ""
>> }
>>
>> +chk_msk_info()
>> +{
>> +    local port="${1}"
>> +    local info
>> +
>> +    for info in "${@:2}"; do
>> +        local cnt1 cnt2 msg
>> +
>> +        cnt1=$(ss -N ${ns} -inHM dport ${port} |
>> mptcp_lib_get_info_value "$info" "$info")
>> +        sleep 0.5
> 
> Hi Geliang -
> 
> With the loop structured this way, it sleeps 3 times. You could collect
> the first timestamp for all three values (last_data_sent last_data_recv
> last_ack_recv), then sleep once, then get all 3 "after" timestamps.
> 
> (Unless Matthieu doesn't care about the extra test time :) )

Good idea to have only one sleep!

Cheers,
Matt
-- 
Sponsored by the NGI0 Core fund.

Re: [PATCH mptcp-next v3 0/3] display "last time" actions info

[MPTCP CI]

Hi Geliang,

Thank you for your modifications, that's great!

Our CI did some validations and here is its report:

- KVM Validation: normal: Unstable: 1 failed test(s): selftest_diag 🔴
- KVM Validation: debug: Unstable: 1 failed test(s): selftest_diag 🔴
- KVM Validation: btf (only bpftest_all): Success! ✅
- Task: https://github.com/multipath-tcp/mptcp_net-next/actions/runs/8489380071

Initiator: Patchew Applier
Commits: https://github.com/multipath-tcp/mptcp_net-next/commits/104a535710cd
Patchwork: https://patchwork.kernel.org/project/mptcp/list/?series=839974


If there are some issues, you can reproduce them using the same environment as
the one used by the CI thanks to a docker image, e.g.:

    $ cd [kernel source code]
    $ docker run -v "${PWD}:${PWD}:rw" -w "${PWD}" --privileged --rm -it \
        --pull always mptcp/mptcp-upstream-virtme-docker:latest \
        auto-normal

For more details:

    https://github.com/multipath-tcp/mptcp-upstream-virtme-docker


Please note that despite all the efforts that have been already done to have a
stable tests suite when executed on a public CI like here, it is possible some
reported issues are not due to your modifications. Still, do not hesitate to
help us improve that ;-)

Cheers,
MPTCP GH Action bot
Bot operated by Matthieu Baerts (NGI0 Core)