From owner-svn-src-all@freebsd.org Mon Jun 8 11:48:09 2020 Return-Path: Delivered-To: svn-src-all@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 407A832CEB9; Mon, 8 Jun 2020 11:48:09 +0000 (UTC) (envelope-from rrs@FreeBSD.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 49gWj50wnvz4KD5; Mon, 8 Jun 2020 11:48:09 +0000 (UTC) (envelope-from rrs@FreeBSD.org) Received: from repo.freebsd.org (repo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id 1ACCC23C3E; Mon, 8 Jun 2020 11:48:09 +0000 (UTC) (envelope-from rrs@FreeBSD.org) Received: from repo.freebsd.org ([127.0.1.37]) by repo.freebsd.org (8.15.2/8.15.2) with ESMTP id 058Bm8fn017915; Mon, 8 Jun 2020 11:48:08 GMT (envelope-from rrs@FreeBSD.org) Received: (from rrs@localhost) by repo.freebsd.org (8.15.2/8.15.2/Submit) id 058Bm7p2017908; Mon, 8 Jun 2020 11:48:07 GMT (envelope-from rrs@FreeBSD.org) Message-Id: <202006081148.058Bm7p2017908@repo.freebsd.org> X-Authentication-Warning: repo.freebsd.org: rrs set sender to rrs@FreeBSD.org using -f From: Randall Stewart Date: Mon, 8 Jun 2020 11:48:07 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r361926 - in head/sys/netinet: . tcp_stacks X-SVN-Group: head X-SVN-Commit-Author: rrs X-SVN-Commit-Paths: in head/sys/netinet: . tcp_stacks X-SVN-Commit-Revision: 361926 X-SVN-Commit-Repository: base MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-all@freebsd.org X-Mailman-Version: 2.1.33 Precedence: list List-Id: "SVN commit messages for the entire src tree \(except for " user" and " projects" \)" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 08 Jun 2020 11:48:09 -0000 Author: rrs Date: Mon Jun 8 11:48:07 2020 New Revision: 361926 URL: https://svnweb.freebsd.org/changeset/base/361926 Log: An important statistic in determining if a server process (or client) is being delayed is to know the time to first byte in and time to first byte out. Currently we have no way to know these all we have is t_starttime. That (t_starttime) tells us what time the 3 way handshake completed. We don't know when the first request came in or how quickly we responded. Nor from a client perspective do we know how long from when we sent out the first byte before the server responded. This small change adds the ability to track the TTFB's. This will show up in BB logging which then can be pulled for later analysis. Note that currently the tracking is via the ticks variable of all three variables. This provides a very rough estimate (hz=1000 its 1ms). A follow-on set of work will be to change all three of these values into something with a much finer resolution (either microseconds or nanoseconds), though we may want to make the resolution configurable so that on lower powered machines we could still use the much cheaper ticks variable. Sponsored by: Netflix Inc. Differential Revision: https://reviews.freebsd.org/D24902 Modified: head/sys/netinet/tcp_input.c head/sys/netinet/tcp_log_buf.c head/sys/netinet/tcp_log_buf.h head/sys/netinet/tcp_stacks/bbr.c head/sys/netinet/tcp_stacks/rack.c head/sys/netinet/tcp_usrreq.c head/sys/netinet/tcp_var.h Modified: head/sys/netinet/tcp_input.c ============================================================================== --- head/sys/netinet/tcp_input.c Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_input.c Mon Jun 8 11:48:07 2020 (r361926) @@ -1841,6 +1841,15 @@ tcp_do_segment(struct mbuf *m, struct tcphdr *th, stru tcp_clean_sackreport(tp); TCPSTAT_INC(tcps_preddat); tp->rcv_nxt += tlen; + if (tlen && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_in == 0)) { + tp->t_fbyte_in = ticks; + if (tp->t_fbyte_in == 0) + tp->t_fbyte_in = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } /* * Pull snd_wl1 up to prevent seq wrap relative to * th_seq. @@ -3016,6 +3025,15 @@ dodata: /* XXX */ else tp->t_flags |= TF_ACKNOW; tp->rcv_nxt += tlen; + if (tlen && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_in == 0)) { + tp->t_fbyte_in = ticks; + if (tp->t_fbyte_in == 0) + tp->t_fbyte_in = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } thflags = th->th_flags & TH_FIN; TCPSTAT_INC(tcps_rcvpack); TCPSTAT_ADD(tcps_rcvbyte, tlen); Modified: head/sys/netinet/tcp_log_buf.c ============================================================================== --- head/sys/netinet/tcp_log_buf.c Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_log_buf.c Mon Jun 8 11:48:07 2020 (r361926) @@ -1693,6 +1693,9 @@ retry: COPY_STAT(snd_numholes); COPY_STAT(snd_scale); COPY_STAT(rcv_scale); + COPY_STAT_T(flags2); + COPY_STAT_T(fbyte_in); + COPY_STAT_T(fbyte_out); #undef COPY_STAT #undef COPY_STAT_T log_buf->tlb_flex1 = 0; Modified: head/sys/netinet/tcp_log_buf.h ============================================================================== --- head/sys/netinet/tcp_log_buf.h Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_log_buf.h Mon Jun 8 11:48:07 2020 (r361926) @@ -32,7 +32,7 @@ #define TCP_LOG_REASON_LEN 32 #define TCP_LOG_TAG_LEN 32 -#define TCP_LOG_BUF_VER (8) +#define TCP_LOG_BUF_VER (9) /* * Because the (struct tcp_log_buffer) includes 8-byte uint64_t's, it requires @@ -143,6 +143,7 @@ struct tcp_log_buffer uint32_t tlb_rttvar; /* TCPCB t_rttvar */ uint32_t tlb_rcv_up; /* TCPCB rcv_up */ uint32_t tlb_rcv_adv; /* TCPCB rcv_adv */ + uint32_t tlb_flags2; /* TCPCB t_flags2 */ uint32_t tlb_rcv_nxt; /* TCPCB rcv_nxt */ uint32_t tlb_rcv_wnd; /* TCPCB rcv_wnd */ uint32_t tlb_dupacks; /* TCPCB t_dupacks */ @@ -150,6 +151,8 @@ struct tcp_log_buffer int tlb_snd_numholes; /* TCPCB snd_numholes */ uint32_t tlb_flex1; /* Event specific information */ uint32_t tlb_flex2; /* Event specific information */ + uint32_t tlb_fbyte_in; /* TCPCB first byte in time */ + uint32_t tlb_fbyte_out; /* TCPCB first byte out time */ uint8_t tlb_snd_scale:4, /* TCPCB snd_scale */ tlb_rcv_scale:4; /* TCPCB rcv_scale */ uint8_t _pad[3]; /* Padding */ Modified: head/sys/netinet/tcp_stacks/bbr.c ============================================================================== --- head/sys/netinet/tcp_stacks/bbr.c Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_stacks/bbr.c Mon Jun 8 11:48:07 2020 (r361926) @@ -8415,6 +8415,15 @@ bbr_process_data(struct mbuf *m, struct tcphdr *th, st tp->t_flags |= TF_ACKNOW; } tp->rcv_nxt += tlen; + if (tlen && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_in == 0)) { + tp->t_fbyte_in = ticks; + if (tp->t_fbyte_in == 0) + tp->t_fbyte_in = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } thflags = th->th_flags & TH_FIN; KMOD_TCPSTAT_ADD(tcps_rcvpack, (int)nsegs); KMOD_TCPSTAT_ADD(tcps_rcvbyte, tlen); @@ -8631,6 +8640,15 @@ bbr_do_fastnewdata(struct mbuf *m, struct tcphdr *th, tcp_clean_sackreport(tp); KMOD_TCPSTAT_INC(tcps_preddat); tp->rcv_nxt += tlen; + if (tlen && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_in == 0)) { + tp->t_fbyte_in = ticks; + if (tp->t_fbyte_in == 0) + tp->t_fbyte_in = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } /* * Pull snd_wl1 up to prevent seq wrap relative to th_seq. */ Modified: head/sys/netinet/tcp_stacks/rack.c ============================================================================== --- head/sys/netinet/tcp_stacks/rack.c Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_stacks/rack.c Mon Jun 8 11:48:07 2020 (r361926) @@ -8763,6 +8763,15 @@ rack_process_data(struct mbuf *m, struct tcphdr *th, s #endif rack_handle_delayed_ack(tp, rack, tlen, tfo_syn); tp->rcv_nxt += tlen; + if (tlen && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_in == 0)) { + tp->t_fbyte_in = ticks; + if (tp->t_fbyte_in == 0) + tp->t_fbyte_in = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } thflags = th->th_flags & TH_FIN; KMOD_TCPSTAT_ADD(tcps_rcvpack, nsegs); KMOD_TCPSTAT_ADD(tcps_rcvbyte, tlen); @@ -8986,6 +8995,15 @@ rack_do_fastnewdata(struct mbuf *m, struct tcphdr *th, tcp_clean_sackreport(tp); KMOD_TCPSTAT_INC(tcps_preddat); tp->rcv_nxt += tlen; + if (tlen && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_in == 0)) { + tp->t_fbyte_in = ticks; + if (tp->t_fbyte_in == 0) + tp->t_fbyte_in = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } /* * Pull snd_wl1 up to prevent seq wrap relative to th_seq. */ Modified: head/sys/netinet/tcp_usrreq.c ============================================================================== --- head/sys/netinet/tcp_usrreq.c Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_usrreq.c Mon Jun 8 11:48:07 2020 (r361926) @@ -1196,6 +1196,16 @@ tcp_usr_send(struct socket *so, int flags, struct mbuf socantsendmore(so); tcp_usrclosed(tp); } + if (TCPS_HAVEESTABLISHED(tp->t_state) && + ((tp->t_flags2 & TF2_FBYTES_COMPLETE) == 0) && + (tp->t_fbyte_out == 0) && + (so->so_snd.sb_ccc > 0)) { + tp->t_fbyte_out = ticks; + if (tp->t_fbyte_out == 0) + tp->t_fbyte_out = 1; + if (tp->t_fbyte_out && tp->t_fbyte_in) + tp->t_flags2 |= TF2_FBYTES_COMPLETE; + } if (!(inp->inp_flags & INP_DROPPED) && !(flags & PRUS_NOTREADY)) { if (flags & PRUS_MORETOCOME) Modified: head/sys/netinet/tcp_var.h ============================================================================== --- head/sys/netinet/tcp_var.h Mon Jun 8 09:39:48 2020 (r361925) +++ head/sys/netinet/tcp_var.h Mon Jun 8 11:48:07 2020 (r361926) @@ -202,6 +202,8 @@ struct tcpcb { tcp_seq t_rtseq; /* sequence number being timed */ u_int t_starttime; /* time connection was established */ + u_int t_fbyte_in; /* ticks time when first byte queued in */ + u_int t_fbyte_out; /* ticks time when first byte queued out */ u_int t_pmtud_saved_maxseg; /* pre-blackhole MSS */ int t_blackhole_enter; /* when to enter blackhole detection */ @@ -434,7 +436,7 @@ TAILQ_HEAD(tcp_funchead, tcp_function); #define TF2_ECN_SND_CWR 0x00000040 /* ECN CWR in queue */ #define TF2_ECN_SND_ECE 0x00000080 /* ECN ECE in queue */ #define TF2_ACE_PERMIT 0x00000100 /* Accurate ECN mode */ - +#define TF2_FBYTES_COMPLETE 0x00000400 /* We have first bytes in and out */ /* * Structure to hold TCP options that are only used during segment * processing (in tcp_input), but not held in the tcpcb.