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

To: kern-bug-people%netbsd.org@localhost,gnats-admin%netbsd.org@localhost,netbsd-bugs%netbsd.org@localhost
Subject: kern/55567: tcp-send slows down to slow single byte transfers
From: kardel%netbsd.org@localhost
Date: Thu, 13 Aug 2020 05:15:00 +0000 (UTC)

>Number:         55567
>Category:       kern
>Synopsis:       tcp-send slows down to slow single byte transfers
>Confidential:   no
>Severity:       critical
>Priority:       high
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Thu Aug 13 05:15:00 +0000 2020
>Originator:     Frank Kardel
>Release:        NetBSD 9.99.70
>Organization:
	
>Environment:
	
	
System: NetBSD pip 9.99.70 NetBSD 9.99.70 (PIPGEN) #32: Wed Aug 12 15:29:33 CEST 2020 kardel@pip:/src/NetBSD/cur/src/obj.amd64/sys/arch/amd64/compile/PIPGEN amd64
Architecture: x86_64
Machine: amd64
>Description:
While running a java application on -current(9.99.60+70) with JDBC talking to a postgres11 database I observed the following:

The application runs and processes large number of queries via the tcp back-end connection via the loopback interface. After a while the communication

slows down significantly.

The database back-end gets a single character of a query string once every five seconds and later on once per minute. At the same time netstat -an

shows that the send-queue has more than one character available.

#root@Alpine:/home/kardel 20:42 [28]# tcpdump -i lo0 -n port 5433 and port 65525
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
21:45:24.330991 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517533791:1517533826, ack 31819, win 4096, options [nop,nop,TS val 1066 ecr 1066], length 35
21:45:24.525198 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], ack 1517533826, win 4096, options [nop,nop,TS val 1066 ecr 1066], length 0
21:45:31.723722 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 31819:31978, ack 1517533826, win 4096, options [nop,nop,TS val 1080 ecr 1066], length 159
21:45:31.725197 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517533826:1517534277, ack 31978, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 451
21:45:31.725459 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 31978:32074, ack 1517534277, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 96
21:45:31.726212 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517534277:1517534718, ack 32074, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 441
21:45:31.726477 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 32074:32233, ack 1517534718, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 159
21:45:31.727340 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517534718:1517535152, ack 32233, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 434
21:45:31.727536 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 32233:32329, ack 1517535152, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 96
21:45:31.728592 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517535152:1517535600, ack 32329, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 448
21:45:31.729087 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 32329:32552, ack 1517535600, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 223
21:45:31.730461 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517535600:1517535664, ack 32552, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 64
21:45:31.730994 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 32552:32622, ack 1517535664, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 70
21:45:31.731107 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517535664:1517535700, ack 32622, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 36
21:45:31.731309 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [P.], seq 32622:32683, ack 1517535700, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 61
21:45:31.731444 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [P.], seq 1517535700:1517535785, ack 32683, win 4096, options [nop,nop,TS val 1080 ecr 1080], length 85
21:45:31.925506 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32683:32769, ack 1517535785, win 4096, options [nop,nop,TS val 1081 ecr 1080], length 86
21:45:32.125511 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32769, win 4096, options [nop,nop,TS val 1081 ecr 1081], length 0
21:45:37.125738 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32769:32770, ack 1517535785, win 4096, options [nop,nop,TS val 1091 ecr 1081], length 1

### What did just happen?

21:45:37.325728 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32770, win 4096, options [nop,nop,TS val 1092 ecr 1091], length 0
21:45:42.126167 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32770:32771, ack 1517535785, win 4096, options [nop,nop,TS val 1101 ecr 1092], length 1
21:45:42.326164 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32771, win 4096, options [nop,nop,TS val 1102 ecr 1101], length 0
21:45:47.126311 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32771:32772, ack 1517535785, win 4096, options [nop,nop,TS val 1111 ecr 1102], length 1
21:45:47.326311 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32772, win 4096, options [nop,nop,TS val 1112 ecr 1111], length 0
21:45:52.126460 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32772:32773, ack 1517535785, win 4096, options [nop,nop,TS val 1121 ecr 1112], length 1
21:45:52.326463 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32773, win 4096, options [nop,nop,TS val 1122 ecr 1121], length 0
21:45:57.126615 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32773:32774, ack 1517535785, win 4096, options [nop,nop,TS val 1131 ecr 1122], length 1
21:45:57.326619 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32774, win 4096, options [nop,nop,TS val 1132 ecr 1131], length 0
21:46:02.126768 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32774:32775, ack 1517535785, win 4096, options [nop,nop,TS val 1141 ecr 1132], length 1
21:46:02.326766 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32775, win 4096, options [nop,nop,TS val 1142 ecr 1141], length 0
21:46:07.126920 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32775:32776, ack 1517535785, win 4096, options [nop,nop,TS val 1151 ecr 1142], length 1
21:46:07.326932 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack 32776, win 4096, options [nop,nop,TS val 1152 ecr 1151], length 0
21:46:12.127070 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq 32776:32777, ack 1517535785, win 4096, options [nop,nop,TS val 1161 ecr 1152], length 1
#root@Alpine:/home/kardel 20:40 [27]# netstat -na | grep 5433

tcp        0      0  127.0.0.1.5433 127.0.0.1.65525        ESTABLISHED
tcp        0    506  127.0.0.1.65525        127.0.0.1.5433 ESTABLISHED

I suspect something triggered the slow sending and it seems to be stuck in that state even though

the window is 4096 and all packets are (slowly - 200ms) acked. 

>How-To-Repeat:
	No simple method yet known. The Java application / database reproduces it in 5 minutes. There
	are reports that this also happens with iperf3 runs.
>Fix:
	not yet - state handling needs to be analysed

>Unformatted:

Follow-Ups:
- Re: kern/55567: tcp-send slows down to slow single byte transfers
  - From: Frank Kardel

Prev by Date: Re: kern/49390: Unsigned wraparound in tcp sequence number calculations on 64-bit machines
Next by Date: Re: misc/55562 (dangling phrase re: code origin)
Previous by Thread: Re: bin/55565: mtree time= values wrong for tv_nsec<100000000
Next by Thread: Re: kern/55567: tcp-send slows down to slow single byte transfers
Indexes:

Home | Main Index | Thread Index | Old Index