WildernessLabs / Meadow_Issues

Public repo for bugs and issues with Meadow
15 stars 0 forks source link

The default 'Project New' application (Blinky) leaks memory #387

Open doingnz opened 7 months ago

doingnz commented 7 months ago

Describe the bug The default Project New application for Meadow F7 (Blinky) leaks memory at a rate of 624 bytes every time it sets the color. By default the application changes color @ 1Hz. The memory leak appears to be related to the Cancellation of the dynamically created Task that animates the RGB Led (varies the brightness to create pulse animation.)

To Reproduce Steps to reproduce the behavior:

  1. Project New Meadow Feather application (New Blinky)
  2. Edit the project to Log memory allocated after first calling the garbage collector to force a collection.

Expected behavior After the initial allocations when the application starts, no further memory increases

Screenshots Example Log data using the sample application given under Additional Context

Initialize...
Run...
Cycle colors...
LogMemory (changed   ), 2023-11-10T19:49:24      ,      615408,           0,      615408,00:00:04.3040000,"CycleColors                   ","Duration: 00:00:01",1,""
LogMemory (changed   ), 2023-11-10T19:49:26      ,      630424,      615408,       15016,00:00:02.1530000,"CycleColors                   ","Duration: 00:00:01",2,""
LogMemory (changed   ), 2023-11-10T19:49:27      ,      631048,      630424,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",3,""
LogMemory (changed   ), 2023-11-10T19:49:28      ,      631672,      631048,         624,00:00:01.1240000,"CycleColors                   ","Duration: 00:00:01",4,""
LogMemory (changed   ), 2023-11-10T19:49:29      ,      632296,      631672,         624,00:00:01.0850000,"CycleColors                   ","Duration: 00:00:01",5,""
LogMemory (changed   ), 2023-11-10T19:49:30      ,      632920,      632296,         624,00:00:01.0850000,"CycleColors                   ","Duration: 00:00:01",6,""
LogMemory (changed   ), 2023-11-10T19:49:31      ,      633544,      632920,         624,00:00:01.0850000,"CycleColors                   ","Duration: 00:00:01",7,""
LogMemory (changed   ), 2023-11-10T19:49:32      ,      634168,      633544,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",8,""
LogMemory (changed   ), 2023-11-10T19:49:33      ,      634792,      634168,         624,00:00:01.1250000,"CycleColors                   ","Duration: 00:00:01",9,""
LogMemory (changed   ), 2023-11-10T19:49:35      ,      635416,      634792,         624,00:00:01.0860000,"CycleColors                   ","Duration: 00:00:01",10,""

Developer tools (please complete the following information as best as you can):

Meadow (please complete the following information as best as you can): Meadow by Wilderness Labs Board Information Model: F7Micro Hardware version: F7CoreComputeV2 Device name: MeadowCompute_Clima

Hardware Information Processor type: STM32F777IIK6 ID: 34-00-25-00-03-51-38-34-35-31-38-33 Serial number: 335D31733438 Coprocessor type: ESP32 MAC Address - WiFi: 4C:75:25:D7:13:C0

Firmware Versions OS: 1.5.0.3 Mono: 1.5.0.3 Coprocessor: 1.5.0.0 Protocol: 7

Additional context Sample Blinky application with calls to GC and logger.

using Meadow;
using Meadow.Devices;
using Meadow.Foundation;
using Meadow.Foundation.Leds;
using Meadow.Peripherals.Leds;
using System;
using System.Threading;
using System.Threading.Tasks;

namespace ClassicBlinky
{
    // Change F7FeatherV2 to F7FeatherV1 for V1.x boards
    public class MeadowApp : App<F7FeatherV2>
    {
        RgbPwmLed onboardLed;

        public override Task Initialize()
        {
            Resolver.Log.Info("Initialize...");

            onboardLed = new RgbPwmLed(
                redPwmPin: Device.Pins.OnboardLedRed,
                greenPwmPin: Device.Pins.OnboardLedGreen,
                bluePwmPin: Device.Pins.OnboardLedBlue,
                CommonType.CommonAnode);

            return base.Initialize();
        }

        public override Task Run()
        {
            Resolver.Log.Info("Run...");

            return CycleColors(/*TimeSpan.FromMilliseconds(1000)*/);
        }

        async Task CycleColors(/*TimeSpan duration*/)
        {
            Resolver.Log.Info("Cycle colors...");
            await onboardLed.StartPulse(Color.Blue, duration / 2);
            while (true)
            {
                await ShowColorPulse(Color.Blue, duration);
                await ShowColorPulse(Color.Cyan, duration);
                await ShowColorPulse(Color.Green, duration);
                await ShowColorPulse(Color.GreenYellow, duration);
                await ShowColorPulse(Color.Yellow, duration);
                await ShowColorPulse(Color.Orange, duration);
                await ShowColorPulse(Color.OrangeRed, duration);
                await ShowColorPulse(Color.Red, duration);
                await ShowColorPulse(Color.MediumVioletRed, duration);
                await ShowColorPulse(Color.Purple, duration);
                await ShowColorPulse(Color.Magenta, duration);
                await ShowColorPulse(Color.Pink, duration);
            }
        }

        async Task ShowColorPulse(Color color, TimeSpan duration)
        {
            Interlocked.Increment(ref countCycleColors);
            await onboardLed.StartPulse(color, duration / 2);
            LogMemory("CycleColors", $"Duration: {duration,8}", countCycleColors);
            await Task.Delay(duration);
        }

        private int countCycleColors = 0;
        private static TimeSpan duration = TimeSpan.FromMilliseconds(1000);
        private static long lastTotalMemory = 0;
        private static DateTime lastTotalMemoryDateTime = DateTime.Now;
        private static DateTime lastTotalMemoryUpdateDateTime = DateTime.Now;
        private static double step = 100.0;

        public static string LogMemory(string function, string commentCount = "", int count = 0, string comment = "")
        {
            GC.Collect();
            GC.WaitForPendingFinalizers();
            long newTotalMemory = GC.GetTotalMemory(true);
            if (newTotalMemory != lastTotalMemory)
            {
                var timeNow = DateTime.Now;
                var delta = timeNow - lastTotalMemoryDateTime;
                lastTotalMemoryDateTime = timeNow;
                string msg =
                    $"LogMemory (changed   ), {TimeStamp(),-25},{newTotalMemory,12},{lastTotalMemory,12},{newTotalMemory - lastTotalMemory,12},{delta,-12},\"{function,-30}\",\"{(string.IsNullOrWhiteSpace(commentCount) ? "" : commentCount)}\",{(string.IsNullOrWhiteSpace(commentCount) ? "" : count.ToString())},\"{(string.IsNullOrWhiteSpace(comment) ? "" : comment)}\"";
                Resolver.Log.Info(msg);
                lastTotalMemory = newTotalMemory;
                return msg;
            }

            if (DateTime.Now - lastTotalMemoryUpdateDateTime > TimeSpan.FromMinutes(2))
            {
                var timeNow = DateTime.Now;
                var delta = timeNow - lastTotalMemoryDateTime;
                string msg =
                    $"LogMemory (no change), {TimeStamp(),-25},{newTotalMemory,12},{lastTotalMemory,12},{newTotalMemory - lastTotalMemory,12},{delta,-12},\"{function,-30}\",\"{(string.IsNullOrWhiteSpace(commentCount) ? "" : commentCount)}\",{(string.IsNullOrWhiteSpace(commentCount) ? "" : count.ToString())},\"{(string.IsNullOrWhiteSpace(comment) ? "" : comment)}\"";
                Resolver.Log.Info(msg);
                lastTotalMemoryUpdateDateTime = DateTime.Now;
            }

            return string.Empty;
        }

        public static string TimeStamp()
        {
            return $"{System.DateTime.Now:yyyy-MM-ddTHH:mm:ss}";
        }
    }
}
doingnz commented 6 months ago

I have retested the above Blinky on 1.6.0.1 and it leaks memory at a steady 624 bytes per second.

Surely if something as simple as Blinky leaks memory, then all Meadow apps will leake memory?

What is special about Blinky that it would leak memory?

Cycle colors...
LogMemory (changed   ), 2023-12-05T20:27:41      ,      616232,           0,      616232,00:00:04.4990000,"CycleColors                   ","Duration: 00:00:01",1,""
LogMemory (changed   ), 2023-12-05T20:27:43      ,      628224,      616232,       11992,00:00:01.9870000,"CycleColors                   ","Duration: 00:00:01",2,""
LogMemory (changed   ), 2023-12-05T20:27:44      ,      628704,      628224,         480,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",3,""
LogMemory (changed   ), 2023-12-05T20:27:45      ,      629328,      628704,         624,00:00:01.1230000,"CycleColors                   ","Duration: 00:00:01",4,""
LogMemory (changed   ), 2023-12-05T20:27:46      ,      629952,      629328,         624,00:00:01.0850000,"CycleColors                   ","Duration: 00:00:01",5,""
LogMemory (changed   ), 2023-12-05T20:27:47      ,      630576,      629952,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",6,""
LogMemory (changed   ), 2023-12-05T20:27:48      ,      631200,      630576,         624,00:00:01.0830000,"CycleColors                   ","Duration: 00:00:01",7,""
LogMemory (changed   ), 2023-12-05T20:27:50      ,      631824,      631200,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",8,""
LogMemory (changed   ), 2023-12-05T20:27:51      ,      632448,      631824,         624,00:00:01.1230000,"CycleColors                   ","Duration: 00:00:01",9,""
LogMemory (changed   ), 2023-12-05T20:27:52      ,      633072,      632448,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",10,""
LogMemory (changed   ), 2023-12-05T20:27:53      ,      633696,      633072,         624,00:00:01.1370000,"CycleColors                   ","Duration: 00:00:01",11,""
LogMemory (changed   ), 2023-12-05T20:27:54      ,      634320,      633696,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",12,""
LogMemory (changed   ), 2023-12-05T20:27:55      ,      634944,      634320,         624,00:00:01.0840000,"CycleColors                   ","Duration: 00:00:01",13,""
doingnz commented 6 months ago

Be aware the leak may be due to the VS2022 debugger. The behaviour when debugging is different to running and monitoring with meadow listen. The latter might not leak, whereas with the VS2022 debugger it is always leaking memory. Running an overnight test to check if memory leaks when debugger not connected over an extended period of time.

doingnz commented 6 months ago

@Alexis Christoforides @Jorge Ramirez please have a look at the difference in handling of TaskCreationOptions as this appears to be a trigger for the memory leak. Specifically the option TaskCreationOptions.LongRunning causes a memory leak with VS2022 debugger attached.

In the context of Blinky and RGB LED, this leaks memory when the debugger is attached.

animationTask = new Task(() =>
{
// task code
}, 
cancellationTokenSource.Token, TaskCreationOptions.LongRunning);

Changing to ANY other TaskCreationOptions does NOT leak memory. e.g.

animationTask = new Task(() =>
{
// task code
}, 
cancellationTokenSource.Token, TaskCreationOptions.AttachedToParent);

This has implications for all other Meadow assemblies where this option is used.

bryancostanich commented 5 months ago

@doingnz thanks for filing this! We've been head's down on critical stability issues marked as P0, but we're almost through all of them and we'll tackle this after.

duduita commented 5 months ago

Be aware the leak may be due to the VS2022 debugger. The behaviour when debugging is different to running and monitoring with meadow listen. The latter might not leak, whereas with the VS2022 debugger it is always leaking memory. Running an overnight test to check if memory leaks when debugger not connected over an extended period of time.

After your long test, have you seen the leak happening when the debugger was not connected @doingnz ? It might indicate that the leak is related to the debugger indeed. Running long tests to check it as well here.

doingnz commented 5 months ago

when I remove all "TaskCreationOptions.LongRunning", then no leaks irrespective if debugger is connected or not.