Pico W need too much time for receiving request data in random cases #46

peterbay · 2023-04-06T19:31:50Z

I have a for example a small web page with repeated ajax requests. Page is sending one request per second and server on Pico W needs different times for processing same request. In my case it varies between 40 ms and 250 ms.

I expected the time for processing the request to be approximately in the range of 40 to 80ms.

Connection to Pico is fast and when i added some debug prints to poll() function in server.py, then i found, that the bottleneck is function - self._receive_header_bytes(conn)

   def poll(self):
        try:
            conn, client_address = self._sock.accept()

            with conn:
                conn.settimeout(self._timeout)

                start_msecs = supervisor.ticks_ms()

                # Receiving data until empty line
                header_bytes = self._receive_header_bytes(conn)

                print(f"time to receive header bytes: {supervisor.ticks_ms() - start_msecs} ms")

                # Return if no data received

example of printed output (it's not the same sample as shown in image)

time to receive header bytes: 157 ms
time to receive header bytes: 1 ms
time to receive header bytes: 152 ms
time to receive header bytes: 1 ms
time to receive header bytes: 129 ms
time to receive header bytes: 1 ms
time to receive header bytes: 12 ms
time to receive header bytes: 95 ms
time to receive header bytes: 210 ms
time to receive header bytes: 1 ms
time to receive header bytes: 12 ms
time to receive header bytes: 1 ms
time to receive header bytes: 46 ms
time to receive header bytes: 1 ms
time to receive header bytes: 167 ms
time to receive header bytes: 188 ms
time to receive header bytes: 199 ms
time to receive header bytes: 208 ms

example code:

import os
import time
import ipaddress
import wifi
import socketpool

import microcontroller

from adafruit_httpserver.server import HTTPServer
from adafruit_httpserver.request import HTTPRequest
from adafruit_httpserver.response import HTTPResponse
from adafruit_httpserver.methods import HTTPMethod
from adafruit_httpserver.mime_type import MIMEType
from adafruit_httpserver.status import CommonHTTPStatus

#  set static IP address
ipv4 = ipaddress.IPv4Address("192.168.88.99")
netmask = ipaddress.IPv4Address("255.255.255.0")
gateway = ipaddress.IPv4Address("192.168.88.1")

wifi.radio.set_ipv4_address(ipv4=ipv4, netmask=netmask, gateway=gateway)
#  connect to your SSID
wifi.radio.connect(
    os.getenv("CIRCUITPY_WIFI_SSID"), os.getenv("CIRCUITPY_WIFI_PASSWORD")
)

print("Connected to WiFi")
pool = socketpool.SocketPool(wifi.radio)
server = HTTPServer(pool)

@server.route("/")
def base(request: HTTPRequest):  # pylint: disable=unused-argument
    with HTTPResponse(request, content_type=MIMEType.TYPE_HTML) as response:
        response.send("""
<html>
    <header>
        <script>
            const ajax = function (opt, cb) {
                const headers = opt.headers || {},
                    body = opt.body || "",
                    xhr = new XMLHttpRequest();

                xhr.open(opt.method || (body ? "POST" : "GET"), opt.url || "/", true);
                xhr.ontimeout = xhr.onabort = xhr.onerror = function (e) {
                    console.error("XHR error: ", e, "opt: ", opt);
                };
                xhr.onreadystatechange = function () {
                    if (xhr.readyState === 4) {
                        cb(xhr.status, xhr.response || xhr.responseText);
                    }
                };
                headers["Content-Type"] = headers["Content-Type"] || "application/x-www-form-urlencoded";
                for (const f in headers) {
                    xhr.setRequestHeader(f, headers[f]);
                }
                xhr.send(body);
            };

            function ajaxRequest(request, interval) {
                const ax = function () {
                    ajax(request, function (code, response) {
                        if (code == 200 && response) {
                            console.log("response", response);
                        }
                        if (interval) {
                            setTimeout(ax, interval);
                        }
                    });
                };
                ax();
            }

            data = {"id":"sw1","value":true}
            intervalMs = 1000

            ajaxRequest({ url: "/api", method: "POST", headers: { "Content-Type": "application/json" }, body: JSON.stringify(data) }, intervalMs);

        </script>
    </header>
    <body>
        sapmle page with ajax request every 1 second
    </body>
</html>""")


@server.route("/api", HTTPMethod.POST)
def base(request: HTTPRequest):
    print("api request", request.body)
    with HTTPResponse(request, content_type=MIMEType.TYPE_JSON) as response:
        response.send('{"status": "ok"}')


print("starting server..")
# startup the server
try:
    server.start(str(wifi.radio.ipv4_address))
    print("Listening on http://%s:80" % wifi.radio.ipv4_address)
    
#  if the server fails to begin, restart the pico w
except OSError:
    time.sleep(5)
    print("restarting..")
    microcontroller.reset()

while True:
    try:
        server.poll()

    except Exception as e:
        print(e)
        continue

The text was updated successfully, but these errors were encountered:

DJDevon3 · 2023-04-06T19:47:11Z

I've run Peterbay's example and can confirm there is a server response lag issue with the Pico W. It's the only board I helped test with. Approximately 216-250ms on average for me. Discord troubleshooting conversation.

Running on the latest nightly build from S3 Bucket with updated 8x PY library from Github

Adafruit CircuitPython 8.1.0-beta.1-10-g6df88ac94 on 2023-04-05; Raspberry Pi Pico W with rp2040
Board ID:raspberry_pi_pico_w

No idea if this is an HTTPServer or Pico W issue specifically. It seemed to fight web workflow for port 80? I tried changing the server port to 81 but that didn't work. It's only sending 106 bytes so one would reasonably assume the response should be much faster than 250ms. More testing is needed.

anecdata · 2023-04-06T20:18:18Z

Running web workflow and an adafruit_httpserver simultaneously should be no problem on separate ports. But I'd suggest disabling web workflow for this testing to get cleaner data for this issue.

I don't think it's specific to Pico W. On an ESP32-S3, my browser shows typical times of a couple hundred ms. I split up poll() into timed sections , and there's quite a bit of variance between requests:

-------------------------
header 0.004s
request 0.009s
remainng body bytes 0.002s
api request b'{"id":"sw1","value":true}'
handler 0.136s
-------------------------
header 0.004s
request 0.078s
remainng body bytes 0.002s
api request b'{"id":"sw1","value":true}'
handler 0.080s
-------------------------
header 0.125s
request 0.009s
remainng body bytes 0.070s
api request b'{"id":"sw1","value":true}'
handler 0.013s
-------------------------
header 0.004s
request 0.009s
remainng body bytes 0.003s
api request b'{"id":"sw1","value":true}'
handler 0.083s
-------------------------
header 0.126s
request 0.009s
remainng body bytes 0.002s
api request b'{"id":"sw1","value":true}'
handler 0.012s
-------------------------
header 0.004s
request 0.078s
remainng body bytes 0.002s
api request b'{"id":"sw1","value":true}'
handler 0.081s

MyRaspberry · 2023-12-15T12:20:33Z

problems upgrading to CP828, 829, 900a5, 900a6

PICO W with web-server and mqtt and mqtt client ( remote command )

i have specific timing issues with
http_server.poll() ( now i run only every second once )
mqtt.mqtt_client.loop ( now i run only every second once, still with this my app goes from 1000 loops/sec to 100 loops/sec )

while back in February CP802 . 810 it worked.

michalpokusa · 2023-12-15T12:41:59Z

problems upgrading to CP828, 829, 900a5, 900a6

PICO W with web-server and mqtt and mqtt client ( remote command )

i have specific timing issues with http_server.poll() ( now i run only every second once ) mqtt.mqtt_client.loop ( now i run only every second once, still with this my app goes from 1000 loops/sec to 100 loops/sec )

while back in February CP802 . 810 it worked.

Can you provide some more details, maybe even code? I think it is more probable that the library itself changed and not CircuitPython, but I may be wrong as I do not really understand your problem at the moment.

MyRaspberry · 2023-12-15T15:37:13Z

well, i started to change all code from the 'old' but in February working

from adafruit_httpserver.server import HTTPServer
server = HTTPServer(pool)

to the new version without "HTTP"
so yes, the library change in that time upto CP828 too.
but how i know what was changed.

while the adafruit_minimqtt.adafruit_minimqtt lib looks like it did not change in that time?
so timing issue most likely in the timing / socket...

same about that the mqtt TLS problem what was solved back then,
i have again, what was also CP timing problem and probably is again.

my GIT only has the working version, is bigger project, so how can i help?

let's start with the timing of server.poll()
how i can get into this:
? it is supposed to be called from the main loop?
but it is not supposed to block all the timing of my multi ( timed ) job structure.
so i put it in my 1 sec loop to get anything running.
and a short timecheck shows that 1 in 10 time it needs 0.004 sec ( without a call from a browser )
like it hangs internally ?waiting ?

with this question?
can you give me a code i can run on pico w under CP900a6?
to check? and crosscheck under CP802? where some diagnostic is enabled?

new test see
https://github.com/MyRaspberry/PICO_W_WEBtest/

michalpokusa · 2023-12-16T00:14:51Z

The repository you linked is either private or already deleted.

I still do not completely understand you problem, but regarding to what I understood:

Server.poll() is blocking, but most of the time if there is no request is blocks for a very small fraction of a second
When it comes to timing, I think the async/await approach might be the way to go, please refer to https://github.com/adafruit/Adafruit_CircuitPython_HTTPServer/blob/main/examples/httpserver_websocket.py for example of implementing this. You could replace the Websocket stuff with MQTT, I think this will work as you expect.
Check the adafruit_httpserver documentation for latest api reference, I highly recommend not using the old version of library, it possibly contains bugs that were fixed in current version and might not implement some security measures

MyRaspberry · 2023-12-16T01:33:06Z

thank for the answer.
-0- sorry i missed that / repository is now public

-1- yes, blocking for short time
but see my testreport it's unusable in main loop

-2- NOT UNDERSTAND test 3: asyncio import failed

-3- yes, i used the latest bundle
but i have a question:
in that cp900a6 bundle used lib is
https://github.com/adafruit/Adafruit_CircuitPython_HTTPServer/blob/main/adafruit_httpserver/server.py ?
see -0- i documented also what files i used

-4- i made a test2
using that server.py source instead server.mpy
and enable debug
but not see a poll debug timing
only a response timing when the auto refresh calls
how to do that?

-5- looks like add to the timing problem there is also a memory problem ( that why i needed many gc.collect )
then i can use it with mqtt ( my PID repository )
but still not with a mqtt client call like for my
https://github.com/MyRaspberry/PICO_W_MQTT_RPI_broker
needed.
in my test there was a loop with server.poll in MAIN
mem: 52160 mem low: 672 ? // mem runs down but autorecovers ?

michalpokusa · 2023-12-16T22:32:47Z

So, regarding the debug mode, it only prints a timing after, and only after handling the response, if poll() did not handle any response (e.g. there was not request), it simply does not print anything. If you want the timing of every poll(), you would have to change the code to do that.

Next thing, if importing asyncio fails, you have to install it.

I think the gc.collect, even if works in your case, is not the way to go, there is probably something else that causes problems with memory, either your code or a library itself.

Please follow the instruction I attached and i suggest posting your problem on Adafruits IDscord server, there are more people that could help with this. This is also a better place, because I believe at this point we are discussing a specific scenario and not really a issue with library itself.

MyRaspberry · 2023-12-17T02:01:03Z

Next thing, if importing asyncio fails, you have to install it.

sorry, thanks, now i found the TICKS library in the bundle
and will work on that test.

"Please follow the instruction I attached"
? what you ref to?

"not really a issue with library itself."
? pls keep in mind that my question comes from a running project
PICO W: http_server and minimqtt under CP802
and the upgrade to current CP's fails for issues regarding

memory
-- http://kll.byethost7.com/kllfusion01/downloads/server_poll_memory.png
timing
TLS (again )
-- minimqtt lib problem with TLS broker circuitpython#7606
like with the TLS back then it was not a library problem, instead a CP timing problem

this might be here as well, i hoped with YOU we can prove it's NOT the library
? just say the library for server.poll has not changed? was only renamed regarding "HTTP"
so i can post a issue at the right place.
( as you asked for a example code, the https://github.com/MyRaspberry/PICO_W_WEBtest/
is only about the server.poll() )

-- sure i asked at Discord server already

i now did tests using CP810 HTTPServer ( code changes )
+++ see 50kB more free RAM

!! back in CP810 i already did use server.poll() NOT in the MAIN loop because of timing issues,

michalpokusa · 2023-12-17T04:19:02Z

Please read to the end.

I you were using the adafruit_httpserver version taht used "HTTP..." prefixes, it probably was 2.x.x or 3.x.x, as they were removed in 4.0.0.

The library got a lot of upgrades since then, here is the diff between 3.0.2 (latest version that used HTTP... prefix) and most recent version: https://github.com/adafruit/Adafruit_CircuitPython_HTTPServer/compare/3.0.2..main#diff-8ebe9b561a5a0efd5ca358f890968beb81364bca15e851add61ee7f09feef016R352

So, the server.poll did change, similary to many different parts of the lib. Nevertheless, it shouldn't cause such problems with memory.

I investigated a bit more and here is what I found:

Only 4048 left!

As you can see, import fail at adafruit_datetime, even when it is the first module to import.

But, on CircuitPython 8.2.9, it works normally:

So, my guess is, CircuitPython 9.x.x changed something regarding memory allocation. I was able to find this live from Adafruits YT channel, when they show something that looks like the problem presented here.

@tannewt maybe you could shine some light onto this?

MyRaspberry · 2023-12-17T05:46:59Z

thanks!
this mem and timing issues made me fight on all fronts:
like after reading your doc examples i changed from

HTTP_INDEX = ""
HTTP_INDEX += "more html"

to your style:

HTTP_INDEX = '''
html
[tab]more
[tab][tab]even more
'''

because i wanted to make my code so beautiful pythonic like yours.
but one night i wake up understanding each [tab] are 4[space]
! taken FROM RAM !
and i deleted all [tab] and free 1kB !!!!
still possibly many [cr][lf] bytes inside this string.

and the later HTML_INDEX.format()
? does it make a copy / meaning 2 times the RAM ?
b.r. KLL

MyRaspberry · 2023-12-17T06:37:58Z

Only 4048 left!
with
import adafruit_datetime

i use only

>>> from adafruit_datetime import datetime
>>> gc.mem_free()
103152
>>>

report from inside the test code:

FREE MEM report after imports
+ import gc 124032 
+ import os 123904 
+ import time 123824 
+ from adafruit_datetime import  datetime 99184 
+ import rtc 99072 
+ import adafruit_ntp 98144 
+ import socketpool 98064 
+ from ipaddress 97952 
+ import wifi 97872 
+ from adafruit_httpserver import Server, Request, Response, Redirect, GET, POST, Websocket 53408 
+ import micropython 53200 
+ import microcontroller 53120

rem: see above, under CP810 i had 50kB more free mem, eaten half half by CP900a6 and httpserver.Server

FREE MEM report after imports
+ import gc 149888 
+ import os 149776 
+ import time 149680 
+ from adafruit_datetime import  datetime 123280 
+ import rtc 123152 
+ import adafruit_ntp 121696 
+ import socketpool 121600 
+ from ipaddres import ip_address 121504 
+ import wifi 121392 
+ from adafruit_httpserver.server import HTTPServer 105984 
+ from adafruit_httpserver.request import HTTPRequest 105808 
+ from adafruit_httpserver.response import HTTPResponse 105680 
+ from adafruit_httpserver.methods import HTTPMethod 105552 
+ from adafruit_httpserver.mime_type import MIMEType 105424 
+ import micropython 105312 
+ import microcontroller 105184

tannewt · 2024-01-16T23:07:07Z

@tannewt maybe you could shine some light onto this?

Yes, memory management has changed in 9.x. CP now has an outer heap that persists over multiple VM runs and the VM heap is split into multiple allocations into the outer heap. This will change the mem_free() reporting a bit because it doesn't include absolutely all memory free in the outer heap. It also can make it harder to do large allocations when the outer heap is fragmented.

You should make sure to run gc.collect() before gc.mem_free() to ensure that memory that isn't needed has been freed. A successful import will run collect() but a failed one won't.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Pico W need too much time for receiving request data in random cases #46

Pico W need too much time for receiving request data in random cases #46

peterbay commented Apr 6, 2023

DJDevon3 commented Apr 6, 2023

anecdata commented Apr 6, 2023 •

edited

Loading

MyRaspberry commented Dec 15, 2023 •

edited

Loading

michalpokusa commented Dec 15, 2023

MyRaspberry commented Dec 15, 2023 •

edited

Loading

michalpokusa commented Dec 16, 2023

MyRaspberry commented Dec 16, 2023 •

edited

Loading

michalpokusa commented Dec 16, 2023

MyRaspberry commented Dec 17, 2023 •

edited

Loading

michalpokusa commented Dec 17, 2023

MyRaspberry commented Dec 17, 2023

MyRaspberry commented Dec 17, 2023 •

edited

Loading

tannewt commented Jan 16, 2024

Pico W need too much time for receiving request data in random cases #46

Pico W need too much time for receiving request data in random cases #46

Comments

peterbay commented Apr 6, 2023

DJDevon3 commented Apr 6, 2023

anecdata commented Apr 6, 2023 • edited Loading

MyRaspberry commented Dec 15, 2023 • edited Loading

michalpokusa commented Dec 15, 2023

MyRaspberry commented Dec 15, 2023 • edited Loading

michalpokusa commented Dec 16, 2023

MyRaspberry commented Dec 16, 2023 • edited Loading

michalpokusa commented Dec 16, 2023

MyRaspberry commented Dec 17, 2023 • edited Loading

michalpokusa commented Dec 17, 2023

MyRaspberry commented Dec 17, 2023

MyRaspberry commented Dec 17, 2023 • edited Loading

tannewt commented Jan 16, 2024

anecdata commented Apr 6, 2023 •

edited

Loading

MyRaspberry commented Dec 15, 2023 •

edited

Loading

MyRaspberry commented Dec 15, 2023 •

edited

Loading

MyRaspberry commented Dec 16, 2023 •

edited

Loading

MyRaspberry commented Dec 17, 2023 •

edited

Loading

MyRaspberry commented Dec 17, 2023 •

edited

Loading