Mem Alloc Failed - dispite having ample 'free()' memory

[mungewell]

I am seeing memory issues, again. This time is to a call to a 3rd party 'config' library
https://github.com/aleppax/upyftsconf

When my code issue a call to update the config (file), it fails with error about allocating 1148 bytes.

My code, with gc.collect() and gc.free() immediately before

                                    # Force Garbage collection
                                    gc.collect()
                                    print("Free Mem", gc.mem_free())

                                    config.set('calibration', format, adj_avg.read())
                                    config.set('calibration', 'period', period)

Error printed, via UART console. Timestamping on the PC with GrabSerial script.

[542.043912 1.033591] 21:39:10:03 0.0006966665 3.037203e-05 -0.01999711 28.64232 0.01439514 P-T2 (-0.01518601, -0.004811092, 0.0)
[542.080518 0.036606] Free Mem 129408
[542.106663 0.026145] Could not read file:  libs/config.py
[542.131156 0.024493] Could not write file:  libs/config.py
[542.131613 0.000458] memory allocation failed, allocating 1148 bytes
[542.156984 0.025371] Could not read file:  libs/config.py
[542.180909 0.023924] Could not write file:  libs/config.py
[542.181363 0.000454] memory allocation failed, allocating 1148 bytes

I don't know if I can reduce this to a simple example, but I can put SWD/GDB into action given some guidance.

[mungewell]

On frequency of issue: ~2 out of 10 calibration runs, but seemingly random.

Each run is 10mins, unit powered off in between.

simon@the-void:~/pico-timecode-sdw-github/test_scripts/calibration/20240320_t2_config/ttyACM1$ grep file *
2024-03-20_17:00:24:[541.060974 0.025617] Could not read file:  libs/config.py
2024-03-20_17:00:24:[541.084967 0.023993] Could not write file:  libs/config.py
2024-03-20_17:00:24:[541.109636 0.024149] Could not read file:  libs/config.py
2024-03-20_17:00:24:[541.133199 0.023563] Could not write file:  libs/config.py
2024-03-20_17:12:23:[542.066201 0.025462] Could not read file:  libs/config.py
2024-03-20_17:12:23:[542.090161 0.023960] Could not write file:  libs/config.py
2024-03-20_17:12:23:[542.114757 0.024031] Could not read file:  libs/config.py
2024-03-20_17:12:23:[542.138308 0.023551] Could not write file:  libs/config.py
simon@the-void:~/pico-timecode-sdw-github/test_scripts/calibration/20240320_t2_config/ttyACM1$ ls
2024-03-20_16:24:28  2024-03-20_16:48:26  2024-03-20_17:12:23  2024-03-20_17:36:19  2024-03-20_18:00:16
2024-03-20_16:36:26  2024-03-20_17:00:24  2024-03-20_17:24:21  2024-03-20_17:48:18  2024-03-20_18:12:15

[mungewell]

It was suggested to try micropython.mem_info(). This causes 100% failure, which I think is due to delay whilst writing via the (USB) UART, ie through a different mechanism.

Here's an example where alloc also failures afterwards.

[540.923311 0.996246] 15:38:02:02 -0.0005333335 -0.0001899611 -0.1778656 18.71783 -0.2798076 P-T1 (0.09498052, -0.2728461, 0.0)
[540.955715 0.032404] Free Mem 128736
[540.964507 0.008791] stack: 660 out of 7936
[540.964792 0.000285] GC: total: 233408, used: 104864, free: 128544
[540.965308 0.000516]  No. of 1-blocks: 2998, 2-blocks: 247, max blk sz: 256, max free sz: 66
[540.966714 0.001406] GC memory layout; from 20007040:
[540.967134 0.000420] 00000000: MDMLhhLhDMhLhhhDhhhDBDBh===BFB=hh====B=BBBBBhB=BhB=BBBhB=hBhB=Bh
[540.968028 0.000893] 00000400: ===DB=h===========h===================BBBhMDh=hh========h=======
[540.968865 0.000837] 00000800: ==========h=====================================================
[540.969802 0.000937] 00000c00: ==========h=====================================================
...
[541.164795 0.000810] 00038c00: ......F......F............F.....................F......F....
[541.165570 0.000774] Mem_info None
[541.180828 0.015258] Could not read file:  libs/config.py
[541.204294 0.023466] Could not write file:  libs/config.py
[541.204762 0.000468] memory allocation failed, allocating 1148 bytes
[541.228956 0.024194] Could not read file:  libs/config.py
[541.252563 0.023607] Could not write file:  libs/config.py
[541.253136 0.000573] memory allocation failed, allocating 1148 bytes

fail_mem_info.txt

[scruss]

See errors Could not read file: libs/config.py

But in trying this library: it does very non-library things. Is it trying to write to itself? Yes it is! Eek! ⚠️ And it's looking for a specially formatted comment to write its data above! https://github.com/aleppax/upyftsconf/blob/6b2338255f8b5706bf80c23fd327f80da03c99d0/config.py#L26C1-L27C62 ⚠️

Please consider using json for persistent storage instead.

[mungewell]

I think I have a solution.

I may have to re-consider the 'config solution' in the future, but for now this it is NOT the problem. Looking at the mem_info() output (and reading what it it all means) made me realize that the memory is heavily fragmented with 'F' all over the place - I made the connection that these are from the 'rolling average' class I have.

The dumb thing is that these are used during the calibration process, but not needed afterwards. I even have a purge() function in the class, which I was not calling.... D'oh.

Add the purge() before writing to the config and all is well. 40 calibration cycles, across two units and no errors.

These show how much I was able to recover.
before.txt
after.txt