From patchwork Mon Apr 16 15:33:38 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yafang Shao X-Patchwork-Id: 898735 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="kYKEQHkc"; dkim-atps=neutral Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by ozlabs.org (Postfix) with ESMTP id 40PsqT2cB3z9s3G for ; Tue, 17 Apr 2018 01:33:57 +1000 (AEST) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752882AbeDPPdz (ORCPT ); Mon, 16 Apr 2018 11:33:55 -0400 Received: from mail-pf0-f195.google.com ([209.85.192.195]:35038 "EHLO mail-pf0-f195.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752120AbeDPPdw (ORCPT ); Mon, 16 Apr 2018 11:33:52 -0400 Received: by mail-pf0-f195.google.com with SMTP id j5so1178510pfh.2; Mon, 16 Apr 2018 08:33:52 -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=AlhCUbQ0/OPjDOYyvWL6ekzq//iJCXqf0mUlMGelEe8=; b=kYKEQHkcCE5jh3h7cl880jSj57X3dq6cfD2z13uZR8Chyi/5sEQQADozScLbYdgU+M 6G9vfNZJub5paj7RbHNjfMOQO03r4SgTEKZRg0RGDvyP94c8RPgEXd7QFaTlFq8i0R7p aZ/FoG5445iiRuB2H4oIYXzcPfQm+xDR1y7Ctjcxo6UG4Vp2QWYAgdnyuWaBtAtrFgCo EOfPurWDT2fhNLYRvsydSLDTFVnpcp8glWFp5alUU/QbJAKzsCugv8cyjXf11krQAQ6k t9lAmMsi97+uu5JQjPKjwd/qhACUc6B2ix7QsXb06QyQmsds/V0+b0RPXCq73CUNNI5C FQjg== 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=AlhCUbQ0/OPjDOYyvWL6ekzq//iJCXqf0mUlMGelEe8=; b=lRVkegqqpHMQWeknM/YFl6FpMN+rzIORTaoAhmN2Atwyn1/jMHKAlOxf9S1CpK8rki 2RvejnXLZPbGaqPuWiY0gvae9MP1n8ikXib9I7R3pAsTs5Svd3kkMS8gC1stYUDV9KVp pMddK7jrsLyN+Twu8FMy1RawhnMXUKlmcPzG6ktNV1WrpnlWF8oaf9NH1x5x93bZRJH2 Kop/YeyhC5fcf5cnidhal8uTv9vj29fAr/JAiyepwptgFAt837BZM2Wo5qQeF0tinhIi JIexBOV5ZQP5Io5/um7s0438VU1QPkU4oUGbLhU+HYJxLpEtIWTKepLNbLYsjXhEjbWM YKqg== X-Gm-Message-State: ALQs6tA4T4laJB2NYODQkvzqKF8bKctOmdX+pnpENkpuaMopMzEzfcks 7LELz62/QpK/vTU1ZtcvJ93Y7w== X-Google-Smtp-Source: AIpwx4/lL+G9Q3KoXuPD0hLWiOgil9vivjk9dUsrLWnZO/MbOQdTMtR56wICH1QYKT8rICHKYpQkqA== X-Received: by 10.99.165.79 with SMTP id r15mr3312422pgu.236.1523892832077; Mon, 16 Apr 2018 08:33:52 -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 g186sm23222989pfb.3.2018.04.16.08.33.49 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Mon, 16 Apr 2018 08:33:51 -0700 (PDT) From: Yafang Shao To: davem@davemloft.net Cc: kuznet@ms2.inr.ac.ru, yoshfuji@linux-ipv6.org, songliubraving@fb.com, netdev@vger.kernel.org, linux-kernel@vger.kernel.org, Yafang Shao Subject: [PATCH net-next] net: introduce a new tracepoint for tcp_rcv_space_adjust Date: Mon, 16 Apr 2018 23:33:38 +0800 Message-Id: <1523892818-12820-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. This could help us figure out whether there's latency in user process. 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. arrives time : user process time => latency caused by user tcp_probe tcp_rcv_space_adjust Hence in the prink message, sk is printed as a key to connect these two tracepoints. Maybe we could export sockfd in this new tracepoint as well, then we could connect this new tracepoint with epoll/read/recv* tracepoint, 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 --- include/trace/events/tcp.h | 21 +++++++++++++++------ net/ipv4/tcp_input.c | 2 ++ 2 files changed, 17 insertions(+), 6 deletions(-) diff --git a/include/trace/events/tcp.h b/include/trace/events/tcp.h index 878b2be..65a6d22 100644 --- a/include/trace/events/tcp.h +++ b/include/trace/events/tcp.h @@ -146,10 +146,11 @@ sk->sk_v6_rcv_saddr, sk->sk_v6_daddr); ), - 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=0x%p", __entry->sport, __entry->dport, __entry->saddr, __entry->daddr, - __entry->saddr_v6, __entry->daddr_v6) + __entry->saddr_v6, __entry->daddr_v6, + __entry->skaddr) ); DEFINE_EVENT(tcp_event_sk, tcp_receive_reset, @@ -166,6 +167,13 @@ TP_ARGS(sk) ); +DEFINE_EVENT(tcp_event_sk, tcp_rcv_space_adjust, + + TP_PROTO(const struct sock *sk), + + TP_ARGS(sk) +); + TRACE_EVENT(tcp_set_state, TP_PROTO(const struct sock *sk, const int oldstate, const int newstate), @@ -265,6 +273,7 @@ TP_ARGS(sk, skb), TP_STRUCT__entry( + __field(const void *, skaddr) /* sockaddr_in6 is always bigger than sockaddr_in */ __array(__u8, saddr, sizeof(struct sockaddr_in6)) __array(__u8, daddr, sizeof(struct sockaddr_in6)) @@ -285,6 +294,8 @@ const struct tcp_sock *tp = tcp_sk(sk); const struct inet_sock *inet = inet_sk(sk); + __entry->skaddr = sk; + memset(__entry->saddr, 0, sizeof(struct sockaddr_in6)); memset(__entry->daddr, 0, sizeof(struct sockaddr_in6)); @@ -305,13 +316,11 @@ __entry->srtt = tp->srtt_us >> 3; ), - 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=0x%p", __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->skaddr) ); #endif /* _TRACE_TCP_H */ diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c index 367def6..4b4d6b9 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)