Skip to content

Changed read counter to read timeout #2

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Oct 2, 2022
Merged

Conversation

tobozo
Copy link
Contributor

@tobozo tobozo commented Oct 1, 2022

Retry counter was getting exhausted too fast when using ethernet, which appears to be much slower than WiFi, here's how I solved it:

  • Removed the INFLATOR_STREAM_DELAY_CTR macro
  • Added new INFLATOR_STREAM_TIMEOUT_MS macro
  • Replaced the counter logic by a condition based on timeout

Also ESP_LOGD wasn't working and I figured this could help:

  • Replaced ESP_LOG*() functions with their Arduino log_*() counterpart which stick better to the debug level chosen from the tools menu, and also because most CONFIG_LOG_* macros are hardcoded and ESP_LOGD/ESP_LOGV macros are useless

Note: for real efficiency the INFLATOR_STREAM_TIMEOUT_MS should always be bigger than the client timeout (e.g. 10 seconds is acceptable with network, 2 seconds is okay with filesystem) so maybe it should have a getter/setter ?

@vortigont
Copy link
Owner

vortigont commented Oct 1, 2022

Hi @tobozo,
tnx for raising this. Actually it is more complicated than it may seem.
Stream class internally already has the same algo that you've proposed here and readBytes() call is blocking until internal timeout expires. So Stream controls incoming rate of data flow itself. My counter there is just a leftovers trying to resolve issue #1. Not that it helped in any way :) I forgot to remove it after finding root cause.
It defines how long I can block the Inflator awaiting an empty Stream to receive anything on each buffer refill cycle. Having 10 sec timeout on each 128 bytes read (not counting internal Stream's delays) could potentially block Inflator for minutes if not hours :)
As I understood you meant 10 sec global timeout for the Stream, no?
I do not like the idea of blocking code from the first point. So I was thinking about spawning a separate vTask for Stream updater and run it asynchronously. But after implementing this optimization the whole update takes about 10 sec over WiFi. Can you tell more about this issue with Ethernet? Why is it that slow?

As for the ESP_LOG* macros is works pretty good for me. It does not work for your setup? Verbosity level could be controlled via -DLOG_LOCAL_LEVEL=ESP_LOG_DEBUG build flag. You can check platformio.ini configuration for debug build. I use ESP-IDF macro's trying not to depend on Arduino's code if possible. I.e. I have another lib that could be used under pure ESP-IDF without Arduino's framework.

@tobozo
Copy link
Contributor Author

tobozo commented Oct 1, 2022

The Ethernet device runs on SPI bus at 20MHz, and even though it's connected to a fibre network it still has more latency than using WiFi, maybe Stream internal timeout is too short for Ethernet? This comforts the idea of a setter :-)

This is the sketch I've been testing with:

https://github.com/tobozo/ESP32-ENC28J60/tree/main/examples/FOTA

Before this PR, the test on the magic byte failed every time with flashZ and esp32-targz (the stream->peek() always returned -1), so I modified esp32-FOTA with the while(!stream,available()) workaround, then I had a successful magic byte read.

However after unlocking that, firwmare decompression was done only partially and eventually died with a zlib/gz read error (both with flashZ and esp32-targz).

It's only after I applied the same while(!stream,available()) workaround to the decompression libraries and esp32-FOTA that I got a successful result in all situations.

Having 10 sec timeout on each 128 bytes read

From what I've observed when receiving a compressed firmware over a TLS connection, the timeout opportunities happen every time 16384 bytes are read from the Ethernet stream, and they vary between 30ms and 3000ms.

10s was just an excessively high value to make sure it's higher than any other timeout in the lwip stack

your PR looks interesting, and tasmota is reactive as usual :p

@vortigont vortigont merged commit b4bb4e8 into vortigont:main Oct 2, 2022
@vortigont
Copy link
Owner

Before this PR, the test on the magic byte failed every time with flashZ and esp32-targz (the stream->peek() always returned -1)

that looks strange to me. If this Stream obtained from an HTTP client object that means at least headers are already know and must reside somewhere in the buffers. So peeking a first byte of a request body should not be delayed at all.
I do not have ethernet modules to test, but my guts tells me that the root cause of this issue is somewhere else. Anyway this change should not affect normal operations so let's have it merged as a short term solution until we find a more appropriate way to handle this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants