ESP8266 TCP Server: Erster Verbindungsaufbau nach Reset dauert lange

[Paul H. (powl)]

Hi,

ich experimentiere gerade erstmals mit dem ESP8266 und möchte auf diesem
einen TCP-Server laufen lassen, der eingehende Verbindungen annimmt und
Steuerbefehle auswertet.

Dabei ist mir aufgefallen, dass der erste Verbindungsaufbau einer
TCP-Verbindung zum ESP sehr lange dauert. Immer nachdem ich einen Reset
durchführe verbindet er sich erwartungsgemäß sofort wieder mit dem WLAN
und beginnt, auf eingehende TCP-Verbindungen zu warten. Sobald ich nun
von meinem Rechner aus eine Verbindung aufbauen will dauert es das erste
Mal zwischen dem Drücken des "connect"-Buttons in meiner Software
ungefär 4 Sekunden bis zur Rückmeldung des ESP in der Serialport
Konsole. Trenne ich danach die TCP.Verbindung wieder und baue eine neue
auf geht das ganze superschnell. Um zu testen, ob es eventuell an meinem
PC oder der verwendeten Software liegt habe ich mehrere TCP Test Tools
ausprobiert und auch mal zunächst versucht, die erste Verbindung zum ESP
von meinem Laptop aus aufzubauen und erst dann zum ESP. Fazit: Egal von
welchem Gerät aus, die erste TCP-Verbindung zum ESP benötigt immer sehr
lange für den Verbindungsaufbau. 3-4 Sekunden. Dabei spielt es auch
keine Rolle, wie lange der ESP schon läuft.

Woran liegt das?

lg Paul

[Stefan F. (Gast)]

Ich sehe keinen Fehler.
Ist die Stromversorgung stabil? Also nicht durch ein Steckbrett geführt 
und hast du einen 100µF Kondensator direkt am ESP-Modul?

[Paul H. (powl)]

Ist ein WeMos D1 R2 Board, da ist der 100µF kondensator schon drauf. 
Auch ein externes Netzteil hilft hier nicht. Hatte aber mit UDP-Paketen 
schon durchaus Probleme mit Paketverlust und weiß daher, dass 
Stromversorgung bei dem Teil offenbar sehr kritisch ist. Daher bin ich 
auch auf das TCP-Protokoll gegangen.

Ich habe mir gerade mal Wireshark besorg und aufgezeichnet. Schaut man 
sich  mal die Zeitstempel an sieht man, dass es 2,76 Sekunden gedauert 
hat, bis die Verbindung stand. Bei nachfolgenden Versuchen dauert das 
dann nur noch 135ms (was ich für computermaßstäbe auch schon sehr sehr 
lange finde)

[Paul H. (powl)]

Was ebenfalls bemerkenswert ist, die Ping-Zeiten des Moduls spielen 
anfangs immer etwas verrückt. Starte ich in der Kommandozeile den 
Ping-Befehl dauern die ersten 3 Pings immer ewig. In Wireshark kann ich 
gut sehen, dass der ESP scheinbar wirklich so lange braucht, um zu 
responden. Alle nachfolgenden sind dann flott.

Verfällt der ESP immer in eine Art Schlafmodus wenn man ihn eine Weile 
schon nicht mehr angepingt hat? Trifft das nur auf Ping oder auch auf 
andere Verbindungen zu?

Auch die Antwort auf ein einfaches TCP-Paket dauert Ewigkeiten. Ich habe 
mal eben eine Verbindung aufgebaut und dann alle paar Sekunden mal ein 
Paket gesendet. In Wireshark dann geschaut, wie lange der ESP braucht um 
das ACK zu schicken:
270ms
234ms
243ms
118ms
249ms
189ms
292ms

Ob der ESP auf 80 oder 160MHz eingestellt ist spielt übrigens hierbei 
auch keine Rolle. Testweise habe ich auch die loop() { ... } Funktion 
mal komplett leer gelassen, kein Unterschied. (Ich programmiere den ESP 
mit der Arduino IDE und den neusten Librarys)

Mach ich hier irgendetwas grob falsch oder mögen es diese Module einfach 
überhaupt nicht, wenn sie nicht regelmäßig mit Daten beschickt um ihnen 
zu beweisen, dass sie sich nicht schlafenlegen sollen?

[Stefan F. (Gast)]

Bei mir dauern die ersten 1-3 Pings auch immer etwas länger (um 100ms), 
danach sind es weniger als 10ms.

Deine ACK Zeiten sehen gar nicht gut aus. Allerdings sehe ich in deinem 
Programm serielle Ausgabe, die braucht auch ihre Zeit und spielt hier 
vielleicht eine Rolle. Kommentiere diese Zeilen man aus und versuche es 
dann nochmal.

Du könntest zum Vergleich mal Programme installieren, die bekanntermaßen 
gut funktionieren. Zum Beispiel meine Beispiele: 
http://stefanfrings.de/esp8266/index.html. Ich sehe in deinem Code zwar 
keinen Fehler, aber vielleicht bringt das trotzdem irgendeine neue 
Erkenntnis. Das kann man ja mal eben schnell probieren.

[Tiramisu (Gast)]

Beim ping "-n" verwenden (um DNS Geschichten auszuschliessen).

Beim Aushandeln der TCP-Windows Sizes sagt der ESP dass er eine
MSS von 536 Bytes und eine Window Size von 2144 Bytes hat.
TCPs kann konzeptuell ACKs delayen (ein Timeout im Receive-TCP-Stack),
der Sender darf 4 Pakete a 536 Bytes senden ohne dass er sich um ACKs
"kuemmern" muss. Daher ist das ACK i.A. kein Maß für die Reaktion
der Applikation.

[Stefan F. (Gast)]

> Daher ist das ACK i.A. kein Maß für die Reaktion der Applikation.

Beim ESP ist sie das schon, da er das ACK immer sofort (ohne Windows 
Size) sendet.

[Dauergast (Gast)]

Paul H. schrieb:
> die Ping-Zeiten des Moduls spielen
> anfangs immer etwas verrückt. Starte ich in der Kommandozeile den
> Ping-Befehl dauern die ersten 3 Pings immer ewig.

Das ist der "AUTO_MODEM_SLEEP" (default nach Reset des ESP8266), siehe 
hier:

https://blog.creations.de/?p=149

In der Praxis sieht das (bei mir) nach wenigen Sekunden ohne Traffic so 
aus (und sollte sich auf eine TCP-Verbindung ebenso auswirken):

MIT wifi_set_sleep_type(NONE_SLEEP_T);

root@spezi-dell:/home/test# sleep 10;ping 10.24.10.202 -i 1 -n -c 20
PING 10.24.10.202 (10.24.10.202) 56(84) bytes of data.
64 bytes from 10.24.10.202: icmp_seq=1 ttl=128 time=3.46 ms
64 bytes from 10.24.10.202: icmp_seq=2 ttl=128 time=5.08 ms
64 bytes from 10.24.10.202: icmp_seq=3 ttl=128 time=3.00 ms
64 bytes from 10.24.10.202: icmp_seq=4 ttl=128 time=2.45 ms
64 bytes from 10.24.10.202: icmp_seq=5 ttl=128 time=1.68 ms
64 bytes from 10.24.10.202: icmp_seq=6 ttl=128 time=3.83 ms
64 bytes from 10.24.10.202: icmp_seq=7 ttl=128 time=4.02 ms
64 bytes from 10.24.10.202: icmp_seq=8 ttl=128 time=3.90 ms
64 bytes from 10.24.10.202: icmp_seq=9 ttl=128 time=3.95 ms
64 bytes from 10.24.10.202: icmp_seq=10 ttl=128 time=3.78 ms
64 bytes from 10.24.10.202: icmp_seq=11 ttl=128 time=2.11 ms
64 bytes from 10.24.10.202: icmp_seq=12 ttl=128 time=2.36 ms
64 bytes from 10.24.10.202: icmp_seq=13 ttl=128 time=5.94 ms
64 bytes from 10.24.10.202: icmp_seq=14 ttl=128 time=3.84 ms
64 bytes from 10.24.10.202: icmp_seq=15 ttl=128 time=3.22 ms
64 bytes from 10.24.10.202: icmp_seq=16 ttl=128 time=3.83 ms
64 bytes from 10.24.10.202: icmp_seq=17 ttl=128 time=3.08 ms
64 bytes from 10.24.10.202: icmp_seq=18 ttl=128 time=2.04 ms
64 bytes from 10.24.10.202: icmp_seq=19 ttl=128 time=1.57 ms
64 bytes from 10.24.10.202: icmp_seq=20 ttl=128 time=3.86 ms

--- 10.24.10.202 ping statistics ---
20 packets transmitted, 20 received, 0% packet loss, time 19029ms
rtt min/avg/max/mdev = 1.570/3.353/5.943/1.078 ms


OHNE wifi_set_sleep_type(NONE_SLEEP_T);

root@spezi-dell:/home/test# sleep 10;ping 10.24.10.202 -i 1 -n -c 20
PING 10.24.10.202 (10.24.10.202) 56(84) bytes of data.
64 bytes from 10.24.10.202: icmp_seq=1 ttl=128 time=102 ms
64 bytes from 10.24.10.202: icmp_seq=2 ttl=128 time=21.9 ms
64 bytes from 10.24.10.202: icmp_seq=3 ttl=128 time=42.9 ms
64 bytes from 10.24.10.202: icmp_seq=4 ttl=128 time=1.93 ms
64 bytes from 10.24.10.202: icmp_seq=5 ttl=128 time=3.59 ms
64 bytes from 10.24.10.202: icmp_seq=6 ttl=128 time=3.31 ms
64 bytes from 10.24.10.202: icmp_seq=7 ttl=128 time=3.80 ms
64 bytes from 10.24.10.202: icmp_seq=8 ttl=128 time=3.70 ms
64 bytes from 10.24.10.202: icmp_seq=9 ttl=128 time=4.78 ms
64 bytes from 10.24.10.202: icmp_seq=10 ttl=128 time=2.91 ms
64 bytes from 10.24.10.202: icmp_seq=11 ttl=128 time=2.52 ms
64 bytes from 10.24.10.202: icmp_seq=12 ttl=128 time=2.49 ms
64 bytes from 10.24.10.202: icmp_seq=13 ttl=128 time=3.28 ms
64 bytes from 10.24.10.202: icmp_seq=14 ttl=128 time=2.99 ms
64 bytes from 10.24.10.202: icmp_seq=15 ttl=128 time=6.56 ms
64 bytes from 10.24.10.202: icmp_seq=16 ttl=128 time=2.14 ms
64 bytes from 10.24.10.202: icmp_seq=17 ttl=128 time=2.61 ms
64 bytes from 10.24.10.202: icmp_seq=18 ttl=128 time=1.51 ms
64 bytes from 10.24.10.202: icmp_seq=19 ttl=128 time=3.21 ms
64 bytes from 10.24.10.202: icmp_seq=20 ttl=128 time=4.28 ms

--- 10.24.10.202 ping statistics ---
20 packets transmitted, 20 received, 0% packet loss, time 19028ms
rtt min/avg/max/mdev = 1.514/11.172/102.847/23.038 ms