SJQv4: Technology Preview

[rlvogel322]

Originally Posted by wayner

FYI - I am very happy to pay for the upgrade. I personally don't mind if developers charge a small fee, or if they ask for donations to a charity of their choice.

Agreed! I look forward to SJQ4 so I donated to get my license file all ready for the beta.

[wayner]

Originally Posted by Slugger

I believe you already have a SageAlert license file? SJQv4 uses the same one so no need to donate again. You just have to register your email address with SJQv4 after the upgrade and you'll be good to go. (A future update will centralize the sagetv-addons license registration such that you don't need to register with every plugin, but that's not done yet and won't be for SJQv4 beta 1).

That's true but I am moving to a new server in the next few weeks. How do I move the license to new hardware?

[Slugger]

Originally Posted by wayner

That's true but I am moving to a new server in the next few weeks. How do I move the license to new hardware?

Once you get the new hardware setup, go here and enter the email address you donated with and it'll send you a new license file.

[kevine]

Originally Posted by Slugger

1. I'm investigating a possible memory leak with SJQv4. I 99% sure it's not SJQ that was leaking, but I've had to strip all plugins, etc. from my producton server and am running barebones + SJQ under my production load to verify. It has been 4-5 days to exhaust the heap memory on my production server (never happened on my dev server) so it's going to be a couple more days before I get some conclusive results. Hopefully everyone eagerly awaiting SJQv4 can appreciate the few extra days.

We may have the same leak. SageTV Service goes to 1.2 GB. Then I must restart the server. I cannot even stop the service. Here is where I reported a lot of my symptoms. Sage support suggested it was a plugin too. Maybe we should look at the commonalities in our plugins.

[Slugger]

Originally Posted by kevine

We may have the same leak. SageTV Service goes to 1.2 GB. Then I must restart the server. I cannot even stop the service. Here is where I reported a lot of my symptoms. Sage support suggested it was a plugin too. Maybe we should look at the commonalities in our plugins.

You don't have SJQv4 installed, which is a good sign (for me). Unless you've manually downloaded the builds from Google Code and installed them yourself? Unfortunately, I'm still seeing the issue. I haven't actually ran out of memory yet, but it's been 4.5 days and my heap values are on the brink of exhaustion. I expect it to go tonight or tomorrow. I'm still running SJQv4 (and all its deps - jetty + a whole bunch of helper jars) and comskip UI, nielm web ui, SRE and SageAlert. I've removed what I thought was the culprit (I won't mention any plugins by names here without hard evidence), but now I'm not so sure. If heap exhausts again then I'm going to have to strip away everything (actually, probably do a fresh install of 7.0.23) and try again. The plugins I'm running now are ones I've been running for ever and have never ran into OOM exceptions and until I hit this the first time I've never increased my heap from the default 389MB. I ran on 389MB of heap since I started using Sage (v6.0) and it's never been an issue. First time I had an OOM (couple weeks ago) coincided with a bunch of new plugins I added and the upgrade to 7.0.23 (from 7.0.18). I accounted for the OOM due to the number of extra plugins I had installed plus I figured v7 probably just needed a little more heap in and of itself.

Now I'm starting to wonder just what's causing the OOM exceptions. If I exhaust again then I will strip back to a fresh install of 7.0.23 and see what happens. I really don't want to have to do this, but I can't file a bug report based on the current state of my server so...

[kevine]

I am running basically the same ones you are except v3 of SJQ. I also have the mobile web ui installed. I also stripped down. Had a bunch installed before. I will also be doing a fresh install this weekend from WHS to Win7 64 bit fresh install but copying over wiz.bin.

[BobPhoenix]

On a related note I see a memory leak in the SageTVServiceControl app.

Here is what I sent on a support ticket:
"The service control app appears to have a memory leak. On my Windows 7 x64 system I left it up in an RDP session for over a day now and Task Manager has the memory use for the process (SageTVServiceControl.exe *32) at 1,716,964K. Appears to only be a problem with Win7 x64 because this didn't happen with WinXP (32 bit). I have UAC turned OFF...". I also noted that this machine has 6GB of memory in my submission.

[razrsharpe]

I think i might be running into the same issue. A memory leak that is exhausting my heap. I discovered this because sjq v3 wasnt processing new jobs (hadn't been for a couple days). I went to investigate and could not log in to the web ui. Looked at my heap usage and i was maxed out (used/total/max = 450ish/779/779). The service was consuming about 980mb. I tried to stop the service using the control applet but that did not work. Needed to stop the exe's in task manager to get things back. Restarted sage and things seem better... but this morning the service is up to using 850mb again (and my heap is 356/571/779).

Looking in the sagetv.log i see where exit is called then its starts stopping plugins, it gets through a couple then it calls stop on jetty and it doesnt call stop on anything after that (and there are definitely other plugins installed)... so perhaps its a memory leak in jetty. After trying to stop the service the correct way i was very patient with it (i waited about 2 min before killing the process manually).

Thu 12/9 21:39:57.581 [main@a9ae05] Sage.exit() called.
Thu 12/9 21:39:57.581 [main@a9ae05] Stopping all core plugins
Thu 12/9 21:39:57.581 [main@a9ae05] Calling stop on plugin: Custom Events
Thu 12/9 21:39:57.581 [main@a9ae05] Calling stop on plugin: Sage Artifact Delete (SAD)
Thu 12/9 21:39:57.581 [main@a9ae05] Calling stop on plugin: SageMyMovies API
Thu 12/9 21:39:57.582 [main@a9ae05] Calling stop on plugin: SageAlert
Thu 12/9 21:39:57.603 [main@a9ae05] Calling stop on plugin: Jetty Web Server

I am going to submit this to support to see if they have any insight....

EDIT: i just disabled all plugins restarted the service and we will see what my heap does (just after restart its 223/429/779)

[kevine]

Originally Posted by razrsharpe

I think i might be running into the same issue. A memory leak that is exhausting my heap. I discovered this because sjq v3 wasnt processing new jobs (hadn't been for a couple days). I went to investigate and could not log in to the web ui. Looked at my heap usage and i was maxed out (used/total/max = 450ish/779/779). The service was consuming about 980mb. I tried to stop the service using the control applet but that did not work. Needed to stop the exe's in task manager to get things back. Restarted sage and things seem better... but this morning the service is up to using 850mb again (and my heap is 356/571/779).

Looking in the sagetv.log i see where exit is called then its starts stopping plugins, it gets through a couple then it calls stop on jetty and it doesnt call stop on anything after that (and there are definitely other plugins installed)... so perhaps its a memory leak in jetty. After trying to stop the service the correct way i was very patient with it (i waited about 2 min before killing the process manually).

Thu 12/9 21:39:57.581 [main@a9ae05] Sage.exit() called.
Thu 12/9 21:39:57.581 [main@a9ae05] Stopping all core plugins
Thu 12/9 21:39:57.581 [main@a9ae05] Calling stop on plugin: Custom Events
Thu 12/9 21:39:57.581 [main@a9ae05] Calling stop on plugin: Sage Artifact Delete (SAD)
Thu 12/9 21:39:57.581 [main@a9ae05] Calling stop on plugin: SageMyMovies API
Thu 12/9 21:39:57.582 [main@a9ae05] Calling stop on plugin: SageAlert
Thu 12/9 21:39:57.603 [main@a9ae05] Calling stop on plugin: Jetty Web Server

I am going to submit this to support to see if they have any insight....

EDIT: i just disabled all plugins restarted the service and we will see what my heap does (just after restart its 223/429/779)

Your problem sounds almost exactly like mine. Only difference is sometimes it was past the point of handling the problem gracefully. In those instances I would have to restart the server. Sometimes still with a hard reboot. However, I never thought to check the Java heap. I only looked at the memory the service was using. I will look at the heap if it happens again. However, it may not as I am resinstalling this weekend. Support wanted a plugin-less SageTV to look into the problem. It is good that you started to take that route.

[razrsharpe]

Originally Posted by razrsharpe

I think i might be running into the same issue. A memory leak that is exhausting my heap.

just to follow up with what support said....

Since my currently used heap was not at or near the max (first number vs third number) i did not have memory leak. They said the behavior that i was seeing (log gagging on stopping jetty gracefully, not able to access sjq web app) was an indication that the problem resides with that plugin... My jetty request log had no entries for about 36 hours (usually its filled with sjq requests) so it looks like for some reason jetty crashed silently and it took me a while to find it... I'll post over there just to give jreichen a heads up (don't know how useful that will be since the only jetty logs i have are the request logs which will indicate when it stopped working but not why).

[Slugger]

Right now I see 300/771/779. But if I'm recording from the HDPVR, a PVR-250 and watching an HDPVR recording simultaneously, then that's when the total starts creeping oh so close to max. When I had a bunch of other plugins installed that's when I ran out of memory - unfortunately the stack traces dumped 3GB of OOM exception logs in about 8 minutes and so I had to stop Sage and wipe the logs. Uninstalling a lot of plugins seems to have got things under control, but not completely (used = 771 vs. max = 779). It seems during peak usage (multiple recordings + viewing on an HD200) is when things start creeping close to the trouble area. If I manage to get by that peak time then by morning the numbers seems to return to about what they are right now. I can easily get used up over 450 by simply starting to view an HDPVR recording on my HD200 (stock theme with a few mods like SRE and SJQ UI mods, 24 hr clock mod, comskip playback). Should the core be grabbing 150+ MB of heap just to do playback of a H.264 recording?

[meisner]

Originally Posted by meisner

Excellent! thanks for the reply.

My SJQ setup really just runs comskip (donator version) and then runs a VB script to fixup a skew that always happens due to the video stream created by the HD-PVR. I just need to launch comskip.exe, call the MediaInfo.GetFileDuration() function, and then call the VB script (via cscript.exe). After reading some of the SJQv4 & Groovy docs, this should be an easy Groovy script to write.

Famous last words...

I need to retrieve the actual length of a recording since there is a difference between sage and the actual. The .cmd below in my groovy script runs the VB script to adjust the edl file based on the differences in duration.

Here is my groovy script I am using to launch comskip (I have the executable set to "script:C:\comskip.groovy"

Object mediaFile = MediaFileAPI.GetMediaFileForID(SJQ4_METADATA.get("SJQ4_ID").toInteger()) 
Integer duration = MediaFileAPI.GetFileDuration(SJQ4_METADATA.get("SJQ4_ID").toInteger())
String file = SJQ4_METADATA.get("SJQ4_PATH") + SJQ4_METADATA.get("SJQ4_LAST_SEGMENT")

Process cmd = "C:/comskip/RunComSkip.cmd \"${file}\" ${duration}".execute()
cmd.waitFor()
return cmd.exitValue()

I never see comskip run in task manager. The sjq agent log file has:

2010-12-17 08:27:06,756 INFO  [Exe]: Received task 19 of type 'COMSKIP' from 192.168.0.30:23347...
2010-12-17 08:27:06,756 INFO  [192_168_0_30-23347-19]: Starting process runner for: Task[id=COMSKIP, reqRes=100, maxInst=1, sched=ON, maxTime=6000, maxTimeRatio=1.0, rc=0-0, exe=script:C:\comskip\comskip.groovy, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=C:\comskip\comskip_test.groovy, testArgs=ts]
2010-12-17 08:27:06,756 INFO  [ProcessRunner]: Converted '"$SJQ4_PATH\$SJQ4_LAST_SEGMENT"' to '"C:\Videos\BurnNotice-OutoftheFire-6217748-0.ts"'
2010-12-17 08:27:08,084 INFO[ListenerClient]: Disconnected from 192.168.0.30:23347
2010-12-17 08:27:28,553 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:28:28,554 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:29:28,554 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:30:28,554 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:31:28,555 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]

But here's the interesting part. The sjq log file has an exception. Any idea what is going on here? Is my script wrong?

2010-12-17 08:27:06,741 INFO  [TaskQueue]: Running queue processor now!
2010-12-17 08:27:06,756 INFO  [TaskQueue]: Assigned task 19 of type 'COMSKIP' to Client[host=htpc.meisners.net:23344,state=ONLINE,lastUpdate=Fri Dec 17 08:27:06 EST 2010]
2010-12-17 08:27:06,756 INFO[ListenerClient]: Disconnected from htpc.meisners.net:23344
2010-12-17 08:27:07,069 INFO[Listener]: Received connection from: /192.168.0.30
2010-12-17 08:27:08,069 ERROR [Handler]: IOError
java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(Unknown Source)
	at java.net.SocketInputStream.read(Unknown Source)
	at java.io.ObjectInputStream$PeekInputStream.peek(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.refill(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.read(Unknown Source)
	at java.io.DataInputStream.readUnsignedShort(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readUTF(Unknown Source)
	at java.io.ObjectInputStream.readUTF(Unknown Source)
	at com.google.code.sagetvaddons.sjq.listener.Handler.run(Handler.java:62)
	at java.lang.Thread.run(Unknown Source)
2010-12-17 08:27:08,069 INFO[Listener]: Received connection from: /192.168.0.30
2010-12-17 08:27:08,069 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.0.30
2010-12-17 08:27:08,084 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.0.30
2010-12-17 08:27:08,381 INFO[Listener]: Received connection from: /192.168.0.30

[razrsharpe]

Originally Posted by meisner

My SJQ setup really just runs comskip (donator version) and then runs a VB script to fixup a skew that always happens due to the video stream created by the HD-PVR.

Originally Posted by meisner

I need to retrieve the actual length of a recording since there is a difference between sage and the actual.

This won't answer your sjq question.... but... Sage fixed this problem in SageTV 7 by introducing a property item to disable timescaling when seeking...

videoframe/disable_timescaling_on_seek=true

[meisner]

I saw that, and put it into sage.properties, but it didn't fix the skew for me.

[meisner]

Something just dawned on me. Do I need to set disable_timescaling_on_seek=true BEFORE a recording is made?

I only tried setting it and playing back a video that was comskip'd.

[razrsharpe]

Originally Posted by meisner

Something just dawned on me. Do I need to set disable_timescaling_on_seek=true BEFORE a recording is made?

I only tried setting it and playing back a video that was comskip'd.

i dont know but i dont think so... because it only effects the playback of the media, not the creation of the edl

[graywolf]

Originally Posted by meisner

I saw that, and put it into sage.properties, but it didn't fix the skew for me.

Silly question since I haven't manually messed with the .properties files much.

Did you recycle SageTV Service (if in service mode) and/or client?

Are not a lot of the .properties only read at startup?
or need to be made while SageTV is down for it to be actually taken?

[meisner]

I run SageTV in non-service mode...only interactively.

I did find that if I made the change with STV running, I lost it. So I shut Sage down, made the change and restarted. That's how I ended up testing it.

If this is workign for others, I will give it another shot.

[razrsharpe]

Originally Posted by meisner

I did find that if I made the change with STV running, I lost it. So I shut Sage down, made the change and restarted. That's how I ended up testing it.

you can only edit the .properties files when the service and the UI are not running... ie sage must be completely shut down. Sage flushes the current values to the .properties files at shutdown so any manual edits made to them while sage is on get overwritten

If this is workign for others, I will give it another shot.

its working for me... my comskip seems to be better since v7... not perfect... but i blame that a lot more on my comskip setup then anything else.

[Slugger]

Originally Posted by meisner

Famous last words...

I need to retrieve the actual length of a recording since there is a difference between sage and the actual. The .cmd below in my groovy script runs the VB script to adjust the edl file based on the differences in duration.

Here is my groovy script I am using to launch comskip (I have the executable set to "script:C:\comskip.groovy"

Object mediaFile = MediaFileAPI.GetMediaFileForID(SJQ4_METADATA.get("SJQ4_ID").toInteger()) 
Integer duration = MediaFileAPI.GetFileDuration(SJQ4_METADATA.get("SJQ4_ID").toInteger())
String file = SJQ4_METADATA.get("SJQ4_PATH") + SJQ4_METADATA.get("SJQ4_LAST_SEGMENT")

Process cmd = "C:/comskip/RunComSkip.cmd \"${file}\" ${duration}".execute()
cmd.waitFor()
return cmd.exitValue()

This line looks suspect to me:

String file = SJQ4_METADATA.get("SJQ4_PATH") + SJQ4_METADATA.get("SJQ4_LAST_SEGMENT")

I would do a println to be sure, but I think you're missing a "\" between the two. It should be:

String file = SJQ4_METADATA.get("SJQ4_PATH") + "\\" + SJQ4_METADATA.get("SJQ4_LAST_SEGMENT")

I never see comskip run in task manager. The sjq agent log file has:

2010-12-17 08:27:06,756 INFO  [Exe]: Received task 19 of type 'COMSKIP' from 192.168.0.30:23347...
2010-12-17 08:27:06,756 INFO  [192_168_0_30-23347-19]: Starting process runner for: Task[id=COMSKIP, reqRes=100, maxInst=1, sched=ON, maxTime=6000, maxTimeRatio=1.0, rc=0-0, exe=script:C:\comskip\comskip.groovy, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=C:\comskip\comskip_test.groovy, testArgs=ts]
2010-12-17 08:27:06,756 INFO  [ProcessRunner]: Converted '"$SJQ4_PATH\$SJQ4_LAST_SEGMENT"' to '"C:\Videos\BurnNotice-OutoftheFire-6217748-0.ts"'
2010-12-17 08:27:08,084 INFO[ListenerClient]: Disconnected from 192.168.0.30:23347
2010-12-17 08:27:28,553 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:28:28,554 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:29:28,554 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:30:28,554 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]
2010-12-17 08:31:28,555 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.30-23347-19) = true; [SJQ4Task-192.168.0.30-23347-19]

I think comskip is failing because the file argument is incorrect.

But here's the interesting part. The sjq log file has an exception. Any idea what is going on here? Is my script wrong?

2010-12-17 08:27:06,741 INFO  [TaskQueue]: Running queue processor now!
2010-12-17 08:27:06,756 INFO  [TaskQueue]: Assigned task 19 of type 'COMSKIP' to Client[host=htpc.meisners.net:23344,state=ONLINE,lastUpdate=Fri Dec 17 08:27:06 EST 2010]
2010-12-17 08:27:06,756 INFO[ListenerClient]: Disconnected from htpc.meisners.net:23344
2010-12-17 08:27:07,069 INFO[Listener]: Received connection from: /192.168.0.30
2010-12-17 08:27:08,069 ERROR [Handler]: IOError
java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(Unknown Source)
	at java.net.SocketInputStream.read(Unknown Source)
	at java.io.ObjectInputStream$PeekInputStream.peek(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.refill(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.read(Unknown Source)
	at java.io.DataInputStream.readUnsignedShort(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readUTF(Unknown Source)
	at java.io.ObjectInputStream.readUTF(Unknown Source)
	at com.google.code.sagetvaddons.sjq.listener.Handler.run(Handler.java:62)
	at java.lang.Thread.run(Unknown Source)
2010-12-17 08:27:08,069 INFO[Listener]: Received connection from: /192.168.0.30
2010-12-17 08:27:08,069 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.0.30
2010-12-17 08:27:08,084 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.0.30
2010-12-17 08:27:08,381 INFO[Listener]: Received connection from: /192.168.0.30

Connection reset errors can be ignored. It's just the task client closing its connection before the server finished processing the 'QUIT' command. See above as I think there are problems with your script.