Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
From:   Song Liu <songliubraving@fb.com>
To:     Yafang Shao <laoar.shao@gmail.com>
CC:     "eric.dumazet@gmail.com" <eric.dumazet@gmail.com>,
        "davem@davemloft.net" <davem@davemloft.net>,
        "kuznet@ms2.inr.ac.ru" <kuznet@ms2.inr.ac.ru>,
        "yoshfuji@linux-ipv6.org" <yoshfuji@linux-ipv6.org>,
        "netdev@vger.kernel.org" <netdev@vger.kernel.org>,
        "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH v2 net-next] net: introduce a new tracepoint for
 tcp_rcv_space_adjust
Thread-Topic: [PATCH v2 net-next] net: introduce a new tracepoint for
 tcp_rcv_space_adjust
Thread-Index: AQHT1mqJ9xgfIFuRz0WmbFf0D1CdOKQFOQAA
Date:   Tue, 17 Apr 2018 17:38:39 +0000
Message-ID: <A047B5AE-CA5F-4664-92F7-935E8ED4C0CA@fb.com>
References: <1523983016-11005-1-git-send-email-laoar.shao@gmail.com>
In-Reply-To: <1523983016-11005-1-git-send-email-laoar.shao@gmail.com>
Accept-Language: en-US
Content-Language: en-US
received-spf: None (protection.outlook.com: fb.com does not designate
 permitted sender hosts)
spamdiagnosticoutput: 1:99
spamdiagnosticmetadata: NSPM
Content-Type: text/plain; charset="us-ascii"
Content-ID: <4DEEA3228AE2C64187283981A4310806@namprd15.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: b565018c-0415-475c-d9bb-08d5a48a0e33
X-MS-Exchange-CrossTenant-originalarrivaltime: 17 Apr 2018 17:38:39.1951
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 8ae927fe-1255-47a7-a2af-5f3a069daaa2
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DM5PR15MB1642
X-OriginatorOrg: fb.com
X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:,, definitions=2018-04-17_09:,,
 signatures=0
X-Proofpoint-Spam-Reason: safe
X-FB-Internal: Safe
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org


> On Apr 17, 2018, at 9:36 AM, Yafang Shao <laoar.shao@gmail.com> wrote:
>=20
> tcp_rcv_space_adjust is called every time data is copied to user space,
> introducing a tcp tracepoint for which could show us when the packet is
> copied to user.
> This could help us figure out whether there's latency in user process.
>=20
> When a tcp packet arrives, tcp_rcv_established() will be called and with
> the existed tracepoint tcp_probe we could get the time when this packet
> arrives.
> Then this packet will be copied to user, and tcp_rcv_space_adjust will
> be called and with this new introduced tracepoint we could get the time
> when this packet is copied to user.
>=20
>        arrives time : user process time    =3D> latency caused by user
>        tcp_probe      tcp_rcv_space_adjust
>=20
> Hence in the printk message, sk_cookie is printed as a key to relate
> tcp_rcv_space_adjust with tcp_probe.
>=20
> Maybe we could export sockfd in this new tracepoint as well, then we
> could relate this new tracepoint with epoll/read/recv* tracepoints, and
> finally that could show us the whole lifespan of this packet. But we
> could also implement that with pid as these functions are executed in
> process context.
>=20
> Signed-off-by: Yafang Shao <laoar.shao@gmail.com>
>=20
> ---
> v1 -> v2: use sk_cookie as key suggested by Eric.
> ---
> include/trace/events/tcp.h | 33 +++++++++++++++++++++++++++------
> net/ipv4/tcp_input.c       |  2 ++
> 2 files changed, 29 insertions(+), 6 deletions(-)
>=20
> diff --git a/include/trace/events/tcp.h b/include/trace/events/tcp.h
> index 3dd6802..814f754 100644
> --- a/include/trace/events/tcp.h
> +++ b/include/trace/events/tcp.h
> @@ -10,6 +10,7 @@
> #include <linux/tracepoint.h>
> #include <net/ipv6.h>
> #include <net/tcp.h>
> +#include <linux/sock_diag.h>
>=20
> #define TP_STORE_V4MAPPED(__entry, saddr, daddr)		\
> 	do {							\
> @@ -125,6 +126,7 @@
> 		__array(__u8, daddr, 4)
> 		__array(__u8, saddr_v6, 16)
> 		__array(__u8, daddr_v6, 16)
> +		__field(__u64, sock_cookie)
> 	),
>=20
> 	TP_fast_assign(
> @@ -144,12 +146,24 @@
>=20
> 		TP_STORE_ADDRS(__entry, inet->inet_saddr, inet->inet_daddr,
> 			       sk->sk_v6_rcv_saddr, sk->sk_v6_daddr);
> +
> +		/*
> +		 * sk_cookie is used to identify a socket, with which we could
> +		 * relate this tracepoint with other tracepoints,
> +		 * i.e. tcp_probe.
> +		 * If we needn't this relation, then sk_cookie is useless;
> +		 * if we need this relation, then tcp_probe is already set,
> +		 * and sk_cookie is already set in tcp_probe, so we could get
> +		 * the value directly.
> +		 */
> +		__entry->sock_cookie =3D atomic64_read(&sk->sk_cookie);
> 	),
>=20
> -	TP_printk("sport=3D%hu dport=3D%hu saddr=3D%pI4 daddr=3D%pI4 saddrv6=3D=
%pI6c daddrv6=3D%pI6c",
> +	TP_printk("sport=3D%hu dport=3D%hu saddr=3D%pI4 daddr=3D%pI4 saddrv6=3D=
%pI6c daddrv6=3D%pI6c sock_cookie=3D%llu",
> 		  __entry->sport, __entry->dport,
> 		  __entry->saddr, __entry->daddr,
> -		  __entry->saddr_v6, __entry->daddr_v6)
> +		  __entry->saddr_v6, __entry->daddr_v6,
> +		  __entry->sock_cookie)
> );
>=20
> DEFINE_EVENT(tcp_event_sk, tcp_receive_reset,
> @@ -166,6 +180,13 @@
> 	TP_ARGS(sk)
> );
>=20
> +DEFINE_EVENT(tcp_event_sk, tcp_rcv_space_adjust,
> +
> +	TP_PROTO(const struct sock *sk),
> +
> +	TP_ARGS(sk)
> +);
> +
> TRACE_EVENT(tcp_retransmit_synack,
>=20
> 	TP_PROTO(const struct sock *sk, const struct request_sock *req),
> @@ -232,6 +253,7 @@
> 		__field(__u32, snd_wnd)
> 		__field(__u32, srtt)
> 		__field(__u32, rcv_wnd)
> +		__field(__u64, sock_cookie)
> 	),
>=20
> 	TP_fast_assign(
> @@ -256,15 +278,14 @@
> 		__entry->rcv_wnd =3D tp->rcv_wnd;
> 		__entry->ssthresh =3D tcp_current_ssthresh(sk);
> 		__entry->srtt =3D tp->srtt_us >> 3;
> +		__entry->sock_cookie =3D sock_gen_cookie(sk);
> 	),
>=20
> -	TP_printk("src=3D%pISpc dest=3D%pISpc mark=3D%#x length=3D%d snd_nxt=3D=
%#x "
> -		  "snd_una=3D%#x snd_cwnd=3D%u ssthresh=3D%u snd_wnd=3D%u srtt=3D%u "
> -		  "rcv_wnd=3D%u",
> +	TP_printk("src=3D%pISpc dest=3D%pISpc mark=3D%#x length=3D%d snd_nxt=3D=
%#x snd_una=3D%#x snd_cwnd=3D%u ssthresh=3D%u snd_wnd=3D%u srtt=3D%u rcv_wn=
d=3D%u sock_cookie=3D%llu",
> 		  __entry->saddr, __entry->daddr, __entry->mark,
> 		  __entry->length, __entry->snd_nxt, __entry->snd_una,
> 		  __entry->snd_cwnd, __entry->ssthresh, __entry->snd_wnd,
> -		  __entry->srtt, __entry->rcv_wnd)
> +		  __entry->srtt, __entry->rcv_wnd, __entry->sock_cookie)
> );
>=20
> #endif /* _TRACE_TCP_H */
> diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
> index f93687f..43ad468 100644
> --- a/net/ipv4/tcp_input.c
> +++ b/net/ipv4/tcp_input.c
> @@ -582,6 +582,8 @@ void tcp_rcv_space_adjust(struct sock *sk)
> 	u32 copied;
> 	int time;
>=20
> +	trace_tcp_rcv_space_adjust(sk);
> +
> 	tcp_mstamp_refresh(tp);
> 	time =3D tcp_stamp_us_delta(tp->tcp_mstamp, tp->rcvq_space.time);
> 	if (time < (tp->rcv_rtt_est.rtt_us >> 3) || tp->rcv_rtt_est.rtt_us =3D=
=3D 0)
> --=20
> 1.8.3.1
>=20

If I understand this correctly, you can get all the information you need wi=
th
a kprobe on tcp_rcv_space_adjust(). Why is it necessary to introduce a new=
=20
tracepoint?=20

Thanks,
Song