Discussion:
is tcp flow control broken in -current
(too old to reply)
Frank Kardel
2020-08-12 19:56:33 UTC
Permalink
Hi !

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 get 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.

#***@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
decode21: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
21:46:12.327069 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack
32777, win 4096, options [nop,nop,TS val 1162 ecr 1161], length 0
21:46:17.127229 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq
32777:32778, ack 1517535785, win 4096, options [nop,nop,TS val 1171 ecr
1162], length 1
21:46:17.327230 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack
32778, win 4096, options [nop,nop,TS val 1172 ecr 1171], length 0
21:46:22.127380 IP 127.0.0.1.65525 > 127.0.0.1.5433: Flags [.], seq
32778:32779, ack 1517535785, win 4096, options [nop,nop,TS val 1181 ecr
1172], length 1
21:46:22.327374 IP 127.0.0.1.5433 > 127.0.0.1.65525: Flags [.], ack
32779, win 4096, options [nop,nop,TS val 1182 ecr 1181], length 0

#***@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 acked.

Any ideas?

Frank


--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de
Jonathan A. Kollasch
2020-08-13 01:15:06 UTC
Permalink
Hi !
While running a java application on -current(9.99.60+70) with JDBC talking
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 get a single character of a query string once every
five seconds and later on once per minute. At the same time netstat -an
It's not just me! I see this all the time with iperf3 (usually only
when the bulk of the traffic is going in a specific direction, which I
don't remember at the moment) after a few gigabytes of transfer.

--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de
Jason Thorpe
2020-08-13 02:05:32 UTC
Permalink
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?
Frank, can you make sure to file a PR on this issue so that it doesn't get lost in the shuffle?

-- thorpej


--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de
Valery Ushakov
2020-08-13 03:32:14 UTC
Permalink
Post by Frank Kardel
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 get 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.
[...]
Post by Frank Kardel
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 acked.
Any ideas?
Without actually looking at the details... I've fixed a bug a while
ago that was kinda similar:

http://gnats.netbsd.org/49390

I wonder if you hit something like that too as sending 1 byte at large
intervals looks like a window probe. Except nothing in your trace
suggests you should be in that territory. Well, you asked for *any*
ideas... :)

-uwe


--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de
Frank Kardel
2020-08-13 05:16:59 UTC
Permalink
Sure - kern/55567

Frank
Post by Jason Thorpe
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?
Frank, can you make sure to file a PR on this issue so that it doesn't get lost in the shuffle?
-- thorpej
--
Posted automagically by a mail2news gateway at muc.de e.V.
Please direct questions, flames, donations, etc. to news-***@muc.de
Loading...