memory leak problems

[davidb]

I have run into an issue that I am not clear is a memory leak in sagetv itself or in sagex. For the impatient types skip to the last paragraph. The first part explains why I am doing things the way I am!

The example code is code extracted from the server side code for my IOS client. I actually have to run this code to get the shows and movies every 24 hours.

I started writing my IOS client in January of 2015. At the time the future of Sagetv looked very bleak. My expectation was sagetv was going to die and another up and coming dvr would come along. I decided to write my server side code with the idea of being able to switch to support another dvr. The safest way to accomplish this was to not write my server side code inside sagetv as plugin but as a separate app that can call into sagetv as needed. I started writing my server side code in c# as web app hosted in IIS. I struggled with this for months trying to be able to run code every so often to sync with sagetv. I had to give up on running under IIS and switch to being my own host and using Nancyfx. This gave me self hosting in my own c# app. Meanwhile I was writing the client side in Objective C. This was my first exposure to development on IOS so things were slow but progressing. Meanwhile Apple was talking great things about their new “Swift 1.0” language. I saw the handwriting on the wall and scrapped my Objective C version and started over using Swift. I initially was sending a json dataset of movies/show info from my test server. My test server only had a dozen or so movies in it though. I moved my code to my “real” server which has over 2000 media items on it and transfer times and loading times on IOS sucked! Disgusted and frustrated I looked for a better way. Sqlite was my answer! The amazing open source – cross platform database. All I had to do was scrap most of my server code, portions of the client and redo it to build a database of the sagetv info and send down a db when the client connects. Now I was able to show sagetv info on IOS. Watching anything was not possible though. I did a few test encodes with handbrake on the server and downloading the mp4 file to ios. Playback worked but encoding on the server was rather slow on my dated server. I upgraded the sever and got a large drive to hold the encoded media. I then wrote server code to encode “new” media each night. By the summer of 2015 we were watching media on vacations with the app. In the mean time sagetv instead of dying was going open source! The app was functional but it sucked that everything had to be encoded first though. With sagetv going open source the possibility of releasing the app so other people could use it came to mind. A quick review of the Apple IOS app store requirements told me what I already expected. All video streaming over 10 seconds in length must use HLS. It didn’t take much google searching to determine ffmpeg was answer. I saw there were two paths I could take. The first is have ffmpeg just stream the existing media to the ios client. This had the advantage that later on supporting watching live tv should be easy to add but the downside of not being able to support chapters for comskip. The other approach is have ffmpeg generate the hls files when asked for and when the server has 15-30 seconds worth have the client start watching. This approach has the advantage of being able to support chapters for comskip but the disadvantage of being more work to support watching live tv. I went with this approach as commercial skipping was one of the big benefits of sage.

One of the issues I really struggled with Sagetv 7 was keeping my database of movies/show in sync with Sage. I saw that as a plugin I can use the SageTVEventListener to get notified when media is added, imported or removed. I thought I was home free until I realized I get no notification if the user changes the title or description. I also found no way to get the poster image file name for a media item. If I had the image filename I can easily look if the file name changed or the file date is newer. Not finding a way to accomplish this I ended up just making a hash of the image and saving the hash in the db. Now every 24 hours of so my code asks for all sage info for movies, shows and their poster images. I save it all in a temporary database then compute any differences between the master database and the temporary database. I am then able to version number the change set. Now when the ios client connects he tells the server what database version number he has and the server is able to just send down the changes to make that client current. If the client connects for the first time obviously he just gets the full database. Now the client is able to quickly sync with server with very little data actually being transferred.

I started having memory leaks on my sage 7 server when I started running this code. I worked around it by restarting sagetv every so often. I assumed it would “fix itself” when I moved to sage 9 but I see the same thing happens. Just with in the last 2 months I have added guide data to the app. On the good side on the server end I am able to discover from an ini file when the epg data has been updated and only ask for the guide data then. But the server code getting the epg data every day and asking for all of the movies, shows and poster images every data makes the memory issue happen faster. Sometimes I get an Out of memory error in Sagetv in addition to the attached error message from the code. In either case the JVM heap size total as shown in setup/system Information is either 1038MB or close to it. Also several hours later the memory usage is still the max or very close to it. I have to restart sagetv again before I can get sagetv info again.

[stuckless]

This is likely a memory leak in the sagex apis...

When a call to the server is made and it creates an object, that object cannot be sent back to client, as is, so what is sent is actually an ObjRef (Object Reference). This "reference" is then passed back to the server when subsequent calls are made against the object. To make this process somewhat efficient, those object references are "cached" on the server and a background process (RemoteObjectReaper) is run every 180 seconds (by default) to clean up the stale objects. If this reaper is not run, or it can't clean up the objects, then I can see where we'd get an OOM error.

in a peice of sample code that allocates 1000s of objects in a very short time, in a loop, it will definately get an OOM error, since the Reaper is set to run every 180 seconds, and you'll likely fill up the memory long before that.

In a normal situation, it is expected that you might allocate 100s or thousands of references but, generally you'll be done with them in about 3 minutes and they should all be reclaimed after that.

In your case, it seems like the Reaper is maybe not being run...
In the logs/sagex-api.log (if the logging is set to debug), you should see messages like...

Remote Object Reaper created to monitor stale objects every  xx seconds

Added Task XX to run every NN ms

And if you are using the RPC handler, which will allocate objects, then you should seem messages like...

Removed NN stale remote objects

It's interesting, that even in my environment, I'm not seeing the "Removed" logging statements... so maybe the Reaper is broken. I'm going to verify that the reaper is working, since, if it isn't then for sure that is the culprit here.

And finally, if 180 seconds is too long, you can change the property

sagex/api/reaperInterval

You can set it to 20, so that the reaper will run every 20 seconds.

[davidb]

I did see the behavior running my code but in a few weeks. The sample just hopefully speeds up demonstrating the problem. The file sagex-api.log is 0 bytes but the sagex-api.log.1 has logs. In it I do not see any RemoteObjectReaper messages but do see the calls where memory would have been allocated. So it looks the the reaper is not being run. I do see the Reaper Interval set to 180 in the configure plugin details. If I understand correctly the reaper will clear out stale objects every 180 seconds. If thats the correct if its running then that would work in my case. The attached sample takes many hours before it fails so clearing stale items every 180 seconds would take care of it.

David

Originally Posted by stuckless

This is likely a memory leak in the sagex apis...

When a call to the server is made and it creates an object, that object cannot be sent back to client, as is, so what is sent is actually an ObjRef (Object Reference). This "reference" is then passed back to the server when subsequent calls are made against the object. To make this process somewhat efficient, those object references are "cached" on the server and a background process (RemoteObjectReaper) is run every 180 seconds (by default) to clean up the stale objects. If this reaper is not run, or it can't clean up the objects, then I can see where we'd get an OOM error.

in a peice of sample code that allocates 1000s of objects in a very short time, in a loop, it will definately get an OOM error, since the Reaper is set to run every 180 seconds, and you'll likely fill up the memory long before that.

In a normal situation, it is expected that you might allocate 100s or thousands of references but, generally you'll be done with them in about 3 minutes and they should all be reclaimed after that.

In your case, it seems like the Reaper is maybe not being run...
In the logs/sagex-api.log (if the logging is set to debug), you should see messages like...

Remote Object Reaper created to monitor stale objects every  xx seconds

Added Task XX to run every NN ms

And if you are using the RPC handler, which will allocate objects, then you should seem messages like...

Removed NN stale remote objects

It's interesting, that even in my environment, I'm not seeing the "Removed" logging statements... so maybe the Reaper is broken. I'm going to verify that the reaper is working, since, if it isn't then for sure that is the culprit here.

And finally, if 180 seconds is too long, you can change the property

sagex/api/reaperInterval

You can set it to 20, so that the reaper will run every 20 seconds.

[phantomii]

Was gonna post a separate message today on my Heap observations comparing my windows server and my new linux server I am building. This though seem like a good place to drop my note.

I have had a SageTV Windows 10 machine running & Supporting several HD200's, and HD300 and a few Miniclients. I have always had Heap issues which caused me to reboot periodically as memory climbs and stays high.

I built a linux machine over the past few weeks as a test to eventually replace my windows machine. I noted when connecting a few clients to it this weekend that the Heap memory did not climb anywhere near as high as the windows box and it did appear to eventually come down where with windows it did not.

Not sure this is related to this issue but it sounds like it might be to my uneducated eye. Sorry if I am wrong about that.

[EnterNoEscape]

Originally Posted by phantomii

Was gonna post a separate message today on my Heap observations comparing my windows server and my new linux server I am building. This though seem like a good place to drop my note.

I have had a SageTV Windows 10 machine running & Supporting several HD200's, and HD300 and a few Miniclients. I have always had Heap issues which caused me to reboot periodically as memory climbs and stays high.

I built a linux machine over the past few weeks as a test to eventually replace my windows machine. I noted when connecting a few clients to it this weekend that the Heap memory did not climb anywhere near as high as the windows box and it did appear to eventually come down where with windows it did not.

Not sure this is related to this issue but it sounds like it might be to my uneducated eye. Sorry if I am wrong about that.

Being a former Windows server user, I have noticed similar behavior despite running even more on heap plugins. I have been curious about this behavior too, but usually takes a few days to really turn into a problem. In Linux, my server never seems to go above 600MB over a span of weeks. In Windows, I'd hit 1023MB after about 3 days and things would get noticeably slower after a week or two. Both of these were using Java 8.

[stuckless]

If you have access to 'jmap' (it's installed on my linux machine as part of the jdk, I think), you might get able to get some information about the running process... especially if you've encountered an OOM error.

On my linux machine, I just dumped my dev sagetv server (that is running fine).

# sudo jmap -histo -F 30266

Attaching to process ID 30266, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.111-b14
Iterating over heap. This may take a while...
Object Histogram:

num 	  #instances	#bytes	Class description
--------------------------------------------------------------------------
1:		370435	24953600	char[]
2:		311585	9970720	java.awt.geom.Rectangle2D$Float
3:		368272	8838528	java.lang.String
4:		17667	6234272	java.lang.String[]
5:		152910	4893120	java.util.HashMap$Node
6:		169725	4316656	tv.sage.mod.AbstractWidget[]
7:		48355	3868400	tv.sage.mod.Nomed
8:		12654	2643952	int[]
9:		35593	2562696	tv.sage.mod.Named
10:		6134	2179160	byte[]
11:		21148	1744160	java.lang.Object[]
12:		3341	1683864	sage.ZPseudoComp
13:		1967	1421560	long[]
14:		5250	1383472	boolean[]
15:		5665	1293088	java.util.HashMap$Node[]
16:		374	1218160	java.awt.geom.Rectangle2D$Float[]
17:		7867	887160	java.lang.Class
18:		18982	607424	java.util.concurrent.ConcurrentHashMap$Node
19:		18029	576928	sage.jep.JEP$CommandElement
20:		6197	446184	tv.sage.mod.Valued
21:		5360	428800	tv.sage.mod.Attribute
22:		12293	393376	java.awt.Color
23:		4993	390672	sage.Widget[]
24:		5075	365400	java.util.regex.Pattern
25:		7605	365040	sage.jep.JEP
26:		10168	325376	java.util.regex.Pattern$Curly
27:		12073	289752	java.util.ArrayList
28:		7078	283120	java.util.LinkedHashMap$Entry
29:		5283	253584	java.util.HashMap
30:		10151	243624	java.util.regex.Pattern$GroupTail
31:		10149	243576	java.util.regex.Pattern$GroupHead
32:		1053	227448	sage.ZImage
....

Now this doesn't indicate a memory leak, just lists the object counts and byte allocations, per object type. Using this we might be able to pinpoint which objects are consuming the most memory, and then try to narrow down why they are not being released.

[phantomii]

Since the machine I appear to be having issues with is my windows box and not my new linux box is the jmap capability also available on Windows? Not familiar with it at all.....

[stuckless]

Originally Posted by phantomii

Since the machine I appear to be having issues with is my windows box and not my new linux box is the jmap capability also available on Windows? Not familiar with it at all.....

if you have the JDK installed then maybe it is... you can run jmap from the command line and see if you get a command not not.

[wnjj]

Originally Posted by stuckless

if you have the JDK installed then maybe it is... you can run jmap from the command line and see if you get a command not not.

Jmap is on my windows machine in the jdk\bin directory.

[phantomii]

So got the JDK loaded on my windows machine and found the jmap application. Wanted to see what I could see and learn with it, but my first hurdle was identifying the PID? Any hint would be appreciated......

[davidb]

The windows task manager can show the PID. If the pid is not showing in task manager Do menu "View/Select Columns". The first item is PiD(Process Identifier). Click to enable it.

Originally Posted by phantomii

So got the JDK loaded on my windows machine and found the jmap application. Wanted to see what I could see and learn with it, but my first hurdle was identifying the PID? Any hint would be appreciated......

[phantomii]

Thanks so much for the reply. That is what I had thought but when attempting to use the PID in task Manager for the SageTV service I receive the following response. I don't think there is a syntax issue and I ran the command prompt in Admin mode.

C:\Program Files (x86)\Java\jdk1.8.0_112\bin>jmap -histo -F 2616
Attaching to process ID 2616, please wait...
Error attaching to process: Doesn't appear to be a HotSpot VM (could not find symbol "gHotSpotVMTypes" in remote process)
sun.jvm.hotspot.debugger.DebuggerException: Doesn't appear to be a HotSpot VM (could not find symbol "gHotSpotVMTypes" in remote process)
at sun.jvm.hotspot.HotSpotAgent.setupVM(HotSpotAgent.java:411)
at sun.jvm.hotspot.HotSpotAgent.go(HotSpotAgent.java:305)
at sun.jvm.hotspot.HotSpotAgent.attach(HotSpotAgent.java:140)
at sun.jvm.hotspot.tools.Tool.start(Tool.java:185)
at sun.jvm.hotspot.tools.Tool.execute(Tool.java:118)
at sun.jvm.hotspot.tools.ObjectHistogram.main(ObjectHistogram.java:64)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at sun.tools.jmap.JMap.runTool(JMap.java:201)
at sun.tools.jmap.JMap.main(JMap.java:130)


C:\Program Files (x86)\Java\jdk1.8.0_112\bin>