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

peterbay commented 1 year ago

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

DJDevon3 commented 1 year ago

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

Capture

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 commented 1 year ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 ) -- https://github.com/adafruit/circuitpython/issues/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 commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

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 commented 8 months ago

@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.

adafruit / Adafruit_CircuitPython_HTTPServer

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