Re: kern/55567: tcp-send slows down to slow single byte transfers

[Frank Kardel <kardel%netbsd.org@localhost>]

The following reply was made to PR kern/55567; it has been noted by GNATS.

From: Frank Kardel <kardel%netbsd.org@localhost>
To: gnats-bugs%netbsd.org@localhost
Cc: 
Subject: Re: kern/55567: tcp-send slows down to slow single byte transfers
Date: Mon, 17 Aug 2020 11:52:57 +0200

 This is a multi-part message in MIME format.
 --------------7998CBB9F2A2AE5CA07C4A61
 Content-Type: text/plain; charset=utf-8; format=flowed
 Content-Transfer-Encoding: 7bit
 
 Updating observations:
 
 Testcase database connection - request/reply pattern:
 Client side while everything is working quickly - send windo is 134336:
 TCP Protocol Control Block at 0xffff97010a313a20:
 
 Timers:
          REXMT   0x100<MPSAFE>
          PERSIST 0x100<MPSAFE>
          KEEP    0x102<PENDING,MPSAFE>   695872
          2MSL    0x100<MPSAFE>
 
 
 State: ESTABLISHED, flags 0xbe4, inpcb 0xffff97010a27b780, in6pcb 0x0
 
 rxtshift 0, rxtcur 3, dupacks 0
 peermss 33584, ourmss 33584, segsz 33572, segqlen 0
 
 snd_una 751851283, snd_nxt 751851283, snd_up 751850985
 snd_wl1 760580867, snd_wl2 751851283, iss 751812995, snd_wnd 134336
 
 rcv_wnd 134336, rcv_nxt 760580867, rcv_up 760580867, irs 760431634
 
 rcv_adv 760715203, snd_max 751851283, snd_cwnd 105455, snd_ssthresh 
 1073725440
 rcvtime 119937, rtttime 0, rtseq 751850985, srtt 11, rttvar 7, rttmin 2, 
 max_sndwnd 134336
 
 oobflags 0, iobc 0, softerror 0
 
 snd_scale 3, rcv_scale 3, req_r_scale 3, req_s_scale 3
 ts_recent 4, ts_regent_age 119937, last_ack_sent 760580867
 
 The server side around that time - send window is 191680:
 
 TCP Protocol Control Block at 0xffff970177875070:
 
 Timers:
          REXMT   0x102<PENDING,MPSAFE>   100
          PERSIST 0x100<MPSAFE>
          KEEP    0x102<PENDING,MPSAFE>   720000
          2MSL    0x100<MPSAFE>
 
 
 State: ESTABLISHED, flags 0x9e4, inpcb 0xffff97010a27b868, in6pcb 0x0
 
 rxtshift 0, rxtcur 2, dupacks 0
 peermss 33584, ourmss 33584, segsz 33572, segqlen 0
 
 snd_una 2723953510, snd_nxt 2723961702, snd_up 2723953510
 snd_wl1 751861149, snd_wl2 2723609446, iss 760431634, snd_wnd 191680
 
 rcv_wnd 134336, rcv_nxt 751861149, rcv_up 751861149, irs 751812995
 
 rcv_adv 751995485, snd_max 2723961702, snd_cwnd 524280, snd_ssthresh 67144
 rcvtime 120706, rtttime 120706, rtseq 2723953510, srtt 7, rttvar 3, 
 rttmin 2, max_sndwnd 199520
 
 oobflags 0, iobc 0, softerror 0
 
 snd_scale 3, rcv_scale 3, req_r_scale 3, req_s_scale 3
 ts_recent 773, ts_regent_age 120706, last_ack_sent 751861149
 
 So all is well ans communication is quick - then after some time the 
 client side closes the send window:
 
 TCP Protocol Control Block at 0xffff97010a313a20:
 
 Timers:
          REXMT   0x100<MPSAFE>
          PERSIST 0x102<PENDING,MPSAFE>   272
          KEEP    0x102<PENDING,MPSAFE>   719791
          2MSL    0x100<MPSAFE>
 
 
 State: ESTABLISHED, flags 0xbe4, inpcb 0xffff97010a27b780, in6pcb 0x0
 
 rxtshift 0, rxtcur 3, dupacks 0
 peermss 33584, ourmss 33584, segsz 33572, segqlen 0
 
 snd_una 751995524, snd_nxt 751995524, snd_up 751995523
 snd_wl1 760593254, snd_wl2 751861149, iss 751812995, snd_wnd 0
 
 rcv_wnd 199872, rcv_nxt 2929580456, rcv_up 760593254, irs 760431634
 
 rcv_adv 2929780328, snd_max 751995524, snd_cwnd 67144, snd_ssthresh 67144
 rcvtime 123247, rtttime 0, rtseq 751995341, srtt 32, rttvar 3, rttmin 2, 
 max_sndwnd 134336
 
 oobflags 0, iobc 0, softerror 0
 
 snd_scale 3, rcv_scale 3, req_r_scale 3, req_s_scale 3
 ts_recent 3314, ts_regent_age 123247, last_ack_sent 2929580456
 
 and the server is still fine:
 TCP Protocol Control Block at 0xffff970177875070:
 
 Timers:
          REXMT   0x100<MPSAFE>
          PERSIST 0x100<MPSAFE>
          KEEP    0x102<PENDING,MPSAFE>   719715
          2MSL    0x100<MPSAFE>
 
 
 State: ESTABLISHED, flags 0x9e4, inpcb 0xffff97010a27b868, in6pcb 0x0
 
 rxtshift 0, rxtcur 3, dupacks 0
 peermss 33584, ourmss 33584, segsz 33572, segqlen 0
 
 snd_una 2929580456, snd_nxt 2929580456, snd_up 2929580456
 snd_wl1 751995341, snd_wl2 2929580456, iss 760431634, snd_wnd 199872
 
 rcv_wnd 134336, rcv_nxt 751995511, rcv_up 751995341, irs 751812995
 
 rcv_adv 752129847, snd_max 2929580456, snd_cwnd 235004, snd_ssthresh 67144
 rcvtime 123116, rtttime 0, rtseq 2929580196, srtt 11, rttvar 7, rttmin 
 2, max_sndwnd 199872
 
 oobflags 0, iobc 0, softerror 0
 
 snd_scale 3, rcv_scale 3, req_r_scale 3, req_s_scale 3
 ts_recent 3183, ts_regent_age 123116, last_ack_sent 751995511
 
 But at this state the persist timer sends 1 byte window probes which get 
 acknowledgments with the correct sequence numbers.
 
 The advertised window size is not picked up in tcp_input ACK processing 
 because  SEQ_LT(tp->snd_wl1, th->th_seq)
 at this point SEQ_LT(760593254, 2929580456) returns 0 in the window 
 update part (step6). The question is
 how it happened that snd_wl1 reached 760593254 though one would expect 
 it around (rcv_nxt)2929580456 =< (rcv_adv)2929780328
 if I didn't confuse things here.
 
 At that state it is unlikely the the connection will recover.
 
 The pcap trace for this is included.
 
 
 --------------7998CBB9F2A2AE5CA07C4A61
 Content-Type: application/gzip;
  name="trace.pcap.gz"
 Content-Transfer-Encoding: base64
 Content-Disposition: attachment;
  filename="trace.pcap.gz"
 
 H4sICGZPNl8AA3RyYWNlLnBjYXAApdRNaNNgHAbwf9ZRhh+wwwY7Brx0EgS1c63sYKc9CDkI
 DjzIlmZJ6tItqbTpKl4W8OBaEMFTi0RQhkwGOfiF6GHqHMyNbRIctNvUi0cvngep79u0je1e
 ZV0Cb0MLeZ7nByVfl54/7oBOqF+x2v3t8DlutXSs+t1ApwOdKECR5QAu+AFmACh8Kgu9Yca6
 mzCNlTt6H1+w76Efqa4jAEcT+FxBz52FtDQlCRp9ko6nkgodEYRkRtW4y5qk0NkJKSXRMu67
 X3b6NF+9z3eTjTX39YYrC7gLdW7qfZECJTX3nUbPdZ7BHyMoJAA92fGMLN5CPwz/BgrdeqCr
 gi7cd2Kb4Bsn+jZNY23Rq+/1NsEnkHxri4w1G/TqG9oh+ESSbzZoGht7Xn2lHYJPIvk29lBn
 0avv2i7BFyf6iqZhDXr12bW+hOuLszdIPmsQddpV3/XD+25/I/gmiD7bNLZkr77j352+tOtL
 sjLJtyUzVk6o+sTD+wZ+OH1PXN8jViH5coJplOaqvgf7fef/4buUVHhZdYS471mtb4iq91Eh
 ViX5SnOocx37Ksx/fPAQ/K7v19++d6iPeeq8T1dc3yc2S/Stm0Z5Xu9GvjeNvsmaj4rA1Sgb
 vThCK7IakHj51DQ/lZFEXpP6aT5Nx+VUWsN9X174IIR6Qm5fEL/L9/vK84yVH9W7IwU70NQ3
 +R7/7176IIyeC7s5A605zu78aGN3fyMng3N4HPT5g7+dQWMtg6Zx2DLKWT74oDHCoBmcpeIg
 9WNbg7iWQToOW0U5P18deBBHGJTDWSIOCiy1NSjWMiiPw/4AdXQSGsMHAAA=
 --------------7998CBB9F2A2AE5CA07C4A61--