Arduino-esp32: Webserver: Consistent 9-second delay when loading in AP mode

Created on 7 Jan 2020 · 8Comments · Source: espressif/arduino-esp32

Hardware:

Board: ESP32 Dev Module
Core Installation version: 1.0.1, 1.0.3, 1.0.4
IDE name: Arduino IDE 1.8.10
Flash Frequency: 80Mhz
PSRAM enabled: no
Upload Speed: 115200
Computer OS: Windows 10

Description:

In AP mode, the browser (Chrome 79.0.3945.88) consistently takes 9 sec to load a page. This is unusual because in STA mode it finishes in 50 msec. Here is what I have captured on WireShark:

"No.","Time","Source","Destination","Protocol","Length","Info"
"1","0.000000","192.168.4.2","8.8.8.8","DNS","78","Standard query 0x7553 A www.googleapis.com"
"2","0.215307","192.168.4.2","8.8.8.8","DNS","79","Standard query 0xcf4c A clients2.google.com"
"3","0.755384","192.168.4.2","8.8.4.4","DNS","84","Standard query 0xbc0d A autoupdate.geo.opera.com"
"4","1.000664","192.168.4.2","8.8.4.4","DNS","78","Standard query 0x7553 A www.googleapis.com"
"5","1.029940","192.168.4.2","192.168.4.1","TCP","66","56664  >  80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"6","1.030329","192.168.4.2","192.168.4.1","TCP","66","56665  >  80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"7","1.033327","192.168.4.1","192.168.4.2","TCP","58","80  >  56664 [SYN, ACK] Seq=0 Ack=1 Win=5744 Len=0 MSS=1436"
"8","1.033511","192.168.4.2","192.168.4.1","TCP","54","56664  >  80 [ACK] Seq=1 Ack=1 Win=64240 Len=0"
"9","1.034514","192.168.4.2","8.8.8.8","DNS","94","Standard query 0x1311 A elb-tky-amz.nimbus.bitdefender.net"
"10","1.034830","192.168.4.2","192.168.4.1","HTTP","544","GET /hello HTTP/1.1 "
"11","1.036960","192.168.4.1","192.168.4.2","TCP","58","80  >  56665 [SYN, ACK] Seq=0 Ack=1 Win=5744 Len=0 MSS=1436"
"12","1.037119","192.168.4.2","192.168.4.1","TCP","54","56665  >  80 [ACK] Seq=1 Ack=1 Win=64240 Len=0"
"13","1.041135","192.168.4.1","192.168.4.2","TCP","54","80  >  56664 [ACK] Seq=1 Ack=491 Win=5254 Len=0"
"14","1.047777","192.168.4.1","192.168.4.2","TCP","136","[TCP segment of a reassembled PDU]"
"15","1.049019","192.168.4.1","192.168.4.2","HTTP","65","HTTP/1.1 299   (text/plain)"
"16","1.049088","192.168.4.2","192.168.4.1","TCP","54","56664  >  80 [ACK] Seq=491 Ack=94 Win=64147 Len=0"
"17","1.215698","192.168.4.2","8.8.4.4","DNS","79","Standard query 0xcf4c A clients2.google.com"
"18","2.756031","192.168.4.2","8.8.8.8","DNS","84","Standard query 0xbc0d A autoupdate.geo.opera.com"
"19","2.756192","192.168.4.2","8.8.4.4","DNS","84","Standard query 0xbc0d A autoupdate.geo.opera.com"
"20","3.000734","192.168.4.2","8.8.8.8","DNS","78","Standard query 0x7553 A www.googleapis.com"
"21","3.000890","192.168.4.2","8.8.4.4","DNS","78","Standard query 0x7553 A www.googleapis.com"
"22","3.050835","192.168.4.1","192.168.4.2","TCP","54","80  >  56664 [FIN, ACK] Seq=94 Ack=491 Win=5254 Len=0"
"23","3.216587","192.168.4.2","8.8.8.8","DNS","79","Standard query 0xcf4c A clients2.google.com"
"24","3.216732","192.168.4.2","8.8.4.4","DNS","79","Standard query 0xcf4c A clients2.google.com"
"25","3.459343","192.168.4.2","224.0.0.251","MDNS","91","Standard query response 0x0000 A, cache flush 192.168.4.2"
"26","4.527714","192.168.4.2","224.0.0.251","MDNS","93","Standard query response 0x0000 A, cache flush 192.168.217.1"
"27","5.036444","192.168.4.2","8.8.4.4","DNS","94","Standard query 0x1311 A elb-tky-amz.nimbus.bitdefender.net"
"28","5.042377","192.168.4.1","192.168.4.2","TCP","54","[TCP Spurious Retransmission] 80  >  56664 [FIN, ACK] Seq=94 Ack=491 Win=5254 Len=0"
"29","5.939795","192.168.4.2","81.161.59.85","TCP","66","56668  >  80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"30","6.756090","192.168.4.2","8.8.8.8","DNS","84","Standard query 0xbc0d A autoupdate.geo.opera.com"
"31","6.756243","192.168.4.2","8.8.4.4","DNS","84","Standard query 0xbc0d A autoupdate.geo.opera.com"
"32","6.941409","192.168.4.2","81.161.59.85","TCP","66","[TCP Retransmission] 56668  >  80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"33","7.002775","192.168.4.2","8.8.8.8","DNS","78","Standard query 0x7553 A www.googleapis.com"
"34","7.002919","192.168.4.2","8.8.4.4","DNS","78","Standard query 0x7553 A www.googleapis.com"
"35","7.218276","192.168.4.2","8.8.8.8","DNS","79","Standard query 0xcf4c A clients2.google.com"
"36","7.218432","192.168.4.2","8.8.4.4","DNS","79","Standard query 0xcf4c A clients2.google.com"
"37","8.053909","192.168.4.1","192.168.4.2","TCP","54","80  >  56665 [FIN, ACK] Seq=1 Ack=1 Win=5744 Len=0"
"38","8.054171","192.168.4.2","192.168.4.1","TCP","54","56665  >  80 [ACK] Seq=1 Ack=2 Win=64240 Len=0"
"39","8.459378","192.168.4.2","224.0.0.251","MDNS","91","Standard query response 0x0000 A, cache flush 192.168.4.2"
"40","8.940983","192.168.4.2","81.161.59.85","TCP","66","[TCP Retransmission] 56668  >  80 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"41","9.037928","192.168.4.2","52.193.16.89","TCP","66","56671  >  443 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"42","9.038161","192.168.4.2","52.193.16.89","TCP","66","56672  >  443 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"43","9.038375","192.168.4.2","52.193.16.89","TCP","66","56673  >  443 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1"
"44","9.043751","192.168.4.1","192.168.4.2","TCP","54","[TCP Spurious Retransmission] 80  >  56664 [FIN, ACK] Seq=94 Ack=491 Win=5254 Len=0"
"45","9.528350","192.168.4.2","224.0.0.251","MDNS","93","Standard query response 0x0000 A, cache flush 192.168.217.1"
"46","10.039017","192.168.4.2","192.168.4.1","TCP","54","56664  >  80 [ACK] Seq=491 Ack=95 Win=64147 Len=0"
"47","10.040319","192.168.4.2","192.168.4.1","TCP","54","56664  >  80 [FIN, ACK] Seq=491 Ack=95 Win=64147 Len=0"
"48","10.042804","192.168.4.1","192.168.4.2","TCP","54","80  >  56664 [ACK] Seq=95 Ack=492 Win=5253 Len=0"
"49","10.528415","192.168.4.2","8.8.4.4","DNS","76","Standard query 0x63ec A mtalk.google.com"

Starting from item 10 (t=1.035s), the content was received shortly at item 15 (t=1.049s). However, the browser continued waiting till 9 seconds later before it completes loading, likely at item 44 (t=9.044s) "TCP Spurious Retransmission".

Could this be a bug? I have tried loading with a few PCs, with some having the same problem as well. Here is the sketch used for testing:

#include <WiFi.h>
#include <DNSServer.h>
#include <WebServer.h>

const char* apssid = "ESP32";
const char* appassword = "pass1234";

DNSServer dnsServer;
WebServer server(80);

void setup(){
  Serial.begin(115200);

  WiFi.softAP(apssid, appassword);
  delay(500);

  Serial.println();
  Serial.print("IP address: ");
  Serial.println(WiFi.softAPIP());

  dnsServer.setErrorReplyCode(DNSReplyCode::NoError);
  dnsServer.start(53, "*", WiFi.softAPIP());

  server.on("/hello", [](){server.send(299,"text/plain","Hello World");});

  server.begin();
  Serial.println("Server started");
}

void loop(){
  server.handleClient();
}

stale

Source

bot1131357

Most helpful comment

Not sure if it is related, but I had a lot of stalling in STA mode and got rid of the stalls with
WiFi.mode( WIFI_STA ); WiFi.setSleep( false ); WiFi.begin();
As said, it did the trick in STA mode not AP mode but it is easy and quick to try.

CelliesProjects on 21 Jan 2020

👍2

All 8 comments

I'm going to preface this with "I don't have in depth networking knowledge so please take this with a pinch of salt."

This is the wireshark capture for loading a http server locally:

"No.","Time","Source","Destination","Protocol","Length","Data","X position","Y position","Info"
"5","0.316483","127.0.0.1","127.0.0.1","TCP","66","","","","61470  >  8000 [SYN] Seq=0 Win=65535 Len=0 MSS=65495 WS=256 SACK_PERM=1"
"6","0.316590","127.0.0.1","127.0.0.1","TCP","66","","","","8000  >  61470 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=65495 WS=256 SACK_PERM=1"
"7","0.316654","127.0.0.1","127.0.0.1","TCP","54","","","","61470  >  8000 [ACK] Seq=1 Ack=1 Win=2619648 Len=0"
"8","0.317696","127.0.0.1","127.0.0.1","HTTP","547","","","","GET / HTTP/1.1 "
"9","0.317734","127.0.0.1","127.0.0.1","TCP","54","","","","8000  >  61470 [ACK] Seq=1 Ack=494 Win=2619648 Len=0"
"10","0.379459","127.0.0.1","127.0.0.1","TCP","209","","","","8000  >  61470 [PSH, ACK] Seq=1 Ack=494 Win=2619648 Len=155 [TCP segment of a reassembled PDU]"
"11","0.379497","127.0.0.1","127.0.0.1","TCP","54","","","","61470  >  8000 [ACK] Seq=494 Ack=156 Win=2619392 Len=0"
"12","0.379565","127.0.0.1","127.0.0.1","HTTP","3627","","","","HTTP/1.0 200 OK  (text/html)"
"13","0.379588","127.0.0.1","127.0.0.1","TCP","54","","","","61470  >  8000 [ACK] Seq=494 Ack=3729 Win=2616064 Len=0"
"14","0.379703","127.0.0.1","127.0.0.1","TCP","54","","","","8000  >  61470 [FIN, ACK] Seq=3729 Ack=494 Win=2619648 Len=0"
"15","0.379733","127.0.0.1","127.0.0.1","TCP","54","","","","61470  >  8000 [ACK] Seq=494 Ack=3730 Win=2616064 Len=0"
"16","0.381655","127.0.0.1","127.0.0.1","TCP","54","","","","61470  >  8000 [FIN, ACK] Seq=494 Ack=3730 Win=2616064 Len=0"
"17","0.381715","127.0.0.1","127.0.0.1","TCP","54","","","","8000  >  61470 [ACK] Seq=3730 Ack=495 Win=2619648 Len=0"

After item 12, we see the following happen:

client sends ACK
server sends FIN, ACK
client sends ACK
client sends FIN, ACK
server sends ACK

At this point, the request is considered to have loaded successfully.

Now looking at the capture you sent:
After item 15, we see

16: client sends ACK
22, 2s later: server sends FIN, ACK
28, 2s later: server sends FIN, ACK again
44, 4s later: server sends FIN, ACK again
46, 1s later: client sends ACK
47: client sends FIN, ACK
48: server sends ACK

At this point, the request is considered to have loaded successfully.

Item 22 raises the question of why does the ESP32 take 2s to send FIN, ACK back

However, theres also the question of why did the client not respond to the repeated FIN, ACKs until nearly 7s later.

JustinOng on 8 Jan 2020

👍1

Thanks, that delayed FIN, ACK might have been the reason that led to a spurious retransmission. It doesn't seem to be a browser issue either - the delay was observed across multiple browsers (Opera, Chrome, FireFox ) on some laptops, but not on others.
I'm surprised that so far no one else has encountered this issue.

Could it have something to do with interference from other wireless devices in my area? Hm...

bot1131357 on 9 Jan 2020

@bot1131357 Do subsequent calls go through immediately after the first delayed one responds? I'm finding this issue as well using a Lolin D32 and D32 Pro. The browser/OS seems irrelevant.

The thing I've noticed is it only seems to happen for the first request, if it's been awhile since it's received a request. If I leave it running for an hour or so and then send a command via a web browser...it takes 1-2 seconds to respond (just looking at network tools in browser). Subsequent calls respond immediately. It seems that if x time passes without receiving something via wifi is when the delay is introduced. I'm not proficient with microcontrollers, but it's acting as though it's waking up from a sleep mode, or like back in the days of platter HD's if the HD went to sleep and you tried to access it it took awhile to respond that first time while it was spinning up, but once it was spinning the rest of the calls respond immediately.

Edit: I'm not using any sort of low power modes, and this problem happens with example code.

steveheinsch on 9 Jan 2020

👍1

@steveheinsch Only that there's no platter to speak of. My example code returns just a text string.

Update: ~You're right.~
Here's what I did:
1) Set up two browsers side-by-side.
2) Load the first browser
3) Wait for ~8 sec before loading the second browser
~4) The second browser completes the request almost immediately after the first.~
4) Few outcomes:
a) second browser completes the request almost immediately after the first.
b) both browsers complete request in about 9 sec.
c) second browser completes request in more than 9 sec.

Now sure I can make out the pattern to this. Also, during testing, sometimes the response time reverts to 1 sec... 🤔

In all cases, the server did respond immediately with the requested content. Somehow the browser fails to get the FIN, ACK.

bot1131357 on 13 Jan 2020

CelliesProjects on 21 Jan 2020

👍2

~I don't have access to my existing system (on vacation), but now that I'm in a different country - I found that the AP response is very speedy - 15ms to 33ms. Adding the code as suggested by @CelliesProjects made it slower to 113ms to 234ms.~

~Could the speed difference be caused by background WiFi interference?~

Update:
~Also tested STA mode in the same environment, and found that the response range between 34ms to 409ms. Anyone knows what to make of this?~

Update2:
~Tested and found the response to be consistent with AsyncWebServer - about 15-30ms in AP mode, 30-120ms in STA mode...~

The AP response was very speedy only because I tested on one of the machines where this problem does not manifest. (It happens on some machines but not others.) The delay still happens when accessed from another machine. In any case, adding the code as suggested by @CelliesProjects did not change anything.

bot1131357 on 2 Feb 2020

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.