WildernessLabs / Meadow_Issues

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

Memory leak when returning data via Maple #276

Open doingnz opened 1 year ago

doingnz commented 1 year ago

Describe the bug Application returns list of JSON serializable objects to Maple to send to HTTP client in response to HTTP GET results in a memory leak.

To Reproduce Steps to reproduce the behavior:

  1. Load Clima Hack Kit sample application
  2. Add following methods to MeadowApp.cs to aid uniform data output

        public static string TimeStamp()
        {
            return $"{System.DateTime.Now:yyyy-MM-ddTHH:mm:ss}";
        }
    
        public static string LogMemory(string function, string commentCount=null, int count=0, string comment = null)
        {
            return $"LogMemory, {TimeStamp(),25},{GC.GetTotalMemory(true),12},\"{function,-30}\",
            \"{(string.IsNullOrWhiteSpace(commentCount)?"":commentCount)}\",
            {(string.IsNullOrWhiteSpace(commentCount) ? "" : count.ToString())},
            \"{(string.IsNullOrWhiteSpace(comment) ? "" : comment)}\"";
         }
  3. Add Console.WriteLine to GetTemperatureLogs() method to call above methods and output memory used.

        [HttpGet("/gettemperaturelogs")]
        public IActionResult GetTemperatureLogs()
        {
            LedController.Instance.SetColor(Color.Magenta);
            Console.WriteLine(MeadowApp.LogMemory("GetTemperatureLogs", comment: "Read Database ..."));
            var logs = DatabaseManager.Instance.GetAllTemperatureReadings();
            Console.WriteLine(MeadowApp.LogMemory("GetTemperatureLogs", "logs",logs.Count, "TemperatureTable"));
            var data = MapDtoTemperatureModels(logs);
            Console.WriteLine(MeadowApp.LogMemory("GetTemperatureLogs", "data", data.Count, "DTO"));
            LedController.Instance.SetColor(Color.Green);
            return new JsonResult(data);
        }
    
        private static List<TemperatureModel> MapDtoTemperatureModels(List<TemperatureTable> logs)
        {
            var data = new List<TemperatureModel>();
            foreach (var log in logs)
            {
                data.Add(new TemperatureModel()
                {
                    Temperature = log.TemperatureCelcius?.ToString("00"),
                    DateTime = log.DateTime.ToString("yyyy-MM-ddTHH:mm:ss.sss "),
                    TotalMemory = log.TotalMemory,
                    ID = log.ID
                });
            }
    
            return data;
        }
  4. Add additional end point that returns data without calling SQLite

        [HttpGet("/gettemperaturedummy/{lines}")]
        public IActionResult GetTemperatureDummy(int lines)
        {
            LedController.Instance.SetColor(Color.Magenta);
            Console.WriteLine(MeadowApp.LogMemory("GetTemperatureLogs", comment: "Read Database ..."));
    
            var logs = DummyList(lines);
            Console.WriteLine(MeadowApp.LogMemory("GetTemperatureLogs", "logs", logs.Count, "DUMMY"));
    
            var data = MapDtoTemperatureModels(logs);
            Console.WriteLine(MeadowApp.LogMemory("GetTemperatureLogs", "data", data.Count, "DTO"));
    
            LedController.Instance.SetColor(Color.Green);
            return new JsonResult(data);
        }
        private List<TemperatureTable> DummyList(int rows)
        {
            List <TemperatureTable> TempList = new List<TemperatureTable >();
            for (int i = 0; i < rows; i++)
            {   // Note, needs ID and TotalMeory added to the DTO model
                TemperatureTable dummy = new TemperatureTable() { ID = i, TemperatureCelcius = 30, 
                          DateTime = DateTime.Now, TotalMemory = GC.GetTotalMemory(true) };
                TempList.Add(dummy);
            }
            return TempList;
        }
  5. Add similar console lines to the SaveReading method in DatabaseManager.cs to confirm no memory leak during saving

        public bool SaveReading(TemperatureTable temperature)
        {
            LedController.Instance.SetColor(WildernessLabsColors.ChileanFireDark);
    
            if (isConfigured == false)
            {
                Console.WriteLine("SaveReading: DB not ready");
                return false;
            }
    
            if (temperature == null)
            {
                Console.WriteLine("SaveReading: Conditions is null");
                return false;
            }
            Console.WriteLine(MeadowApp.LogMemory("SaveReading", "GetCountReadings", 
                     GetCountReadings(), "Saving temperature reading to DB"));
            Database.Insert(temperature);
            Console.WriteLine(MeadowApp.LogMemory("SaveReading", "GetCountReadings", GetCountReadings(), "Saved")); 
            LedController.Instance.SetColor(Color.Green);
            return true;
        }
  6. Exercise the two HTTP GET end points and observe the increase in allocated memory that is not released. Let application run and collected samples to show no memory leak when data saved.

Expected behavior Total allocated Memory should not increase with each call to either endpoint. Note that the objects in the list returned to Maple would only be released after the data is serialised.

Screenshots Confirm that saving data to SQLite does not leak memory by checking does not increase at "done!" In this example the memory is +/- 1183864 (small variation ok)

Meadow StdOut: LogMemory,       2023-03-06T20:12:32,     1223040,"AnalogTemperature             ","Celsius",31,""
Meadow StdOut: LogMemory,       2023-03-06T20:12:35,     1177624,"SaveReading                   ","GetCountReadings",76,"Saving temperature reading to DB"
Meadow StdOut: LogMemory,       2023-03-06T20:12:38,     1183272,"SaveReading                   ","GetCountReadings",77,"Saved"
Meadow StdOut: LogMemory,       2023-03-06T20:12:38,     1182904,"AnalogTemperature             ","",,"Saved"
Meadow StdOut: LogMemory,       2023-03-06T20:12:39,     1183544,"AnalogTemperature             ","",,"done!

... delete other lines for clarity ....

Meadow StdOut: LogMemory,       2023-03-06T20:13:43,     1183864,"AnalogTemperature             ","Celsius",30,""
Meadow StdOut: LogMemory,       2023-03-06T20:13:43,     1183864,"SaveReading                   ","GetCountReadings",78,"Saving temperature reading to DB"
Meadow StdOut: LogMemory,       2023-03-06T20:13:45,     1183864,"SaveReading                   ","GetCountReadings",79,"Saved"
Meadow StdOut: LogMemory,       2023-03-06T20:13:45,     1183864,"AnalogTemperature             ","",,"Saved"
Meadow StdOut: LogMemory,       2023-03-06T20:13:46,     1183864,"AnalogTemperature             ","",,"done!"

Do HTTP Get to dummy end point that does not call SQLite to confirm the memory leak is in Maple and not the memory allocated at the "DTO" line and then at subsequent saves

Meadow StdOut: Received GET /gettemperaturedummy/300 - Invoking gettemperaturedummy
Meadow StdOut: LogMemory,       2023-03-06T20:14:11,     1232320,"GetTemperatureLogs            ","",,"Read Database ..."
Meadow StdOut: LogMemory,       2023-03-06T20:14:27,     1249032,"GetTemperatureLogs            ","logs",300,"DUMMY"
Meadow StdOut: LogMemory,       2023-03-06T20:14:28,     1287656,"GetTemperatureLogs            ","data",300,"DTO"

Note at the next save and other saves that follow, some of the memory is released, but not all as total memory returns to +/- 1285256 and not near the original 1183864 above.

Meadow StdOut: LogMemory,       2023-03-06T20:15:57,     1285424,"AnalogTemperature             ","Celsius",30,""
Meadow StdOut: LogMemory,       2023-03-06T20:15:57,     1285128,"SaveReading                   ","GetCountReadings",82,"Saving temperature reading to DB"
Meadow StdOut: LogMemory,       2023-03-06T20:15:59,     1285256,"SaveReading                   ","GetCountReadings",83,"Saved"
Meadow StdOut: LogMemory,       2023-03-06T20:15:59,     1285128,"AnalogTemperature             ","",,"Saved"
Meadow StdOut: LogMemory,       2023-03-06T20:16:00,     1285256,"AnalogTemperature             ","",,"done!"

Doing additional HTTP GET will step up the allocated memory

Meadow StdOut: LogMemory,       2023-03-06T20:16:22,     1363600,"GetTemperatureLogs            ","data",300,"DTO"
Meadow StdOut: LogMemory,       2023-03-06T20:18:38,     1496112,"GetTemperatureLogs            ","data",1000,"DTO"

and the additional memory is not released, even if the app runs for "long" time.

Meadow StdOut: LogMemory,       2023-03-06T20:27:10,     1313344,"AnalogTemperature             ","",,"done!"
Meadow StdOut: LogMemory,       2023-03-06T20:28:17,     1313344,"AnalogTemperature             ","",,"done!"
...
Meadow StdOut: LogMemory,       2023-03-06T20:37:12,     1313408,"AnalogTemperature             ","",,"done!"

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

Meadow (please complete the following information as best as you can): Connecting to Meadow on COM6 Meadow by Wilderness Labs Board Information Model: F7Micro Hardware version: F7FeatherV2 Device name: MeadowF7

Hardware Information Processor type: STM32F777IIK6 ID: 22-00-26-00-11-51-36-30-33-33-37-33 Serial number: 335D335F3036 Coprocessor type: ESP32 MAC Address - WiFi: 94:B9:7E:91:F4:0C

Firmware Versions OS: 0.9.4.0 Mono: 0.9.4.0 Coprocessor: 0.9.4.0

Done!

Additional context Uses Clima Hack Kit sample application as base.

doingnz commented 1 year ago

You can increase the speed of the method to populate the dummy list by only calling GC.GetTotalMemory(true) once by putting the call outside the for loop, or not calling it.

        private List<TemperatureTable> DummyList(int rows)
        {
            long totalMemory = GC.GetTotalMemory(true);
            List <TemperatureTable> TempList = new List<TemperatureTable >();
            for (int i = 0; i < rows; i++)
            {
                TemperatureTable dummy = new TemperatureTable() { ID = i, TemperatureCelcius = 30, 
                         DateTime = DateTime.Now, TotalMemory = totalMemory };
                TempList.Add(dummy);
            }
            return TempList;
        }

As noted in the initial issue, you need to add property public long TotalMemory { get; set; } to public class TemperatureTable if returning the memory as a property (I added it to the Model saved to the database in the path that saves the temperature to have a record of the memory used at each save. However, as demonstrated by the HTTP GET endpoint that returns dummy data, the logging to SQLite and reading SQLIte don't contribute to the significant memory leak seen in Maple.

doingnz commented 1 year ago

Note the dummy endpoint needs a parameter that set the number of records to return. e.g for 2000 records

http://192.168.2.112:5417/gettemperaturedummy/2000

Fetching 2000 records will work once. Some form of out of memory error will be raised on the next attempt... e.g.

Meadow StdOut: memalign returned null when requesting 1048576 bytes (1048576 alignment) -- out of memory?
Meadow StdOut: mono_os_mutex_trylock: pthread_mutex_trylock failed with "Error code '142'" (142)

Meadow will need to be restarted.

Requesting smaller number of returned records will let you do the request multiple times, till the memory is exhausted.

alexischr commented 6 months ago

I think this needs to be re-tested on OS 1.6; preliminary tests have shown that we are much more reliable on Maple.

bryancostanich commented 6 months ago

@halyssonJr we think this is fixed, can you validate, please?

halyssonJr commented 5 months ago

I carried out a validation using the App provided by the user, however there was a problem with the allocation of 12k bytes and after that the application broke. I tested with OS v1.7.0.0 and v1.8.0.0

Meadow StdOut: Log level: Information
Meadow StdOut: Device is configured to use WiFi for the network interface
Meadow StdOut: Update Service is disabled.
Meadow StdOut: Health Metrics disabled.
Listening for Meadow Console output. Press Ctrl+C to exit
Meadow StdOut: MeadowApp: Connected to network: ip=192.168.4.37 port=5417
Meadow StdOut: SetClock(01/12/2024 10:02:29);
Meadow StdOut: Listening on http://192.168.4.37:5417/
Meadow StdOut: GET : /gettemperaturelogs --> GetTemperatureLogs
Meadow StdOut: GET : /gettemperaturepage/{page} --> GetTemperaturePage
Meadow StdOut: requestHandlers.Count: 1
Meadow StdOut: Starting up Maple HTTP Request listener.
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: Saving (26.0776556776556,01/12/2024 10:02:44)...
Meadow StdOut: SaveReading: Saving temperature reading to DB
Meadow StdOut: Could not allocate 12312 bytes
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::192.168.4.37, port: 17756
Meadow StdOut: Request received from 172.20.10.2:55458
Meadow StdOut: Received GET /gettemperaturepage/10 - Invoking gettemperaturepage
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: GetReadings:  TotalCount=29 TotalPages=1 PageSize=50 CurrentPage=1
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: memalign returned null when requesting 65536 bytes (4096 alignme
Meadow StdOut: nt) -- out of memory?
Meadow StdOut: mono_os_mutex_trylock: pthread_mutex_trylock failed with "Error
Meadow StdOut: code '142'" (142)
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: mono_os_mutex_trylock: pthread_mutex_trylock failed with "Error
Meadow StdOut: code '142'" (142)
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
Meadow StdOut: UDP Broadcast: Meadow::172.20.10.3, port: 17756
bryancostanich commented 2 months ago

Gonna retest after several fixes in the queue land, think that this may be fixed with them.

adrianstevens commented 1 month ago

The team is doing a lot of work optimizing memory usage - will retest and verify this issue soon

alexischr commented 4 weeks ago

@halyssonJr I would like you to re-test this when you get the chance, please!