[Ovmsdev] V3 progress

Mon Oct 23 13:59:41 HKT 2017

On Sun, 22 Oct 2017, Stephen Casner wrote:

> However, while checking about that leak I see what looks like a leak
> of another 108-byte block every time the tick script runs.  I have not
> identified that yet.

I don't have the answer yet regarding why this memory is leaked, but I
can answer how it is leaked. The following may serve as an example for
using the debugging tools I've implemented to explore other memory
leaks.

First, I use the 'module memory' command before and after the event
that causes the leak to see what it looks like:

OVMS > module memory
============================
Free 8-bit 37284/217136, 32-bit 18588/43560, numafter = 950
============================
I (172019) script: Running script /store/events/ticker.10/tick
OVMS > module memory
============================
Free 8-bit 37176/217136, 32-bit 18588/43560, numafter = 951
task=Tmr total=      0   2752      0 change=     +0   +108     +0
============================

Here 108 bytes are leaked each time the script runs.  This could be
more than one block, but I've seen this size before and am guessing
that it is one block.  Since I don't know where the allocation is
occurring, I can use the "module abort" command to force an abort at
the point where the allocation is made.  The abort is restricted to
allocations made by the named task and for a particular size since
there may be other blocks of different sizes successfully allocated
and freed.

OVMS > module abort ?
Usage: module abort <task> <count> [<size>]
OVMS > module abort Tmr 1 108
OVMS > abort() was called at PC 0x40085a3b on core 0
0x40085a3b: mem_malloc_block at /Users/casner/src/github/esp-idf/components/freertos/./heap_regions_debug.c:214

[snip the automatic backtrace since gdb's is better]

Entering gdb stub now.
[more snip]
Remote debugging using /dev/cu.SLAB_USBtoUART
0x40088c8c in invoke_abort () at /Users/casner/src/github/esp-idf/components/esp32/./panic.c:125
125	        *((int*) 0) = 0;
(gdb) bt
#0  0x40088c8c in invoke_abort () at /Users/casner/src/github/esp-idf/components/esp32/./panic.c:125
#1  0x40088d5a in abort () at /Users/casner/src/github/esp-idf/components/esp32/./panic.c:134
#2  0x40085a3e in mem_malloc_block (data=0x3fffb400) at /Users/casner/src/github/esp-idf/components/freertos/./heap_regions_debug.c:214
#3  0x4008547a in pvPortMallocTagged (xWantedSize=<optimized out>, tag=<optimized out>) at /Users/casner/src/github/esp-idf/components/freertos/./heap_regions.c:308
#4  0x4008938b in pvPortMallocCaps (xWantedSize=84, caps=4) at /Users/casner/src/github/esp-idf/components/esp32/./heap_alloc_caps.c:372
#5  0x400893cc in pvPortMalloc (xWantedSize=84) at /Users/casner/src/github/esp-idf/components/esp32/./heap_alloc_caps.c:306
#6  0x40085e8a in xQueueGenericCreate (uxQueueLength=1, uxItemSize=0, ucQueueType=4 '\004') at /Users/casner/src/github/esp-idf/components/freertos/./queue.c:388
#7  0x400860bb in xQueueCreateMutex (ucQueueType=4 '\004') at /Users/casner/src/github/esp-idf/components/freertos/./queue.c:495
#8  0x40081db9 in lock_init_generic (lock=0x3ffca87c, mutex_type=4 '\004') at /Users/casner/src/github/esp-idf/components/newlib/./locks.c:79
#9  0x40081eca in _lock_init_recursive (lock=0x3ffca87c) at /Users/casner/src/github/esp-idf/components/newlib/./locks.c:95
#10 0x4000bde8 in ?? ()
#11 0x40001ef3 in ?? ()
#12 0x400d72c2 in _fopen_r (ptr=0x3ffd96d0, file=0x3fff66dc "/store/events/ticker.10/tick", mode=0x3f4167e0 "r") at ../../../.././newlib/libc/stdio/fopen.c:138
#13 0x400d735f in fopen (file=0x3fff66dc "/store/events/ticker.10/tick", mode=0x3f4167e0 "r") at ../../../.././newlib/libc/stdio/fopen.c:181
#14 0x400f57f9 in OvmsScripts::AllScripts (this=<optimized out>, path=...) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_script.cpp:102
#15 0x400f58d8 in OvmsScripts::EventScript (this=0x3ffc3c7c <MyScripts>, event=..., data=<optimized out>) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_script.cpp:122
#16 0x400f02a9 in OvmsEvents::SignalEvent (this=<optimized out>, event=..., data=0x0) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_events.cpp:117
#17 0x400f0f1a in Housekeeping::Ticker1 (this=0x3ffda03c) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_housekeeping.cpp:182
#18 0x400f1053 in HousekeepingTicker1 (timer=0x3ffd6878) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_housekeeping.cpp:56
#19 0x40087ca9 in prvProcessExpiredTimer (xNextExpireTime=170009, xTimeNow=170009) at /Users/casner/src/github/esp-idf/components/freertos/./timers.c:422
#20 0x40087cdc in prvProcessTimerOrBlockTask (xNextExpireTime=170009, xListWasEmpty=<optimized out>) at /Users/casner/src/github/esp-idf/components/freertos/./timers.c:469
#21 0x40087de7 in prvTimerTask (pvParameters=0x0) at /Users/casner/src/github/esp-idf/components/freertos/./timers.c:442
(gdb)

Here I see that this allocation is a FreeRTOS Queue to serve as a lock
for file I/O during fopen().  I assume that Queue should be freed when
the file is closed.  So there may be multiple blocks of the same size
allocated, and perhaps this is not the one that is leaked.

I can specify not to abort until some number of blocks of the
requested size have been allocated.  So I try again specifying a count
of 2 rather than 1.

OVMS > module abort Tmr 2 108

(gdb) bt
#0  0x40088c8c in invoke_abort () at /Users/casner/src/github/esp-idf/components/esp32/./panic.c:125
#1  0x40088d5a in abort () at /Users/casner/src/github/esp-idf/components/esp32/./panic.c:134
#2  0x40085a3e in mem_malloc_block (data=0x3fff69bc) at /Users/casner/src/github/esp-idf/components/freertos/./heap_regions_debug.c:214
#3  0x4008547a in pvPortMallocTagged (xWantedSize=<optimized out>, tag=<optimized out>) at /Users/casner/src/github/esp-idf/components/freertos/./heap_regions.c:308
#4  0x4008938b in pvPortMallocCaps (xWantedSize=84, caps=4) at /Users/casner/src/github/esp-idf/components/esp32/./heap_alloc_caps.c:372
#5  0x400893cc in pvPortMalloc (xWantedSize=84) at /Users/casner/src/github/esp-idf/components/esp32/./heap_alloc_caps.c:306
#6  0x40085e8a in xQueueGenericCreate (uxQueueLength=1, uxItemSize=0, ucQueueType=4 '\004') at /Users/casner/src/github/esp-idf/components/freertos/./queue.c:388
#7  0x400860bb in xQueueCreateMutex (ucQueueType=4 '\004') at /Users/casner/src/github/esp-idf/components/freertos/./queue.c:495
#8  0x40081db9 in lock_init_generic (lock=0x3ffca87c, mutex_type=4 '\004') at /Users/casner/src/github/esp-idf/components/newlib/./locks.c:79
#9  0x40081ddf in lock_acquire_generic (lock=0x3ffca87c, delay=4294967295, mutex_type=4 '\004') at /Users/casner/src/github/esp-idf/components/newlib/./locks.c:132
#10 0x40081f24 in _lock_acquire_recursive (lock=0x3ffca87c) at /Users/casner/src/github/esp-idf/components/newlib/./locks.c:169
#11 0x4000be38 in ?? ()
#12 0x40002031 in ?? ()
#13 0x400020b8 in ?? ()
#14 0x400f584c in OvmsScripts::AllScripts (this=<optimized out>, path=...) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_script.cpp:108
#15 0x400f58f4 in OvmsScripts::EventScript (this=0x3ffc3c7c <MyScripts>, event=..., data=<optimized out>) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_script.cpp:123
#16 0x400f02b1 in OvmsEvents::SignalEvent (this=<optimized out>, event=..., data=0x0) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_events.cpp:117
#17 0x400f0f22 in Housekeeping::Ticker1 (this=0x3ffda03c) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_housekeeping.cpp:182
#18 0x400f105b in HousekeepingTicker1 (timer=0x3ffd6878) at /Users/casner/src/github/ovms/vehicle/OVMS.V3/main/./ovms_housekeeping.cpp:56
#19 0x40087ca9 in prvProcessExpiredTimer (xNextExpireTime=5009, xTimeNow=5009) at /Users/casner/src/github/esp-idf/components/freertos/./timers.c:422
#20 0x40087cdc in prvProcessTimerOrBlockTask (xNextExpireTime=5009, xListWasEmpty=<optimized out>) at /Users/casner/src/github/esp-idf/components/freertos/./timers.c:469
#21 0x40087de7 in prvTimerTask (pvParameters=0x0) at /Users/casner/src/github/esp-idf/components/freertos/./timers.c:442
(gdb) q

This abort is pretty similar in that a Queue is being created, but
there is no call to fopen in frame 13 and the source line of
ovms_script in frame 14 is different.  Looking at the code I see that
is a redundant fclose(), that is, on a file that is already closed.
Removing that fclose() got rid of the leak.  One would expect that the
redundant fclose would just result in an error, but apparently
FreeRTOS does not handle it gracefully.

                                                        -- Steve