Hello!

Some times my application was very slow, and I noted that problem could be the write file slowing down the entire application. So I did a very simple example just writing file to demonstrate the BUG.

Some notes:

1. I'm writing ~700 bytes
2. I'm using the asyncio just to write each 6 seconds. In the real application it write each 30 minutes, and, even each 30 minutes the problem happen, rarely, but happen.
3. I did in the code (function timed_function_1) to print the time to write just when the time is bigger than 100ms.
4. I'm using official firmware .bin downloaded from the Micropython.org - is not build from myself.
5. I have just one file in the MicroPython filesystem, just the file that the example are writing. The moremote ls below show that.

Problem:
Mostly times the time to write that 700 bytes is ~50ms, but some times, rarely, the time to write is much more, like as 300ms, 700ms, and some times more than 1 second, and more than two seconds (2922 ms) - look below the output test. As I have others asyncio tasks (and one thread) that need to do their job until 300ms, or even until 1 second. But using that long time to write is a very very big problem, because when the time to write the file is 1 second for example, the entire system is blocked during 1 second, including the thread. I thing if the time to write a file of 700 bytes (doing nothing more tasks as showed in example here), each 6 seconds, or even each 30 minutes, use so long time, it could just be a bug, right?

Yes, I know how is the MicroPython behavior when I write files in the same flash where is the MicroPython firmware. In this case the MicroPython code is blocked, because it is in the same flash. Anyway, 50ms is the normal speed, but from 50 to 300, 500, 700, 1 second, and more than 2 seconds can't have some relation with MicroPython is running in the same flash where I'm writing. Am I correct?

Hardware info:

ESP32-S3-WROOM-1 - ESP32-S3 module from Espressif, 16MB flash and 2MB RAM

MicroPython info:

>>> 
MicroPython v1.21.0 on 2023-10-06; Generic ESP32S3 module with ESP32S3
Type "help()" for more information.
>>> import os
>>> os.uname()
(sysname='esp32', nodename='esp32', release='1.21.0', version='v1.21.0 on 2023-10-06', machine='Generic ESP32S3 module with ESP32S3')
>>> 

The simple code to demonstrate the problem:

import asyncio, json, time

data = {'previous_firmware_version': None, 'wifi_client_operation_mode': 'normal', 'sys_id': 0, 'boot_id': 0, 'hour_meter': 0, 'watchdog_boot_id': 0, 'counter_time_process_temp_delay': {'previous': {'300_ms': 0, '600_ms': 0, '1000_ms': 0, 'max_ms': 0}, 'current': {'300_ms': 0, '600_ms': 0, '1000_ms': 0, 'max_ms': 0}}, 'counter_process': {'counter_process_U': 0, 'counter_process_K': 0, 'counter_process_M': 0, 'counter_process_B': 0}, 'counter_time_write': {'previous': {'100_ms': 0, '200_ms': 0, 'max_ms': 0}, 'current': {'100_ms': 0, '200_ms': 0, 'max_ms': 0}}, 'counter_shorted_sensor': {'c1': 0, 'c2': 0, 'c3': 0, 'c4': 0, 'c5': 0, 'c6': 0}, 'counter_opened_sensor': {'c1': 0, 'c2': 0, 'c3': 0, 'c4': 0, 'c5': 0, 'c6': 0}, 'counter_max_reset': {'c1': 0, 'c2': 0, 'c3': 0, 'c4': 0, 'c5': 0, 'c6': 0}}

def timed_function_1(f, *args, **kwargs):
    try:
        myname = str(f).split(' ')[1]
    except:
        myname = f.__name__
    def time_calc(*args, **kwargs):
        t = time.ticks_ms()
        result = f(*args, **kwargs)
        delta = time.ticks_diff(time.ticks_ms(), t)
        if delta > 100:
            print(f'!!!!!!!---- Function {myname}({time_calc.__name__}) Time = {delta} ms')
        return result
    return time_calc

def json_dumps_now(data: dict) -> str:
    res = json.dumps(data, separators=(',', ':'))
    return res

@timed_function_1
def write_file_as_json(file_name, data):
    res = json_dumps_now(data)
    f = open(file_name, 'w')
    f.write(res)
    f.close()

async def write_file():
    while True:
        await asyncio.sleep(6)
        write_file_as_json('file1.json', data)

async def main():
    task = asyncio.create_task(write_file())
    await task

asyncio.run(main())

Running the code:

$ mpremote ls
ls :
         139 boot.py
         705 file1.json

$ mpremote run asyncio_write_test.py 
!!!!!!!---- Function write_file_as_json(time_calc) Time = 136 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 2922 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 589 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 106 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 1157 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 579 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 116 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 579 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 579 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 126 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 579 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 579 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 589 ms
!!!!!!!---- Function write_file_as_json(time_calc) Time = 579 ms