Out of memory with 4GB allocated to Sage Heap

[BobPhoenix]

I am using the Docker image of SageTV on Docker. I have the memory allocated to the docker set to 6GB and the SageTV heap set to 4GB. I put the logs from a recent restart of the docker that shows the Heap out of memory exception along with a SystemInfo.txt file from "SystemInfo" screen from immediately before the OOM exception. I have seen this OOM error before but this is the first time I had a good log to post.

Thoughts? Suggestions?

Can't attache the file evidently since it is 3MB in size archived. Will try upload it elsewhere and attache a link.

OK let me know if you can get to the archive here: https://www.dropbox.com/s/q4rzr1x3vk...TVLog.zip?dl=0

[BobPhoenix]

Just to update this a little bit.

I got a bad recording message from SageTV and was browsing to find the file in the GUI so I could delete it when it happened. I deleted two of the recordings I made today from MC in unRAID and have been able to display all the others of that show now without an OOM error. So it was a bad recording that caused it. But with 4GB of memory allocated to SageTV I would not have thought it would run out of memory that easy.

[stuckless]

In looking at the log I can see that you are experiencing some ui "hang time" and then it hits an OOM. The precise code that is doing the OOM is

Wed 9/28 16:39:02.526 [EventRouter-0023a5000a6a@56e2dcd] EventRouter Threw An Exception:java.lang.OutOfMemoryError: Java heap space
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] java.lang.OutOfMemoryError: Java heap space
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at java.util.Arrays.copyOf(Arrays.java:3332)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:137)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:121)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:569)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at java.lang.StringBuffer.append(StringBuffer.java:369)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.IOUtils.getInputStreamAsString(IOUtils.java:662)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.IOUtils.getFileAsString(IOUtils.java:681)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.api.Utility$118.runSafely(Utility.java:2971)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.PredefinedJEPFunction.run(PredefinedJEPFunction.java:112)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.jep.JEP$CommandEvaluator.evaluate(JEP.java:586)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.jep.JEP.getValueAsObject(JEP.java:428)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.Catbert.evaluateExpression(Catbert.java:641)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.processChain(ZPseudoComp.java:4641)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.processChain(ZPseudoComp.java:4680)
Wed 9/28 16:39:02.528 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.processParentActions(ZPseudoComp.java:5212)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:4928)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Wed 9/28 16:39:02.529 [EventRouter-0023a5000a6a@56e2dcd] 	at sage.ZDataTable.buildUIForData(ZDataTable.java:1849)
Wed 9/28 16:39:02.532 [AWTThreadWatcher-0023a5000a6a@50c6473a] EventThread-0023a5000a6a Hang Detected - hang time = 18074 UILocker=null

It appears that it is trying to load a file into memory, but I don't know what file it is accessing... Not sure if there is a way to turn on sagetv function logging to get the parameter that is passed here. Interesting enough, this is failing in code that I recently changed, but, I don't think my changes are causing this (I reviewed them again, to just to make sure).

I think that you our OOM issue is either the UI is trying to load a very large file into memory... OR the hang time is happening because of some other endless loop condition causing the UI to hang and then eventually run out memory.

Maybe Jeff can suggest some logging options to capture this.

[Narflex]

Right before that event...memory usage was fine:

Wed 9/28 16:38:10.294 [Seeker@17fe92a1] MemStats: Used=366MB Total=499MB Max=3817MB

Grepping for 'MemStats' is a good trick for seeing JVM heap usage over time.

This would lead me to believe that whatever was trying to read that file in as a String was reading a very large file.

In the default STV...there is very little usage of the GetFileAsString API call (all the ones I found looked like accessing stuff in /sys/, which is probably for RAID, wifi and other things that are likely not used by anybody but me). So it's probably something from one of your plugins. If you can reproduce it...then I'd just build a new version and log out what file it's trying to read in that function and that'll give you more insight as to why. I don't think there's any other logging you can turn on that would help.

Alternatively, just look to see if you have some huge EDL or .properties file in your recordings/import dirs or something else that would normally get accessed like that.

[stuckless]

I can build and post a debug Sage.jar that will log out files opened via GetFileAsString if you can't build it yourself.

[BobPhoenix]

I was afraid it was a plugin. I will try to build my own jar to output the info. Also look for large properties and edls. Not sure which it was at this point since I deleted the bad recording and they don't happen every day. Will update the appropriate plugin thread and this one when I figure out which one is most likely.

[KarylFStein]

Originally Posted by stuckless

I can build and post a debug Sage.jar that will log out files opened via GetFileAsString if you can't build it yourself.

Off topic, sorry, but is there some method that will send a stack trace (or string) to the log like the previous log snippit seems to suggest? Last night I was trying to debug a problem with my Hauppauge card and ended up taking one of the SystemMessage methods, giving it a string as an argument then passing something I found with Google to convert a stack trace to a string. I'm not sure if it worked as when I loaded it I got a corrupted wiz.bin and reverted to the latest stuckless JAR. It would be nice to use something already in the core code so I don't have to redo the custom logging method after a sync...

[stuckless]

Originally Posted by KarylFStein

Off topic, sorry, but is there some method that will send a stack trace (or string) to the log like the previous log snippit seems to suggest? Last night I was trying to debug a problem with my Hauppauge card and ended up taking one of the SystemMessage methods, giving it a string as an argument then passing something I found with Google to convert a stack trace to a string. I'm not sure if it worked as when I loaded it I got a corrupted wiz.bin and reverted to the latest stuckless JAR. It would be nice to use something already in the core code so I don't have to redo the custom logging method after a sync...

If you have an exception... ie, something like...

try {
  // do something
} catch (Exception  e) {
   e.printStackTrace(); // will write the stacktrace to the log.
}