From patchwork Fri Apr 20 15:14:05 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yafang Shao X-Patchwork-Id: 901980 X-Patchwork-Delegate: davem@davemloft.net Return-Path: X-Original-To: patchwork-incoming-netdev@ozlabs.org Delivered-To: patchwork-incoming-netdev@ozlabs.org Authentication-Results: ozlabs.org; spf=none (mailfrom) smtp.mailfrom=vger.kernel.org (client-ip=209.132.180.67; helo=vger.kernel.org; envelope-from=netdev-owner@vger.kernel.org; receiver=) Authentication-Results: ozlabs.org; dmarc=pass (p=none dis=none) header.from=gmail.com Authentication-Results: ozlabs.org; dkim=pass (2048-bit key; unprotected) header.d=gmail.com header.i=@gmail.com header.b="CUj26Nv8"; dkim-atps=neutral Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by ozlabs.org (Postfix) with ESMTP id 40SKCJ5wycz9s3F for ; Sat, 21 Apr 2018 01:14:36 +1000 (AEST) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755431AbeDTPOU (ORCPT ); Fri, 20 Apr 2018 11:14:20 -0400 Received: from mail-pg0-f67.google.com ([74.125.83.67]:34329 "EHLO mail-pg0-f67.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755291AbeDTPOT (ORCPT ); Fri, 20 Apr 2018 11:14:19 -0400 Received: by mail-pg0-f67.google.com with SMTP id p10so4174304pgn.1; Fri, 20 Apr 2018 08:14:19 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id; bh=2i47duIpr7sXhfEL6QB+43/PtHWlIYjLoafUZlT0wHI=; b=CUj26Nv8nDXa0x/ToETZB0tOY5v7gPejpl9rIGVTUL0G3oNX9pHO+UhB5wfQTPfIia 76nN19Ao4bpmgietEjQICcJ0vT9StWItzInwH6MGzzXpsdGC4DAdXBifxtHP97uObj9R I+VaBaF94ruEoiiIUiGAMU7pq9xRQdUFR9/r5OICKPBTmotTbKvlg+gSiwBbwz8Gv+mW syo3ruPCqP/6o01kmkNkhciXfjA9KK6Tf0fzCjYkUhDimLGT9igxRNAJXrbKtOpev6E1 +pA9q/l3EABuVB7QvTiBYBj3+PHpEltxILvSpTK9H3D3FfwM1AvHNS8WhvM1Yh8UreP1 5j1w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id; bh=2i47duIpr7sXhfEL6QB+43/PtHWlIYjLoafUZlT0wHI=; b=fD0giCLkVVx6YSQIwYuYfqdNFkNwSWzZGaCOXYi1UeBD/e6GQ5Ry0GyQk8e245qkmV iCzHTWiPfpAOw9YVYefPTnVLh3+8OnRkPBLEscoMAwW0PlaFzBEZ36PnEA1Qq3jeO1km Z6XfXl0jjrtqeiNy/ucFVExvcDFC2Q3b31dNY9gdyWYHA0Hx9aSAr+I8XpNDLcEUn2O9 qo4MbUbuuIJP2reVlBuDWwdr7nLwcRcSZ3QngvdZWh5z/Uou8rQFTHhVH2tuZcF8sFSS H7uJ6l8xIeluT8GY1sM0On6nAu7ZzOxolhZ/KVBDirvcxU22+fqf98QK4iFiNGdbz7Tc CmdA== X-Gm-Message-State: ALQs6tBa4j7N9Z6BQrbCR2+YZXn2ivW7mRyIaDYROJeivk3zzqqIzC35 y1YhPRR5mIyg0K4em/euicM= X-Google-Smtp-Source: AIpwx48p4yJFK1FwOzObr6DfleW+HFLrDmDyRyfL3gCagzOQkz1lIewxT9AhcTs8qkksgBMHEiamLQ== X-Received: by 10.98.208.195 with SMTP id p186mr10139316pfg.250.1524237258641; Fri, 20 Apr 2018 08:14:18 -0700 (PDT) Received: from li1588-6.members.linode.com (li1588-6.members.linode.com. [139.162.104.6]) by smtp.gmail.com with ESMTPSA id r82sm18202085pfk.187.2018.04.20.08.14.16 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Fri, 20 Apr 2018 08:14:17 -0700 (PDT) From: Yafang Shao To: eric.dumazet@gmail.com, alexei.starovoitov@gmail.com, songliubraving@fb.com, davem@davemloft.net Cc: netdev@vger.kernel.org, linux-kernel@vger.kernel.org, Yafang Shao Subject: [PATCH net-next v3] net: introduce a new tracepoint for tcp_rcv_space_adjust Date: Fri, 20 Apr 2018 23:14:05 +0800 Message-Id: <1524237245-10940-1-git-send-email-laoar.shao@gmail.com> X-Mailer: git-send-email 1.8.3.1 Sender: netdev-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: netdev@vger.kernel.org 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. 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. With these two tracepoints, we could figure out whether the user program processes this packet immediately or there's latency. Hence in the printk message, sk_cookie is printed as a key to relate tcp_rcv_space_adjust with tcp_probe. 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. Signed-off-by: Yafang Shao --- v2 -> v3: use sock_gen_cookie in tcp_event_sk as well. Maybe we could init sk_cookie in the stack then in other code path we just read it other than set it. If that is needed I will do it in another new patch. v1 -> v2: use sk_cookie as a key suggested by Eric. --- include/trace/events/tcp.h | 30 +++++++++++++++++++++--------- net/ipv4/tcp_input.c | 2 ++ 2 files changed, 23 insertions(+), 9 deletions(-) diff --git a/include/trace/events/tcp.h b/include/trace/events/tcp.h index 3dd6802..c820bf6 100644 --- a/include/trace/events/tcp.h +++ b/include/trace/events/tcp.h @@ -10,6 +10,7 @@ #include #include #include +#include #define TP_STORE_V4MAPPED(__entry, saddr, daddr) \ do { \ @@ -113,7 +114,7 @@ */ DECLARE_EVENT_CLASS(tcp_event_sk, - TP_PROTO(const struct sock *sk), + TP_PROTO(struct sock *sk), TP_ARGS(sk), @@ -125,6 +126,7 @@ __array(__u8, daddr, 4) __array(__u8, saddr_v6, 16) __array(__u8, daddr_v6, 16) + __field(__u64, sock_cookie) ), TP_fast_assign( @@ -144,24 +146,34 @@ TP_STORE_ADDRS(__entry, inet->inet_saddr, inet->inet_daddr, sk->sk_v6_rcv_saddr, sk->sk_v6_daddr); + + __entry->sock_cookie = sock_gen_cookie(sk); ), - TP_printk("sport=%hu dport=%hu saddr=%pI4 daddr=%pI4 saddrv6=%pI6c daddrv6=%pI6c", + TP_printk("sport=%hu dport=%hu saddr=%pI4 daddr=%pI4 saddrv6=%pI6c daddrv6=%pI6c sock_cookie=%llu", __entry->sport, __entry->dport, __entry->saddr, __entry->daddr, - __entry->saddr_v6, __entry->daddr_v6) + __entry->saddr_v6, __entry->daddr_v6, + __entry->sock_cookie) ); DEFINE_EVENT(tcp_event_sk, tcp_receive_reset, - TP_PROTO(const struct sock *sk), + TP_PROTO(struct sock *sk), TP_ARGS(sk) ); DEFINE_EVENT(tcp_event_sk, tcp_destroy_sock, - TP_PROTO(const struct sock *sk), + TP_PROTO(struct sock *sk), + + TP_ARGS(sk) +); + +DEFINE_EVENT(tcp_event_sk, tcp_rcv_space_adjust, + + TP_PROTO(struct sock *sk), TP_ARGS(sk) ); @@ -232,6 +244,7 @@ __field(__u32, snd_wnd) __field(__u32, srtt) __field(__u32, rcv_wnd) + __field(__u64, sock_cookie) ), TP_fast_assign( @@ -256,15 +269,14 @@ __entry->rcv_wnd = tp->rcv_wnd; __entry->ssthresh = tcp_current_ssthresh(sk); __entry->srtt = tp->srtt_us >> 3; + __entry->sock_cookie = sock_gen_cookie(sk); ), - TP_printk("src=%pISpc dest=%pISpc mark=%#x length=%d snd_nxt=%#x " - "snd_una=%#x snd_cwnd=%u ssthresh=%u snd_wnd=%u srtt=%u " - "rcv_wnd=%u", + TP_printk("src=%pISpc dest=%pISpc mark=%#x length=%d snd_nxt=%#x snd_una=%#x snd_cwnd=%u ssthresh=%u snd_wnd=%u srtt=%u rcv_wnd=%u sock_cookie=%llx", __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) ); #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; + trace_tcp_rcv_space_adjust(sk); + tcp_mstamp_refresh(tp); time = 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 == 0)