Marscel
2017-11-08, 17:24:38
Ich brauche mal eure Ideen. Hier ist ein Programm (A), das per Websocket-over-TLS über C/Winsock mit einer Gegenstelle (B) redet, auf dem selben Host.
Die TCP-Pakete sind so gut wie nie größer als 1kB, die Verarbeitung dauert max. 1ms. Das ging auch lange ganz gut, allerdings nicht mehr, wenn die Gegenstelle einen bestimmten Zustand hat. Ich kann den Fall wenigstens sauber eigenständig nachstellen.
Folgendes, grobes Protokoll:
A: WS-Frame Handshake
B: WS-Frame Handshake_OK
...
B: WS-Frame N, dann M, dann wieder N
A: sieht M und schickt darauf T um K zu beantragen, ließt dann das letzte N vom Socket
B: WS-Frame K, K, K
Lässt man das letzte N weg, läuft alles super. Hat man es, bleibt A beim recv() für die Daten des zweiten K hängen. Erst wenn B nachschießt, kommt Bewegung in A, aber auch wieder nur bis zu einem bestimmten Punkt.
Ich habe mir mit Wireshark mal das ganze angeguckt:
No. Time Source Destination Protocol Length Info
15 2.684240 192.168.2.100 192.168.2.122 TLSv1 331 Application Data
16 2.688255 192.168.2.122 192.168.2.100 TLSv1 256 Application Data, Application Data
17 2.688360 192.168.2.100 192.168.2.122 TLSv1 299 Application Data
18 2.745087 192.168.2.122 192.168.2.100 TCP 60 9002 → 50152 [ACK] Seq=1438 Ack=799 Win=33536 Len=0
25 6.227487 192.168.2.122 192.168.2.100 TLSv1 288 Application Data, Application Data
26 6.228397 192.168.2.122 192.168.2.100 TLSv1 522 Application Data, Application Data, Application Data, Application Data
-> ACK: ~0ms
27 6.228432 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=799 Ack=2140 Win=66076 Len=0
28 6.228954 192.168.2.100 192.168.2.122 TLSv1 299 Application Data
29 6.230729 192.168.2.122 192.168.2.100 TCP 60 9002 → 50152 [ACK] Seq=2140 Ack=1044 Win=34560 Len=0
30 6.232110 192.168.2.122 192.168.2.100 TLSv1 992 Application Data, Application Data
-> ACK: 200ms
31 6.437166 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=1044 Ack=3078 Win=66780 Len=0
32 6.447154 192.168.2.122 192.168.2.100 TLSv1 992 [TCP Spurious Retransmission] , Application Data, Application Data
33 6.447188 192.168.2.100 192.168.2.122 TCP 66 [TCP Dup ACK 31#1] 50152 → 9002 [ACK] Seq=1044 Ack=3078 Win=66780 Len=0 SLE=2140 SRE=3078
35 6.949176 192.168.2.122 192.168.2.100 TLSv1 992 Application Data, Application Data
36 7.149211 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=1044 Ack=4016 Win=65840 Len=0
37 7.150638 192.168.2.122 192.168.2.100 TLSv1 992 [TCP Spurious Retransmission] , Application Data, Application Data
38 7.150672 192.168.2.100 192.168.2.122 TCP 66 [TCP Dup ACK 36#1] 50152 → 9002 [ACK] Seq=1044 Ack=4016 Win=65840 Len=0 SLE=3078 SRE=4016
43 9.936687 192.168.2.122 192.168.2.100 TLSv1 992 Application Data, Application Data
48 10.136164 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=1044 Ack=4954 Win=66780 Len=0
52 10.154243 192.168.2.122 192.168.2.100 TLSv1 992 [TCP Spurious Retransmission] , Application Data, Application Data
53 10.154273 192.168.2.100 192.168.2.122 TCP 66 [TCP Dup ACK 48#1] 50152 → 9002 [ACK] Seq=1044 Ack=4954 Win=66780 Len=0 SLE=4016 SRE=4954
TL; DR:
* Auf einmal steigt das ACK-Delay von A von bisher 0ms auf 200ms an (Zeile 31).
* B scheint das für Timeouts zu halten und schickt mir nochmal den Kram. (Zeile 32)
* A schickt denselben ACK nochmal, aber jetz in null Zeit (Zeilen 33, 38, 53).
* Dann dauerts wieder jeweils beim ACK (zweites K kommt im Test 700ms später, drittes nochmal 3s später, das ist gewollt - Zeilen 36, 48).
Ein wenig Gegoogle und es scheint da etwas Windows-spezifisches mit 200ms Timeout zu geben - bei den kleineren Nachrichten am Anfang ist ja aber noch alles gut (bis Zeile 27). Als Maßnahmen werden da abwechselnd TCP_NODELAY auf 1 und SO_SNDBUF auf 0 erwähnt, aber das hat bisher nichts wundersam geheilt.
Schematisch macht A im Code sowas wie:
while (1) {
// blockiert, sollte aber hier in Ordnung sein
ws_read_frame(socket, data);
// verarbeite `data'
if (war_M)
ws_send_frame(socket, T_data);
}
`ws_read_frame' bleibt dann bald hängen, obwohl B gerade was geschickt hat, bis B erneut was mitteilt, und holt dann erst die vorherige Nachricht auf.
Hab ich irgendwas übersehen oder ist was offensichtlich totaler Käse?
Die TCP-Pakete sind so gut wie nie größer als 1kB, die Verarbeitung dauert max. 1ms. Das ging auch lange ganz gut, allerdings nicht mehr, wenn die Gegenstelle einen bestimmten Zustand hat. Ich kann den Fall wenigstens sauber eigenständig nachstellen.
Folgendes, grobes Protokoll:
A: WS-Frame Handshake
B: WS-Frame Handshake_OK
...
B: WS-Frame N, dann M, dann wieder N
A: sieht M und schickt darauf T um K zu beantragen, ließt dann das letzte N vom Socket
B: WS-Frame K, K, K
Lässt man das letzte N weg, läuft alles super. Hat man es, bleibt A beim recv() für die Daten des zweiten K hängen. Erst wenn B nachschießt, kommt Bewegung in A, aber auch wieder nur bis zu einem bestimmten Punkt.
Ich habe mir mit Wireshark mal das ganze angeguckt:
No. Time Source Destination Protocol Length Info
15 2.684240 192.168.2.100 192.168.2.122 TLSv1 331 Application Data
16 2.688255 192.168.2.122 192.168.2.100 TLSv1 256 Application Data, Application Data
17 2.688360 192.168.2.100 192.168.2.122 TLSv1 299 Application Data
18 2.745087 192.168.2.122 192.168.2.100 TCP 60 9002 → 50152 [ACK] Seq=1438 Ack=799 Win=33536 Len=0
25 6.227487 192.168.2.122 192.168.2.100 TLSv1 288 Application Data, Application Data
26 6.228397 192.168.2.122 192.168.2.100 TLSv1 522 Application Data, Application Data, Application Data, Application Data
-> ACK: ~0ms
27 6.228432 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=799 Ack=2140 Win=66076 Len=0
28 6.228954 192.168.2.100 192.168.2.122 TLSv1 299 Application Data
29 6.230729 192.168.2.122 192.168.2.100 TCP 60 9002 → 50152 [ACK] Seq=2140 Ack=1044 Win=34560 Len=0
30 6.232110 192.168.2.122 192.168.2.100 TLSv1 992 Application Data, Application Data
-> ACK: 200ms
31 6.437166 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=1044 Ack=3078 Win=66780 Len=0
32 6.447154 192.168.2.122 192.168.2.100 TLSv1 992 [TCP Spurious Retransmission] , Application Data, Application Data
33 6.447188 192.168.2.100 192.168.2.122 TCP 66 [TCP Dup ACK 31#1] 50152 → 9002 [ACK] Seq=1044 Ack=3078 Win=66780 Len=0 SLE=2140 SRE=3078
35 6.949176 192.168.2.122 192.168.2.100 TLSv1 992 Application Data, Application Data
36 7.149211 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=1044 Ack=4016 Win=65840 Len=0
37 7.150638 192.168.2.122 192.168.2.100 TLSv1 992 [TCP Spurious Retransmission] , Application Data, Application Data
38 7.150672 192.168.2.100 192.168.2.122 TCP 66 [TCP Dup ACK 36#1] 50152 → 9002 [ACK] Seq=1044 Ack=4016 Win=65840 Len=0 SLE=3078 SRE=4016
43 9.936687 192.168.2.122 192.168.2.100 TLSv1 992 Application Data, Application Data
48 10.136164 192.168.2.100 192.168.2.122 TCP 54 50152 → 9002 [ACK] Seq=1044 Ack=4954 Win=66780 Len=0
52 10.154243 192.168.2.122 192.168.2.100 TLSv1 992 [TCP Spurious Retransmission] , Application Data, Application Data
53 10.154273 192.168.2.100 192.168.2.122 TCP 66 [TCP Dup ACK 48#1] 50152 → 9002 [ACK] Seq=1044 Ack=4954 Win=66780 Len=0 SLE=4016 SRE=4954
TL; DR:
* Auf einmal steigt das ACK-Delay von A von bisher 0ms auf 200ms an (Zeile 31).
* B scheint das für Timeouts zu halten und schickt mir nochmal den Kram. (Zeile 32)
* A schickt denselben ACK nochmal, aber jetz in null Zeit (Zeilen 33, 38, 53).
* Dann dauerts wieder jeweils beim ACK (zweites K kommt im Test 700ms später, drittes nochmal 3s später, das ist gewollt - Zeilen 36, 48).
Ein wenig Gegoogle und es scheint da etwas Windows-spezifisches mit 200ms Timeout zu geben - bei den kleineren Nachrichten am Anfang ist ja aber noch alles gut (bis Zeile 27). Als Maßnahmen werden da abwechselnd TCP_NODELAY auf 1 und SO_SNDBUF auf 0 erwähnt, aber das hat bisher nichts wundersam geheilt.
Schematisch macht A im Code sowas wie:
while (1) {
// blockiert, sollte aber hier in Ordnung sein
ws_read_frame(socket, data);
// verarbeite `data'
if (war_M)
ws_send_frame(socket, T_data);
}
`ws_read_frame' bleibt dann bald hängen, obwohl B gerade was geschickt hat, bis B erneut was mitteilt, und holt dann erst die vorherige Nachricht auf.
Hab ich irgendwas übersehen oder ist was offensichtlich totaler Käse?