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. _______________________________________________ svn-src-all@freebsd.org mailing list https://lists.freebsd.org/mailman/listinfo/svn-src-all To unsubscribe, send any mail to "svn-src-all-unsubscr...@freebsd.org"
