mpremote: Can't read file >255bytes from mounted path on ESP32S2

[zcattacz]

mpremote==0.4.0
Official mpy firmware on ESP32S2Mini

user@localhost# mpremote mount .

>>> os.uname()
(sysname='esp32', nodename='esp32', release='1.21.0', version='v1.21.0 on 2023-10-06', machine='Generic ESP32S2 module with ESP32S2')
>>> gc.mem_free()
2054208
>>> len(open("host_config1.json").read())
255 # immediate reply
>>> len(open("host_config2.json","rb").read())
259 # noticable delay
>>> len(open("host_config3.json","rb").read())
268 # 5s later
>>> len(open("host_config_368byte.json","rb").read())
    # endless wait.

Official mpy firmware on Generic ESP32

>>> os.uname()
(sysname='esp32', nodename='esp32', release='1.21.0', version='v1.21.0 on 2023-10-05', machine='Generic ESP32 module with ESP32')
>>> gc.mem_free()
130784
>>> len(open("test_agent.py","rb").read())
18391  # no delay

[zcattacz]

For the above 18k script, mpremote run test_agent.py works without noticeable delay on both ESP32S2 and ESP32.
Am I the only one having this mount issue ?

[zcattacz]

I can confirm this on a second ESP32S2-Mini. When the file is more than ~300byte, mpremote deadlock. ^C is not able to interrupt it. Need to press RST on the board.
If I kill mpremote process, without RST the board. The next mpremote run will stuck after Use Ctrl-] to exit this shell line. The serial line is blocked.

[robert-hh]

There is a problem with the USB port of both ESP32S2 and ESP32S3, when sending/pasting more than about 250 bytes. This happens e.g. as well, if you paste code in paste mode or raw mode. It seems that the USB stack cannot handle input data fast enough. If I add e.g. a delay between lines that are sent it works.

[Josverl]

There is a problem with the USB port of both ESP32S2 and ESP32S3, when sending/pasting more than about 250 bytes.

I think this is about the remote filesystem driver - not about C/P

[Josverl]

May I suggest using a more recent version of mpremote ?
pip install -U mpremote should get you v1.22.0 today which has a significant number of improvements for both the transfer speed as well as for compatibility for the esp32 DTR/RTS idiosyncrasies

[robert-hh]

Even with the 1.22 version of mpremote reading a file > ~300 bytes from a mounted remote locks up.
Edit: If I used f.readlines() instead of f.read() to read from a file f opened at a mounted device, it works. But reading is slow.

[Josverl]

I've done an end-end test with the same code across 5 diferent ports.

• there are very significant differences between the ports
• on most ports (all but ESP32)there is a huge impact of even printing a single character before reading a mounted file, so there is clearly something throttling here. and the ESP32 seems to throttled all the time.
• the ESP32 is slowest of the tested ports

Test to measure the performance of reading a MPremote --mounted filesystem

This test uses a pre-existing function that reads a file from a mounted filesystem to lookup a board's name based on a description.

Requirements:

• a jupyter environment (Vscode or Jupyterlab or Jupyter notebook)
• micropython-magic ( you may need to %load_ext micropython_magic )
• a MCU connected
• this notebook
• a copy of board_info.csv ( adjust the path in the --mount options)

Tests:

1. find a board on line 1 of the file (2 readlines)
2. find a board on line 41 of the file (42 readlines)
3. Read entire file - print(os.listdir()) before file access
4. Read entire file - no print output during file access
5. Read entire file - print(".", end="")-before file access

Summary of the inital test results:

5 different boards, each with micropython v1.22.0

#	esp32	rp2040	stm32	esp32S3	samd51
1	1_148.613ms	96.968ms	47.633ms	166.957ms	55.435ms
2	36_186.832ms	2_575.598ms	1_215.549ms	4_736.842ms	1_627.422ms
3	170_160.422ms	97_ 391.750ms	95_162.203ms	103_133.047ms	95_467.406ms
4	168_729.234ms	12_039.165ms	5_765.905ms	22_183.824ms	7_597.681ms
5	170_168.984ms	97_292.445ms	95_163.602ms	102_089.680ms	95_728.898ms

Notebook and data can be found here :
https://gist.github.com/Josverl/6a8f40da412159330acee84a47ef5a92#file-mpremote_mount_timings-ipynb

[Josverl]

It's the receiving where the ESP32S2/S3 have problems

I think the different timings between test 3 and 4 shows that there is more to it than just the ESP serial interface.
I cant explain that printing a single "." should cause a 50-90% slowdown (on all but esp32)

timings for file.read() for the same dataset
if only this would work on all ports It may be worth trading memory for time

@timed_function
def file_read():
    with open("board_info.csv", "r") as file:
        data = file.read()
    print(len(data))

file_read()

6. file.read() - 8434 bytes

#	esp32	rp2040	stm32(PYBV11)	esp32S3	samd51
6	783.032ms	77.075ms	times-out	777.169ms	50.300ms

[Josverl]

@zcattacz

I woud suggest to all remove prints before or during your test as in my testing they slow down the reads
and repeat your tests

            if len(c) > 0:
                buf += c
                # print(".", end="") # <-- Remove this and repeat your tests 
            else:

[zcattacz]

Thank you for the suggestions, I updated my test accordlingly:

benchmark.py

def read_bcmark_py():
    buf = b""
    with open("_benchmark.py") as fh:
        while True:
            c = fh.read(8*31+7)
            if len(c) > 0:
                buf += c
            else:
                break
    return buf
exec(read_bcmark_py())

_benchmark.py

import time, gc, os
fp = "autorun.py"
def chunkr(ck_sz, fp):
    tsum, bc, lc = 0, 0, 0
    with open(fp) as fh:
        while True:
            t = time.ticks_ms()
            c = len(fh.read(ck_sz))
            tsum += (time.ticks_ms()-t)
            lc += 1
            if c > 0:
                bc += c
            else:
                break
    return tsum, lc, bc

def zeror(times, fp):
    tsum = 0
    with open(fp) as fh:
        for i in range(0,times):
            t = time.ticks_ms()
            c = len(fh.read(0))
            tsum += time.ticks_ms()-t
    return tsum

def benchmark(chunk_size, fp, times=10):
    Tsum, Tmx, Tmn = 0, 0, 0xffff
    Tsum0, Tmx0, Tmn0 = 0, 0, 0xffff
    for i in range(0, times):
        t, lc, bc = chunkr(chunk_size, fp)
        Tsum += t
        Tmn, Tmx = min(Tmn, t), max(Tmx, t)
        if i == 0:
            print(f"Test @chunksize:{chunk_size} total bytes:{bc} read times:{lc}")
        print(f"#{i+1}:{t}ms ", end="")
        t = zeror(lc, fp)
        Tsum0 += t
        Tmn0, Tmx0 = min(Tmn0, t), max(Tmx0, t)
    print(f"")
    print(f"    per file: took max:{Tmx}ms\tmin:{Tmn}ms\tavg:{Tsum/times}ms")
    print(f"    per read: took max:{Tmx/(lc)}\tmin:{Tmn/(lc)}\tavg:{Tsum/(lc*times)}")
    print(f"   zero read: took max:{Tmx0/(lc)}\tmin:{Tmn0/(lc)}\tavg:{Tsum0/(lc*times)}")
    print(f"net per read: took max:{(Tmx-Tmx0)/(lc)}\tmin:{(Tmn-Tmn0)/(lc)}\tavg:{(Tsum-Tsum0)/(lc*times)}")
    print(f"net per byte: took max:{(Tmx-Tmx0)/(lc*chunk_size)}\ttmin:{(Tmn-Tmx0)/(lc*chunk_size)}\tavg:{(Tsum-Tsum0)/(lc*times*chunk_size)}")

gc.collect()
print(os.uname())
if "ESP32S2" in os.uname().machine or "ESP32-S2" in os.uname().machine:
    for i in [10*8, 20*8, 30*8, 31*8+1]:
        benchmark(i, fp); gc.collect()
elif "ESP32 " in os.uname().machine:
    for i in [64*8, 128*8, 512*8, 1024*8]:
        benchmark(i, fp); gc.collect()

Results:

mpremote mount -l mount-dir

>>> import benchmark
(sysname='esp32', nodename='esp32', release='1.21.0', version='v1.21.0 on 2023-10-06', machine='LOLIN_S2_MINI with ESP32-S2FN4R2')
Test @chunksize:80 total bytes:18809 read times:237
#1:2206ms #2:2621ms #3:2268ms #4:2508ms #5:2568ms #6:1922ms #7:2484ms #8:2021ms #9:2141ms #10:2719ms 
    per file: took max:2719ms   min:1922ms      avg:2345.8ms
    per read: took max:11.47257 min:8.109705    avg:9.89789
   zero read: took max:11.13924 min:8.827004    avg:10.02447
net per read: took max:0.3333333        min:-0.7172996  avg:-0.1265823
net per byte: took max:0.004166667      tmin:-0.0378692 avg:-0.001582278
Test @chunksize:160 total bytes:18809 read times:119
#1:1159ms #2:1179ms #3:1028ms #4:1170ms #5:1151ms #6:1437ms #7:1111ms #8:1157ms #9:1171ms #10:1328ms 
    per file: took max:1437ms   min:1028ms      avg:1189.1ms
    per read: took max:12.07563 min:8.638656    avg:9.992437
   zero read: took max:12.55462 min:7.739496    avg:9.636134
net per read: took max:-0.4789916       min:0.8991596   avg:0.3563025
net per byte: took max:-0.002993698     tmin:-0.02447479        avg:0.002226891
Test @chunksize:240 total bytes:18809 read times:80
#1:797ms #2:705ms #3:869ms #4:807ms #5:1096ms #6:781ms #7:845ms #8:792ms #9:748ms #10:972ms 
    per file: took max:1096ms   min:705ms       avg:841.2ms
    per read: took max:13.7     min:8.8125      avg:10.515
   zero read: took max:11.0     min:6.9875      avg:9.37
net per read: took max:2.7      min:1.825       avg:1.145
net per byte: took max:0.01125  tmin:-0.009114582       avg:0.004770833
Test @chunksize:249 total bytes:18809 read times:77
#1:681ms #2:850ms #3:863ms #4:880ms #5:885ms #6:853ms #7:965ms #8:773ms #9:692ms #10:1007ms 
    per file: took max:1007ms   min:681ms       avg:844.9ms
    per read: took max:13.07792 min:8.844156    avg:10.97273
   zero read: took max:11.93507 min:7.844156    avg:10.36883
net per read: took max:1.142857 min:1.0 avg:0.6038961
net per byte: took max:0.004589787      tmin:-0.01241329        avg:0.002425285
>>>

mpremote mount -l mount-dir
>>> import benchmark
(sysname='esp32', nodename='esp32', release='1.21.0', version='v1.21.0 on 2023-10-05', machine='Generic ESP32 module with ESP32')
Test @chunksize:512 total bytes:18809 read times:38
#1:2222ms #2:2228ms #3:2229ms #4:2229ms #5:2229ms #6:2229ms #7:2230ms #8:2230ms #9:2230ms #10:2222ms 
    per file: took max:2230ms   min:2222ms      avg:2227.8ms
    per read: took max:58.68421 min:58.47368    avg:58.62632
   zero read: took max:20.0     min:20.0        avg:20.0
net per read: took max:38.68421 min:38.47368    avg:38.62632
net per byte: took max:0.0755551        tmin:0.07514391 avg:0.07544202
Test @chunksize:1024 total bytes:18809 read times:20
#1:2047ms #2:2046ms #3:2046ms #4:2046ms #5:2046ms #6:2046ms #7:2046ms #8:2046ms #9:2046ms #10:2046ms 
    per file: took max:2047ms   min:2046ms      avg:2046.1ms
    per read: took max:102.35   min:102.3       avg:102.305
   zero read: took max:20.0     min:20.0        avg:20.0
net per read: took max:82.35    min:82.3        avg:82.305
net per byte: took max:0.08041992       tmin:0.08037109 avg:0.08037598
Test @chunksize:4096 total bytes:18809 read times:6
#1:1730ms #2:1730ms #3:1730ms #4:1730ms #5:1740ms #6:1730ms #7:1730ms #8:1730ms #9:1730ms #10:1740ms 
    per file: took max:1740ms   min:1730ms      avg:1732.0ms
    per read: took max:290.0    min:288.3333    avg:288.6667
   zero read: took max:20.0     min:20.0        avg:20.0
net per read: took max:270.0    min:268.3333    avg:268.6667
net per byte: took max:0.06591797       tmin:0.06551107 avg:0.06559244
Test @chunksize:8192 total bytes:18809 read times:4
#1:1710ms #2:1710ms #3:1710ms #4:1710ms #5:1710ms #6:1710ms #7:1710ms #8:1710ms #9:1710ms #10:1710ms 
    per file: took max:1710ms   min:1710ms      avg:1710.0ms
    per read: took max:427.5    min:427.5       avg:427.5
   zero read: took max:20.0     min:20.0        avg:20.0
net per read: took max:407.5    min:407.5       avg:407.5
net per byte: took max:0.04974365       tmin:0.04974365 avg:0.04974365
>>> 

Now it makes more sense. read(0) on ESP32 has a constant 20ms delay, while on ESP32S2 varies around 10ms. Its cheaper to call read() on ESP32S2, so chunk_read seems more viable.
Also have a look at the funny negative numbers, they disappeared after chunksize reach +240b.
@Josverl Maybe you'll be interested to check read(0) in your test on other ports ?

[Josverl]

I'm away from home, so not for another week or more

[zcattacz]

Hi @robert-hh , can this be optimized in mpy? I can't import most of my modules on ESP32S2 from mounted dir due to this issue.

[robert-hh]

At the first glance, it looks like a problem in the esp-idf, not calling the TinyUSB callback immediately when data arrives, but only on schedule. That could be bypassed in mpremote by throttling the data rate, but that would not fix other situations when the device locks up.