1.27.0 Memory leak in TVService (1 Viewer)

[mm1352000]

Thanks for the log files!

In short, there's nothing that stands out as concerning.

Putting aside the service start and stop stuff, the most common entries in the main log files (TVService.*.log) during your test are related to the tuner detector. In fact there's almost nothing else. The tuner detector does seem to run more often than is absolutely necessary, On average, perhaps every half hour or so, but it appears to be irregular/unpredictable. In an ideal world the detector would only run when a tuner is connected or disconnected; in the real world it runs when Windows reports a device change event, which may well be entirely unrelated to tuners. Cutting to the chase, in my opinion it's unlikely that the detector is causing a memory leak on your system because:

1. I've seen the "running more often than absolutely necessary" behaviour before, including on my own system. In my experience it is normal and has never been indicative of a problem of any kind.
2. As previously mentioned, the detector appears to run irregularly/sporadically/randomly. This is not at all consistent with a slow and steady 20 MB per hour memory leak. If it were the detector causing a leak, I'd expect memory usage to jump significantly every time it runs.
3. There are periods in your log files - for example: between 9 PM on the 12th and 9 AM on the 13th - during which the tuner detector doesn't run at all. Again, this is not at all consistent with a continuous memory leak.

Honestly, I'm not to sure where to go from here. Once again my hope for an obvious issue with an obvious cause have been dashed.

Given that the log files aren't showing anything much, really the only other way to determine what's going on would be to use developer tools to attach to the TvS process and "debug" it. However, this isn't particularly straightforward. Are you a developer? ...or do you happen to have experience doing that sort of thing?

 

[PRW]

I am not a developer. I do have a lot of experience debugging code, but not since about 35 years ago.
Can you tell me briefly what tools would be used? I will look them up and see whether I think I can manage them.
Would it be helpful to add more logging to TvS to track memory acquisition and releasing?

 

[mm1352000]

Can you tell me briefly what tools would be used?

In short, you'd need to grab the code from Github. Simplest way to do that is to get just the 1.27 release code from here:

https://github.com/MediaPortal/MediaPortal-1/archive/Release_1.27.0.zip

Then to attach to the process you'd use Visual Studio 2019 Community Edition:

Visual Studio 2022 Community Edition – Download Latest Free Version

Try our free, fully-featured, and extensible IDE for creating modern developer apps for Windows, Android, & iOS. Download Community for free today!

visualstudio.microsoft.com

Attach to running processes with the debugger - Visual Studio (Windows)

Attach the Visual Studio debugger to a running process on a local or remote computer to debug running apps, apps not created in Visual Studio, and other scenarios.

docs.microsoft.com

Alternatively, a quick Internet search suggests something like this product could be useful:

.NET Memory Profiler By Redgate | ANTS Memory Profiler

Get a free trial of ANTS Memory Profiler, Redgate's .NET memory profiler. Find memory leaks & optimize memory usage in your .NET code. Works with C# & VB.NET

www.red-gate.com

Would it be helpful to add more logging to TvS to track memory acquisition and releasing?

.NET processes don't manually acquire and release memory. Memory management is all done behind the scenes by the .NET garbage collector. For that reason it isn't really practical to add more logging.

Some information about how memory management works with .NET applications:

.NET garbage collection - .NET

Learn about garbage collection in .NET. The .NET garbage collector manages the allocation and release of memory for your application.

docs.microsoft.com

 

[PRW]

I would love to contribute to MP but after looking at the tools I don't think I am up to the job.
As a workaround I have created Windows tasks that stop and restart TvS. As long they run at a time of day that I am unlikely to be recording or playing back they should solve my problem.
Thanks for your help. Good hunting.

 

[RonD]

I also see unusually large tvservice.exe process sizes running MePo v1.25. Last night Task Manager showed it was about 1 GB, used tvsetup to stop/start tvservice and it started at about 35 MB, this morning over 370 MB. Overnight did 2 recordings and a tvguide.xml import, about 58 MB xml file.

With ProcessExplorer looked at some memory info, see picts, "Gen 2 heap size = 404 MB"

TVS_ProcEx2_20210318_0918am.PNG is "Properties > Performance"
TVS_ProcEx1_20210318_0918am.PNG is "Properties > .Net Performance"
TVS_ResMon_20210318_0918am.PNG is Resource monitor > Memory view

MePo v1.25, tvserver system has 4 core i5 CPU, 24 GB of DRAM

attached zip file is logs from/after doing tvservice restart

with task manager created a "right click dump" file about 561 MB, zipped shrinks down to 115 MB, uploaded zip to my google drive, link should let you download DMP file.

MePo_Mem – Google Drive

drive.google.com

 

[RonD]

Figured out how to setup windows "Performance Monitor" tool to monitor/track tvservice memory usage. Configured to take snapshot of memory usage info once/minute for 12 hours. The numbers on the vertical axis are scaled by a factor of 1 million, so 500 = 500MB etc.

Did manual tvserver stop/start at about 8:10 am, let run all day

Looked at data around 7pm, with PerfMon tool looked data for 2 values

Gen2 heap, starts 3.4 MB grew to 642 MB.
Working Set, starts 60 MB grew to 766 MB.

Looks like the garbage collector cleanup ran at about 6PM and memory usage sees big drop. Gen2 heap dropped to 50-60 MB. Working Set dropped to 150 MB or so

Left running overnight and get 2nd picture 8:44am. Looks like garbage collector ran around 3AM and memory usage see another big drop.

strangely the 2 garbage collector run seem to match up to with how I grab EPG data from schedules direct at 6pm/3am and do tvguide.xml import. Seems like garbage collector runs are triggered as side effect xmltv-plugin and EPG update.

[2021-03-19 17:58:20,025] [Log    ] [XmlTvImporter] [INFO ] - plugin:xmltv importing L:\MePo\xmltv\meposd\tvguide.xml
[2021-03-19 18:05:23,517] [Log    ] [XmlTvImporter] [INFO ] - Xmltv: waiting for database to finish inserting imported programs.
[2021-03-19 18:11:03,487] [Log    ] [SQL EPG importer] [INFO ] - schedule.SynchProgramStatesForAll
[2021-03-19 18:11:08,230] [Log    ] [SQL EPG importer] [DEBUG] - BusinessLayer: InsertProgramsThread exiting
[2021-03-19 18:11:08,230] [Log    ] [XmlTvImporter] [INFO ] - plugin:xmltv import done

[2021-03-20 03:12:24,905] [Log    ] [XmlTvImporter] [INFO ] - plugin:xmltv importing L:\MePo\xmltv\meposd\tvguide.xml
[2021-03-20 03:12:26,979] [Log    ] [XmlTvImporter] [INFO ] - Xmltv: waiting for database to finish inserting imported programs.
[2021-03-20 03:19:42,724] [Log    ] [SQL EPG importer] [INFO ] - schedule.SynchProgramStatesForAll
[2021-03-20 03:19:48,073] [Log    ] [SQL EPG importer] [DEBUG] - BusinessLayer: InsertProgramsThread exiting
[2021-03-20 03:19:48,073] [Log    ] [XmlTvImporter] [INFO ] - plugin:xmltv import done

As an experiment modified how task manager runs EPG download to skip 6pm tonight. Will be curious to see what happens and when garbage collector runs. Maybe @mm1352000 and have some comments.

 

[RonD]

Disabled 6pm EPG update and tvserver Virtual memory usage grew overnight to close to 2.0 GB and the working set grew to around 1.5 to 1.6 GB. There is about 0.2 GB drop in memory usage after 2:30 am and a big 1.3 GB drop at 3:30 am when the EPG update was done. The Virtual bytes dropped from almost 2 GB to 0.5 GB and the working set numbers dropped from 1.5 GB to under 0.2 GB.

After the big drop, the tvserver memory usage starts growing again hitting 0.3 to 0.5 GB at 9:15am when I grabbed the pictures

Not sure how the C# garbage collector works, but this sort of looks like its keeping Virtual memory under 2.0 GB (2:30 am) and EPG update side effects cause a bigger cleanup.

Disabled task manager updates to see what happens overnight with no EPG updates.

tvserver logfile info for EPG update:

[2021-03-21 03:23:36,822] [Log    ] [XmlTvImporter] [INFO ] - plugin:xmltv importing L:\MePo\xmltv\meposd\tvguide.xml
[2021-03-21 03:23:36,913] [Log    ] [XmlTvImporter] [INFO ] - xmltv import L:\MePo\xmltv\meposd\tvguide.xml
[2021-03-21 03:30:07,387] [Log    ] [SQL EPG importer] [INFO ] - schedule.SynchProgramStatesForAll
[2021-03-21 03:30:12,380] [Log    ] [SQL EPG importer] [DEBUG] - BusinessLayer: InsertProgramsThread exiting
[2021-03-21 03:30:12,382] [Log    ] [XmlTvImporter] [INFO ] - plugin:xmltv import done

pictures show the overnight Performance Monitor memory usage graphs and a 9:15am Resource Monitor view to show how the PrefMon and ResourceMon numbers matchup

 

[Brownard]

Not sure how the C# garbage collector works, but this sort of looks like its keeping Virtual memory under 2.0 GB (2:30 am) and EPG update side effects cause a bigger cleanup.

That sounds about right, the GC runs when it detects memory 'pressure', which is pretty complicated but an oversimplified version would be it runs when memory usage is already quite high relative to the rest of the OS and it needs to allocate more memory. This is different to what is often intuitively expected, the GC doesn't necessarily free up memory after it's finished with it or try and keep memory usage as low as possible (because the GC requires that the entire app is 'paused' whilst it marks what memory can be freed which is obviously detrimental to app responsiveness), but will hang on to it until the next time a big allocation is needed which takes it over some calculated limit. For something like the TV server that might sit idle for hours/days this can mean that the GC doesn't run for hours/days until something like the EPG runs and allocates a load of stuff, which then triggers a GC which frees all of the unused memory and causes a potentially big drop.

 

[RonD]

note: this is MePo v1.25

left system running 1+ days without doing any EPG updates. Performance Monitor shows growing memory use with "virtual bytes" just under 2000 MB, "Working Set" 1600 MB. At 12:31pm local, recording ends and tvserver.exe got "out of memory" fatal crash. Was watching with Mepo-Client on tvserver.

end of tvserver.log shows the following

[2021-03-23 12:31:24,066] [Log    ] [scheduler thread] [INFO ] - dvb:StopGraph called
[2021-03-23 12:31:24,067] [Log    ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2021-03-23 12:31:24,067] [Log    ] [scheduler thread] [INFO ] - dvb:StopGraph filterstate already stopped, returning.
[2021-03-23 12:31:25,441] [Log    ] [7        ] [DEBUG] - Controller: DoSetChannelStates for 28 channels
[2021-03-23 12:31:27,917] [Log    ] [7        ] [INFO ] - ChannelStates.DoSetChannelStates took 2475 msec
[2021-03-23 12:31:28,104] [Log    ] [scheduler thread] [INFO ] - diskmanagement: recording KPIX 5 News at Noon ended. type:Once max episodes:1
[2021-03-23 12:32:02,507] [Log    ] [5        ] [DEBUG] - Debug: SSDPClientController: Problem parsing incoming multicast UDP packet.
Error message: 'Exception of type 'System.OutOfMemoryException' was thrown.'

the following is copy/paste of the text from the 3 Event Log entries

Spoiler: press for event log info

*** Error
Application: TVService.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: System.OutOfMemoryException

*** Error
Faulting application name: TVService.exe, version: 1.25.0.0, time stamp: 0x5ecd5a76
Faulting module name: KERNELBASE.dll, version: 10.0.18362.1316, time stamp: 0x7a6bfa05
Exception code: 0xe0434352
Fault offset: 0x001146d2
Faulting process id: 0x5b7c
Faulting application start time: 0x01d71f3235616b3c
Faulting application path: C:\Program Files (x86)\Team MediaPortal\MediaPortal TV Server\TVService.exe
Faulting module path: C:\WINDOWS\System32\KERNELBASE.dll
Report Id: a76ec76a-de1d-4656-aff6-8109a44b8da6
Faulting package full name:
Faulting package-relative application ID:

*** Information
Fault bucket 2066977961694640996, type 1
Event Name: APPCRASH
Response: Not available
Cab Id: 0

Problem signature:
P1: TVService.exe
P2: 1.25.0.0
P3: 5ecd5a76
P4: KERNELBASE.dll
P5: 10.0.18362.1316
P6: 7a6bfa05
P7: e0434352
P8: 001146d2
P9:
P10:

Will reboot windows so everything get "clean start" and see if this happens again, suspect it will.

The event log info imply there might be dump file in a "windows folder", but I get caught in some MSFT-HELL with ""You Don't Currently Have Permission to Access This Folder" Error". Have not been able to find (google) a way to gain access to the folders, have tried 3 or 4 online webpages, NONE of them work.

****
These files may be available here:
\\?\C:\ProgramData\Microsoft\Windows\WER\ReportArchive\AppCrash_TVService.exe_a667dab55d14df381ee351a0c2d140c8606236_a725e5b1_6e8b42b5-6dd2-4c54-baf7-dd4c5d83cbfe

zipfile has full tvserver log and event log info

 

[TLD]

The event log info imply there might be dump file in a "windows folder", but I get caught in some MSFT-HELL with ""You Don't Currently Have Permission to Access This Folder" Error". Have not been able to find (google) a way to gain access to the folders, have tried 3 or 4 online webpages, NONE of them work.

Have you tried to access the folder in windows "safe mode".