ESP8266HTTPClient takes very long time to send 1MB file(SPIFFS)

[IMAN4K]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: ESP-12
• Core Version: 2.5.0-beta2
• Development Env: other(MSVC2015+VisualMicro)
• Operating System: Windows

Settings in IDE

• Module: Generic ESP8266 Module
• Flash Mode: dio
• Flash Size: 4MB/3MB
• lwip Variant: v2 Higher Bandwidth
• Reset Method: nodemcu
• Flash Frequency: 40Mhz
• CPU Frequency: 80Mhz
• Upload Using: SERIAL
• Upload Speed: 115200

Problem Description

There's a .CSV file in 1MB size that we need to upload to OwnCloud remote server(i have an average ping of 117ms) which takes about 500s to finish! I'm seeking some optimizations to reduce this time as much as possible(while at the end server return code 500, the file is uploaded correctly!)

MCVE Sketch

#include <ESP8266WiFi.h>
#include <ESP8266HTTPClient.h>
#include <FS.h>

#define FILE "/samples.csv"
#define URL "https://oc.unileoben.ac.at/public.php/webdav/sensor_data" FILE
#define SSID "AP-C27347"
#define PSK "Tp@9Jaguar_12_55747+&854"
#define DBG Serial

void setup() {
	DBG.begin(115200);
	DBG.println("starting...");
	WiFi.begin(SSID, PSK);
	uint8_t max = 16;
	while (!WiFi.isConnected() && max--) {
		DBG.println(".");
		delay(250);
	}

	if (!SPIFFS.begin())
		DBG.println("failed to start SPIFFS!");
}

void loop() {
	static bool cloud_send = false;
	if (!cloud_send) {
		cloud_send = true;

		auto f = SPIFFS.open(FILE, "r");
		const auto f_size = f.size();

		std::unique_ptr<BearSSL::WiFiClientSecure>client(new BearSSL::WiFiClientSecure);
		client->setFingerprint("70 7D 10 A9 5E FF 7E 3A 55 87 B8 2C 15 8F C0 14 12 C4 9A 58");
		HTTPClient https;
		https.setUserAgent(String("DataLogger_") + String(ESP.getChipId(), HEX));
		https.addHeader("Content-Type", "text/csv");
		https.addHeader("Content-Length", String(f_size, DEC));
		https.setAuthorization("JPLPTtmcjXxuGFq", "");
		if (!https.begin(*client, URL)) {
			DBG.println("\nfailed to begin https\n");
			return;
		}
		
		int http_code;
		const auto A = millis();
		http_code = https.sendRequest("PUT", &f, f_size);
		DBG.printf("\n time-keep: %lus", (millis() - A) / 1000);
		https.writeToStream(&DBG);
		https.end();
		f.close();
	}
}

Debug Messages

.
.
.
[HTTP-Client][begin] url: https://oc.unileoben.ac.at/public.php/webdav/sensor_data/samples.csv
[HTTP-Client][begin] host: oc.unileoben.ac.at port: 443 url: /public.php/webdav/sensor_data/samples.csv
[hostByName] request IP for: oc.unileoben.ac.at
[hostByName] Host: oc.unileoben.ac.at IP: 193.171.87.163
:ref 1
:wr 223 0
:wrc 223 223 0
:ack 223
:rn 1380
:rd 5, 1380, 0
:rdi 1380, 5
:rd 93, 1380, 5
:rdi 1375, 93
:rch 1380, 1380
:rch 2760, 324
:rd 5, 3084, 98
:rdi 1282, 5
:rd 2634, 3084, 103
:rdi 1277, 1277
:c 1277, 1380, 3084
:rdi 1380, 1357
:rd 5, 1704, 1357
:rdi 23, 5
:rd 333, 1704, 1362
:rdi 18, 18
:c 18, 1380, 1704
:rdi 324, 315
:rd 5, 324, 315
:rdi 9, 5
:rd 4, 324, 320
:rdi 4, 4
:c0 4, 324
wifi evt: 7
wifi evt: 7
wifi evt: 7
:wr 75 0
:wrc 75 75 0
:wr 6 0
:wrc 6 6 0
:wr 45 0
:wrc 45 45 0
:ack 75
:ack 51
:rn 51
:rd 5, 51, 0
:rdi 51, 5
:rd 1, 51, 5
:rdi 46, 1
:rd 5, 51, 6
:rdi 45, 5
:rd 40, 51, 11
:rdi 40, 40
:c0 40, 51
[HTTP-Client] connected to oc.unileoben.ac.at:443
[HTTP-Client] sending request header
-----
PUT /public.php/webdav/sensor_data/samples.csv HTTP/1.1
Host: oc.unileoben.ac.at
User-Agent: DataLogger_438db7
Connection: close
Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
Authorization: Basic SlBMUFR0bWNqWHh1R0ZxOg==
Content-Length: 1043820

-----
:wr 287 0
:wrc 287 287 0
wifi evt: 7
:ack 287
:wr 541 0
:wrc 541 541 0
wifi evt: 7
:ack 541
:wr 541 0
:wrc 541 541 0
wifi evt: 7
:ack 541
:wr 465 0
:wrc 465 465 0
:ack 465
:wr 541 0
:wrc 541 541 0
:ack 541
:wr 541 0
.
.
.
:wrc 465 465 0
wifi evt: 7
:ack 465
:wr 541 0
:wrc 541 541 0
:ack 541
:wr 541 0
:wrc 541 541 0
:ack 541
:wr 465 0
:wrc 465 465 0
:ack 465
:wr 541 0
:wrc 541 541 0
wifi evt: 7
:ack 541
:wr 541 0
:wrc 541 541 0
:ack 541
:wr 385 0
:wrc 385 385 0
:ack 385
[HTTP-Client][sendRequest] Stream payload written: 1043820
:rn 1380
:rch 1380, 371
:rcl
:abort
:rd 5, 1751, 0
:rdi 1380, 5
:rd 1124, 1751, 5
:rdi 1375, 1124
[HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 500 Internal Server Error'
[HTTP-Client][handleHeaderResponse] RX: 'Date: Sun, 27 Jan 2019 10:14:01 GMT'
[HTTP-Client][handleHeaderResponse] RX: 'Server: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips PHP/7.0.32'
[HTTP-Client][handleHeaderResponse] RX: 'Strict-Transport-Security: max-age=15768000; includeSubDomains; preload'
[HTTP-Client][handleHeaderResponse] RX: 'X-Powered-By: PHP/7.0.32'
[HTTP-Client][handleHeaderResponse] RX: 'Set-Cookie: d3c944a9a=2985h0vgek2b1qsrdajs7uekk0; path=/; secure; HttpOnly'
[HTTP-Client][handleHeaderResponse] RX: 'Expires: Thu, 19 Nov 1981 08:52:00 GMT'
[HTTP-Client][handleHeaderResponse] RX: 'Cache-Control: no-store, no-cache, must-revalidate'
[HTTP-Client][handleHeaderResponse] RX: 'Pragma: no-cache'
[HTTP-Client][handleHeaderResponse] RX: 'Set-Cookie: oc_sessionPassphrase=Np%2FXnD4Qhxm%2BGZIHgtW%2BzBu7royWWPgVPIf1YJIR4iKsxOHtzSFKkfZrYJ2l%2FR6n7FzbM%2BKGApbysMw%2FeZg%2BhdXOyZIVO%2F5G4DspJwih%2B7fBChApWo%2FA9xseYrrcVlAO; path=/; secure; HttpOnly'
[HTTP-Client][handleHeaderResponse] RX: 'Content-Security-Policy: default-src 'self'; script-src 'self' 'unsafe-eval'; style-src 'self' 'unsafe-inline'; frame-src *; img-src * data: blob:; font-src 'self' data:; media-src *; connect-src *'
[HTTP-Client][handleHeaderResponse] RX: 'X-Content-Type-Options: nosniff'
[HTTP-Client][handleHeaderResponse] RX: 'X-XSS-Protection: 1; mode=block'
[HTTP-Client][handleHeaderResponse] RX: 'X-Robots-Tag: none'
[HTTP-Client][handleHeaderResponse] RX: 'X-Frame-Options: SAMEORIGIN'
[HTTP-Client][handleHeaderResponse] RX: 'X-Download-Options: noopen'
[HTTP-Client][handleHeaderResponse] RX: 'X-Permitted-Cross-Domain-Policies: none'
[HTTP-Client][handleHeaderResponse] RX: 'Content-Length: 593'
[HTTP-Client][handleHeaderResponse] RX: 'Connection: close'
[HTTP-Client][handleHeaderResponse] RX: 'Content-Type: application/xml; charset=utf-8'
[HTTP-Client][handleHeaderResponse] RX: ''
[HTTP-Client][handleHeaderResponse] code: 500
[HTTP-Client][handleHeaderResponse] size: 593

 time-keep: 501s:rd 5, 1751, 1129
:rdi 251, 5
:rd 617, 1751, 1134
:rdi 246, 246
:c 246, 1380, 1751
:rdi 371, 371
:c0 371, 371
<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>Doctrine\DBAL\Exception\DriverException</s:exception>
  <s:message>An exception occurred while executing 'SELECT `fileid`, `storage`, `path`, `parent`, `name`, `mimetype`, `mimepart`, `size`, `mtime`,
					   `storage_mtime`, `encrypted`, `etag`, `permissions`, `checksum`
				FROM `oc_filecache` WHERE `storage` = ? AND `path_hash` = ?' with params [325, "355ef093881b1c0119da32d0e35b614e"]:

SQLSTATE[HY000]: General error: 2006 MySQL server has gone away</s:message>
</d:error>
[HTTP-Client][writeToStreamDataBlock] connection closed or file end (written: 593).
[HTTP-Client][end] tcp is closed
[HTTP-Client][end] tcp is closed
SPIFFS_close: fd=1
SPIFFS_close: fd=1
:ur 1
:del
.
.
.

[d-a-v]

while at the end server return code 500, the file is uploaded correctly!

Yes, this was a annoying issue finally solved by lwIP-v2.1.2 and SACK.

Regarding slowness, this will be fixed, I hope, after release 2.5.0, maybe with #5511,
maybe with data transfer optimizations that are also planned.

[IMAN4K]

Hi @d-a-v
So there's not much we can do right now with WiFiClient?

[d-a-v]

You are already using "higher bandwidth".
Maybe you could try #5511 ?

[devyte]

To know whether #5511 will help, there are a couple of experiments to try:
How long does it take to read a 1MB file?
How long does it take to stream a 1MB file (not with httpclient of course)?

If just reading the file takes very long, it's the SPIFFS performance issue. In this case #5511 could help.
If reading the file doesn't take too long, but streaming it does, then there is an issue with Stream.
If neither takes too long, then there is an issue with httpclient or WiFiClient or our use of lwip.

[IMAN4K]

To know whether #5511 will help, there are a couple of experiments to try:
How long does it take to read a 1MB file?

In my experiments it will take about 3-4ms to read 3KB from the file system(with above settings), so for 1MB it will be 970-1100ms, and I suppose the bottleneck is the WiFiClient stack itself(?)

How long does it take to stream a 1MB file (not with httpclient of course)?

I stream the exact same file through ESP8266WebServer::streamFile(T &file, const String& contentType) inside captive portal in about 9.5s

If just reading the file takes very long, it's the SPIFFS performance issue. In this case #5511 could help.

It seems no, it's not about file system performance

If reading the file doesn't take too long, but streaming it does, then there is an issue with Stream.

As I mentioned, the streaming is fast with no delay

If neither takes too long, then there is an issue with httpclient or WiFiClient or our use of lwip.

So what should we do ?!

[earlephilhower]

Can you please try actually reading the file? SPIFFS gets slower as it goes further down the file in many cases, and at the end of a 1MB file it may be massively slower than you were getting in the beginning.

[IMAN4K]

Hi @earlephilhower
Reading the whole 1MB doesn't take longer than 950-1000ms:

		auto f = SPIFFS.open("/samples.csv", "r");
		const auto f_size = f.size();
		uint32_t pos = 0;
		char buff[2048];
		const auto A = millis();
		while (pos < f_size && f.available()) {
			ESP.wdtFeed();
			yield();
			f.seek(pos, fs::SeekMode::SeekSet);
			const auto read = f.readBytes(buff, sizeof(buff));
			pos += read;
		}
		Serial.printf("\n Took: %lums", millis() - A);

[d-a-v]

I think ESP8266HTTPClient::writeToStream() is slow because it uses Stream::readStringUntil('\r') which reads data bytes by bytes.
The above code is faster because it reads blocks.

We definitely need an optimized Stream::stream(Print& out, size_t len).

@IMAN4K can you rewrite the above test with a byte by byte transfer and measure its duration ? (I think with a char buff[1])

[IMAN4K]

@d-a-v
Reading byte by byte takes 161984ms and is 170 times slower!

[IMAN4K]

I'm just curious why in web portal streaming the TCP segment buffer is 1460(1460byte is acknowledged) and in my test 541byte is acknowledged in each transaction?!

:wr 737220 306600
:wrc 1460 737220 0
:ack 1460
:wr 735760 308060
:wrc 1460 735760 0
:ack 1460
:wr 734300 309520
:wrc 1460 734300 0
:ack 1460
:ack 1460
:wr 732840 310980
:wrc 2920 732840 0
:ack 1460
:ack 1460
:wr 729920 313900
:wrc 2920 729920 0
:ack 1460
:ack 1460
:wr 727000 316820
:wrc 2920 727000 0
:ack 1460
:wr 724080 319740
:wrc 1460 724080 0
:ack 1460
:ack 1460
:wr 722620 321200
:wrc 2920 722620 0
:ack 1460
:ack 1460

[d-a-v]

lwIP bufferizes data until full packets can be sent, because of naggle algorithm and also because peer (the server) allows it. Less and bigger packets, more latency, more throughput.
Naggle can be disabled with https.getStream().setNoDelay(true); (more and smaller packets, lower latency).