No Fanart displayed - Exception in getValueAsObject

[wayner]

This has happened before and I believe it can be fixed with a SageTV restart - but I am not getting any Fanart appearing for either Move Walls or TV banners. (I need a maintenance window from the family to restart).

Any idea what is happening? In my SageTV logs I got lots of messages like the following:

Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] EXCEPTION in getValueAsObject:sage.jep.ParseException: Error in method reflection of Gemstone_ImageCache_GetPoster of java.lang.reflect.InvocationTargetException for:Gemstone_ImageCache_GetPoster(PosterVideoCell,PosterRefreshArea,FullPoster)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] sage.jep.ParseException: Error in method reflection of Gemstone_ImageCache_GetPoster of java.lang.reflect.InvocationTargetException
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.Catbert$ReflectedJEPFunction.run(Catbert.java:2150)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.jep.JEP$CommandEvaluator.evaluate(JEP.java:586)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.jep.JEP.getValueAsObject(JEP.java:428)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.Catbert.evaluateExpression(Catbert.java:641)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.processChain(ZPseudoComp.java:4641)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.processParentActions(ZPseudoComp.java:5212)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:4995)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.714 [ReProcessHook@6dbe39b9] 	at sage.ZDataTable.evaluate(ZDataTable.java:1439)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.PseudoMenu.refresh(PseudoMenu.java:1117)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.api.Global$1.runSafely(Global.java:77)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.PredefinedJEPFunction.run(PredefinedJEPFunction.java:110)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.jep.JEP$CommandEvaluator.evaluate(JEP.java:586)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.jep.JEP.getValueAsObject(JEP.java:428)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.Catbert.evaluateExpression(Catbert.java:641)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.processChain(ZPseudoComp.java:4641)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.ZPseudoComp.processChain(ZPseudoComp.java:4579)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.Catbert.processHookDirectly(Catbert.java:493)
Sat 9/9 12:35:22.715 [ReProcessHook@6dbe39b9] 	at sage.Catbert.processUISpecificHook(Catbert.java:465)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at sage.Catbert$3.run(Catbert.java:404)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at sage.Pooler$PooledThread.run(Pooler.java:254)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] Caused by: java.lang.reflect.InvocationTargetException
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at sun.reflect.GeneratedMethodAccessor156.invoke(Unknown Source)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at java.lang.reflect.Method.invoke(Method.java:498)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at sage.Catbert$ReflectedJEPFunction.run(Catbert.java:2142)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	... 35 more
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] Caused by: java.util.NoSuchElementException
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at java.util.LinkedList.removeLast(LinkedList.java:283)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at Gemstone.SoftHashMap.get(SoftHashMap.java:45)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at Gemstone.ImageCache.GetImage(ImageCache.java:234)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at Gemstone.ImageCache.GetImage(ImageCache.java:213)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at Gemstone.ImageCache.GetArtifact(ImageCache.java:180)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at Gemstone.ImageCache.GetArtifact(ImageCache.java:162)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	at Gemstone.ImageCache.GetPoster(ImageCache.java:128)
Sat 9/9 12:35:22.716 [ReProcessHook@6dbe39b9] 	... 39 more
Sat 9/9 12:35:22.717 [ReProcessHook@6dbe39b9] java.lang.reflect.InvocationTargetException
Sat 9/9 12:35:22.717 [ReProcessHook@6dbe39b9] sun.reflect.GeneratedMethodAccessor156.invoke(Unknown Source)
Sat 9/9 12:35:22.717 [ReProcessHook@6dbe39b9] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Sat 9/9 12:35:22.717 [ReProcessHook@6dbe39b9] java.lang.reflect.Method.invoke(Method.java:498)
Sat 9/9 12:35:22.717 [ReProcessHook@6dbe39b9] sage.Catbert$ReflectedJEPFunction.run(Catbert.java:2142)
Sat 9/9 12:35:22.717 [ReProcessHook@6dbe39b9] sage.jep.JEP$CommandEvaluator.evaluate(JEP.java:586)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.jep.JEP.getValueAsObject(JEP.java:428)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.Catbert.evaluateExpression(Catbert.java:641)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.processChain(ZPseudoComp.java:4641)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.processParentActions(ZPseudoComp.java:5212)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:4995)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.718 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZDataTable.evaluate(ZDataTable.java:1439)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.PseudoMenu.refresh(PseudoMenu.java:1117)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.api.Global$1.runSafely(Global.java:77)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.PredefinedJEPFunction.run(PredefinedJEPFunction.java:110)
Sat 9/9 12:35:22.719 [ReProcessHook@6dbe39b9] sage.jep.JEP$CommandEvaluator.evaluate(JEP.java:586)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.jep.JEP.getValueAsObject(JEP.java:428)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.Catbert.evaluateExpression(Catbert.java:641)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.processChain(ZPseudoComp.java:4641)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.processChain(ZPseudoComp.java:4579)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.Catbert.processHookDirectly(Catbert.java:493)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.Catbert.processUISpecificHook(Catbert.java:465)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.Catbert$3.run(Catbert.java:404)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] sage.Pooler$PooledThread.run(Pooler.java:254)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] java.util.NoSuchElementException
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] java.util.LinkedList.removeLast(LinkedList.java:283)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] Gemstone.SoftHashMap.get(SoftHashMap.java:45)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] Gemstone.ImageCache.GetImage(ImageCache.java:234)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] Gemstone.ImageCache.GetImage(ImageCache.java:213)
Sat 9/9 12:35:22.720 [ReProcessHook@6dbe39b9] Gemstone.ImageCache.GetArtifact(ImageCache.java:180)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] Gemstone.ImageCache.GetArtifact(ImageCache.java:162)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] Gemstone.ImageCache.GetPoster(ImageCache.java:128)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sun.reflect.GeneratedMethodAccessor156.invoke(Unknown Source)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] java.lang.reflect.Method.invoke(Method.java:498)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.Catbert$ReflectedJEPFunction.run(Catbert.java:2142)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.jep.JEP$CommandEvaluator.evaluate(JEP.java:586)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.jep.JEP.getValueAsObject(JEP.java:428)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.Catbert.evaluateExpression(Catbert.java:641)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.processChain(ZPseudoComp.java:4641)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.processParentActions(ZPseudoComp.java:5212)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:4995)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluateTree(ZPseudoComp.java:1154)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9] sage.ZPseudoComp.evaluate(ZPseudoComp.java:5127)
Sat 9/9 12:35:22.721 [ReProcessHook@6dbe39b9]

[jusjoken]

Gemstone uses a SoftHashMap to hold fanart in memory for performance of flows that show lots of fanart. When adding to the map and if the "hard part" of the map is at it's max (this is the Min Cache size...see below) then the "last" (oldest) item in the hard list is removed. That process is failing and generating this exception. It's very hard to know why this is failing as it obviously does not fail all the time so I would need more info around the issue... if only a restart resolves this then likely it will be hard to recreate a specific case to cause this but if you do, please report it.

I likely will take a different approach in G2 but we do need to keep the images in memory or the flows will be VERY slow.

PS, in the Utility, Image Options you can increase the Min size of that cache so that it increases the performance but it WILL increase the memory as that many images will ALWAYS be in memory (until a restart). The default is 10 if I recall. And if there is an issue with this SoftHashMap solution this may increase/decrase the occurrence of the issue.

k

[wayner]

Restarting the server did fix the client.

I have only seen this on my unRAID server, I don't think I ever had this problem on my Windows server.

What does a Cache Min Size of 10 mean? What should I set it to? 20? 100? 1000?

I have set my JVM heap size to 3GB and I have never hit more than 2GB, even when I was running about a dozen or more miniclients. So using more memory isn't too big of an issue for me. Does it use one cache across all miniclients?

[jusjoken]

Yes, one shared cache for miniclients and you really need to experiment on values and see what happens as it was written a long time ago and i plan to replace it anyway as i am sure its part of the issue of consuming too much memory

I will experiment with other approaches soon and see where i land.

k

[wayner]

Ok, I am trying 20 for now - should I Clear the Memory Cache and/or restart Sage? It does say that changing this value will reset the cache.

[wayner]

HOLY CRAP!!!!

Changing that setting from 10 to 20 gave me the best performance improvement I have ever seen with SageTV/Gemstone. It's like I got a new CPU with twice the clock speed and double the cores and went from a physical hard drive to an SSD. The images on Movie Walls used to populate very slowly and it was a slow process to scroll through the pages. Now it scrolls as quickly as you can push the button. The same thing for TV screens that have banners - when you paged down it would take a few seconds for all of the banner images to appear. Now they are immediately there.

And I don't notice much of an increase in memory usage - I have four clients connected and am using about 1GB.

I would recommend that everyone using Gemstone increase this parameter - unless they are having memory issues. For those of us on Linux/unRAID then memory is unlikely to be an issue.

[wayner]

This error is re-occurring on a regular basis. Any advice on what to do to try to ease the issue?

When it occurs the logging goes batsh!t and fills up each of the log files every couple of minutes so I can't even find the first entry that causes this issue or it has rolled off the oldest log since the logging is so verbose.

[jusjoken]

Originally Posted by wayner

This error is re-occurring on a regular basis. Any advice on what to do to try to ease the issue?

When it occurs the logging goes batsh!t and fills up each of the log files every couple of minutes so I can't even find the first entry that causes this issue or it has rolled off the oldest log since the logging is so verbose.

If its the same issue then a restart is the only solution until i rewrite that part of the code. You could disable caching but you wont like the performance

k

[wayner]

Just want to mention that this error still occurs - despite the fact that I restart SageTV on a weekly basis (the restart is forced by the unRAID docker backup process). This error just came up now on Sunday - SageTV will restart at 3am on Sunday night/Monday morning.