Plugin: Sage Job Queue (SJQ)

[Opus4]

Originally Posted by nyplayer

That is the way Sage works when it transcodes has nothing to do with SJQ. If you transcode a recording within SageTV you will not see the Channel #.

I believe that is the case when a transcode job makes a copy of the file instead of replacing the original, so they can be distinguished in the database.

- Andy

[madas]

OK, one more problem. I seem to have a memory leak. I'm running the latest beta of SageTV on Vista and SJQ 1.4.

After initially loading Sage it uses 200-250MB...after an hour or two its up to 1GB+ and eventually it stalls the system.

I removed the SJQ file from the start_at_load line and sage is now stable at around 250MB.

My SJQ rules file is simple
-----------------------------------
###__Rule 1
= IsTV: true
= IsScheduledRecording: true
$ Filename: .mpg
= IsActivelyRecording: false
COMMFLAG "C:\Program Files\SageTv\Comskip\runcom.bat" "%f%"

###__Rule 2
= IsTV: true
= IsScheduledRecording: true
= IsActivelyRecording: false
= FileExists: %d%\%b%.txt
TRANS "__TRANSCODE" "MPEG4-High Quality AVI" true
-----------------------------------

and I have a very small number of recordings (~20) and only a few are recorded each day.

I'm also running the latest java, 1.6.0_06

Any ideas where I should start debugging this?

Thanks

Graham

[Slugger]

Originally Posted by madas

OK, one more problem. I seem to have a memory leak. I'm running the latest beta of SageTV on Vista and SJQ 1.4.

After initially loading Sage it uses 200-250MB...after an hour or two its up to 1GB+ and eventually it stalls the system.

I removed the SJQ file from the start_at_load line and sage is now stable at around 250MB.

My SJQ rules file is simple
-----------------------------------
###__Rule 1
= IsTV: true
= IsScheduledRecording: true
$ Filename: .mpg
= IsActivelyRecording: false
COMMFLAG "C:\Program Files\SageTv\Comskip\runcom.bat" "%f%"

###__Rule 2
= IsTV: true
= IsScheduledRecording: true
= IsActivelyRecording: false
= FileExists: %d%\%b%.txt
TRANS "__TRANSCODE" "MPEG4-High Quality AVI" true
-----------------------------------

and I have a very small number of recordings (~20) and only a few are recorded each day.

I'm also running the latest java, 1.6.0_06

Any ideas where I should start debugging this?

Thanks

Graham

I'm unable to reproduce these results. My Sage starts up using 63MB RAM and after 10 consecutive runs of SJQ (all triggered within ~15 seconds) the process runs up to 66MB where it stays steady. I then did 10 more runs and the usage increased to 70MB where it then held steady until I went and turned on one of my HD100's then the usage jumped to 128MB where it holds steady, even after turning off the HD100. Then I turned the same HD100 back on and the process jumped to 151MB.

It's hard to track the cause - I mean I do see where each run of SJQ is increasing the mem usage of the process, but is that because the Java garbage collector hasn't ran yet (or recently)? Each SJQ run immediately adds about 300kb to the mem usage of the process. This would be variable based on the size of one's media library. And mine's bigger than yours so I wouldn't expect anything more on your instance. But I now see as I write this that the mem usage just dropped about 260kb before increasing another 30kb. I'm also running the web server and my SRE plugin so those numbers are going to move around while those plugins are doing their thing - and of course using Sage itself is going to play with these numbers so I can't really confirm (or deny a mem leak) in SJQ. I'll take a quick look at the code tonight or tomorrow night to see if the obvious spots where I'd hold onto objects unnecessarily are not an issue, but I figure I'd have heard from others if such a leak existed in the code.

My guess is that something isn't interacting with Vista nicely. It may be your JRE (unlikely) or SageTV (less unlikely, but still unlikely) or SJQ (more likely than the former, but not as likely as the following) or the JDBC driver used by SJQ (the most likely culprit). I run on XP, test on XP and have never tried my code on Vista so a Vista incompatibility certainly isn't impossible nor would it be all that surprising.

I'd start by enabling SJQ again and restarting Sage. See if you can reproduce the issue constantly. Also, did SJQ happen to trigger a process that may have caused the issue? Perhaps a transcoding job went crazy? Maybe a comskip process? Perhaps a comskip process dumped a whole bunch of output, which may choke SJQ/SQLite since SJQ captures all output and stores it in the database.

As you can see there are many variables. Start by trying to isolate the cause - make sure it's just SJQ and not a process that it may have triggered (make sure your tests will always return false so that it never triggers a process and see how long it goes). If it continues to happen and SJQ never triggers a process then at least I can then start to look at my source code and see if there's anything obvious that I can find.

With that said, I've personally had SJQ run for weeks - even months at a time - without issue (though I've never actually tracked the mem usage of SageTV). I run with 2GB of RAM in my system - plenty, but not so much that such a massive mem leak in the SJQ code wouldn't be seen on my system.

[madas]

I was able to consistently reproduce it. For now, let me try removing all of my rules and see if this still happens when SJQ actually has nothing to do

[madas]

OK, I tried running it with a blank rules.sjq file and leaving SageTV totally alone in windowed mode.

After a couple of hours it was up to 512MB of memory used and increasing at a few MB every mins

Remove the SJQ from the start line of the properties file, couple of hours its steady at 250MB.

Any ideas how to further debug? would logs help?

[Slugger]

Originally Posted by madas

OK, I tried running it with a blank rules.sjq file and leaving SageTV totally alone in windowed mode.

After a couple of hours it was up to 512MB of memory used and increasing at a few MB every mins

Remove the SJQ from the start line of the properties file, couple of hours its steady at 250MB.

Any ideas how to further debug? would logs help?

How is SJQ setup to run? Are you automatically running it every 2 minutes or are you just running it after the end of each recording (or after the start of each recording)? Assuming you're running it after each recording, there's no reason for it to constantly chew up memory since the bulk of the time the thread would just be sleeping. The current logs won't log anything useful for this scenario so once I get some more details from you I'll have to add some debug statements to the code and get you to run with a modified jar file.

[Slugger]

Originally Posted by madas

OK, I tried running it with a blank rules.sjq file and leaving SageTV totally alone in windowed mode.

After a couple of hours it was up to 512MB of memory used and increasing at a few MB every mins

Remove the SJQ from the start line of the properties file, couple of hours its steady at 250MB.

Any ideas how to further debug? would logs help?

Another thing to try is to download older versions of SJQ from the sourceforge download page and see if you can find a version there that does not exhibit this behaviour. If you can, then at least I know where to start looking. I've set my own SJQ to run in a constant interval of 2 mins and I'm going to monitor my system over the next couple hours this morning.

If you do decide to start installing older versions please completely remove any existing version before installing another.

[madas]

Its set to

Max time between scans: 5 mins
When: After end of each recording
Delay: 1 min

Last run:
Thu Jul 03 10:01:50 EDT 2008
Next run:
Thu Jul 03 10:07:51 EDT 2008
Current status:
Sleeping

Very strange!

[Slugger]

Originally Posted by madas

Its set to

Max time between scans: 5 mins
When: After end of each recording
Delay: 1 min

Last run:
Thu Jul 03 10:01:50 EDT 2008
Next run:
Thu Jul 03 10:07:51 EDT 2008
Current status:
Sleeping

Very strange!

Those settings mean run 1 minute after the end of the next recording or every 5 mins, whichever comes first. Typically I'd set max time between scans to at least 360 minutes (6 hours), which then means run 1 min after the end of the next recording or every 6 hours, which ever comes first.

That explains the constant mem increase every five minutes, though doesn't explain the cause of it. If you could, please try older versions of SJQ (with the 5 min max setting) and see if any older version eliminates the behaviour.

[nyplayer]

Slugger,

One thing that I have noticed is that if I display the log the memory in Sage keeps increasing and seems to stay there. I expect it to increase in IEExplorer which it does but then memory usage goes down in IE but stays up in Sage.

This appears to be the Problem. I ran ok with no memory increase without displaying the log.

when I displayed the log this is what happens.

80,000 - Starting memory
281,000 - 1rst Display of log
363,000 - 2nd Display of log
371,816 - 3rd Display

memory for Sage is at 371,812 using no CPU.

No cleanup appears to have been done.

[madas]

maybe i'm missing something, but i've tried 1.0 and 1.1 and i just keep getting

Thu 7/3 12:31:41.103 ERROR Loading startup runnable extension of:java.lang.ClassNotFoundException: net.sourceforge.sagetv.sjq.SageJobQueue

are the install instructions different for the older vers?

I didn't modify the .properties file

[nyplayer]

Originally Posted by madas

maybe i'm missing something, but i've tried 1.0 and 1.1 and i just keep getting

Thu 7/3 12:31:41.103 ERROR Loading startup runnable extension of:java.lang.ClassNotFoundException: net.sourceforge.sagetv.sjq.SageJobQueue

are the install instructions different for the older vers?

I didn't modify the .properties file

I am using sjq150b1 with 6.44 as long as I do not display the log everything runs fine.

I believe the properties setting did change I am not sure in what version.

[madas]

NYPlayer...are you running Vista?

I get this problem even if I just leave Sage at the main screen and don't display ANYTHING

[nyplayer]

XP Pro. I run SageTV Minimized on my server. I installed SJQ on the client on my server so if something goes wrong all I have to do is restart SageTV not the service.

BTW even if you do not display the Log... It might still have something to do with logging. I noticed you check every 5 minutes. Therefore you are logging more often. I know slugger had changed the logging I am not sure when best to wait till he comes on. I am sure he can fix it.

[Slugger]

Originally Posted by madas

maybe i'm missing something, but i've tried 1.0 and 1.1 and i just keep getting

Thu 7/3 12:31:41.103 ERROR Loading startup runnable extension of:java.lang.ClassNotFoundException: net.sourceforge.sagetv.sjq.SageJobQueue

are the install instructions different for the older vers?

I didn't modify the .properties file

Blah... sorry. Yeah, the class name is different in older versions. slugger.sagetv.sjq.SageJobQueue is the class name. Also, older versions have no servlet so no viewing via the web. This is why it's quite important to completely toast off anything from 1.4.0 or 1.5.0B1 before installing one of these older versions.

I'm inclined to believe the problem is related to the db based logging scheme I implemented in v1.1.0 (though I'm not 100% convinced at this point). If you can setup and get 1.0.1 to run and it doesn't exhibit the behaviour then I'll know where to start digging. Though not convinced it's the logging, I'd be very pleased to find out it is since that should be relatively easy for me to track down. Before I speculate anymore, I'll await your results.

[madas]

ok i'm running 1.0.1 with a blank ruleset, the 5 minute setting still (i didn't even figure out where to modify this in ver 1.0.1???)

No memory leak...its been running for 5 hours and i'm at 230MB

[Slugger]

Originally Posted by madas

ok i'm running 1.0.1 with a blank ruleset, the 5 minute setting still (i didn't even figure out where to modify this in ver 1.0.1???)

No memory leak...its been running for 5 hours and i'm at 230MB

Yeah, I've been playing around with things myself this evening, too. Definitely convinced myself it was the db code. Your results further confirm it.

I've gone over my db code and I'm fairly certain I'm close()ing all the JDBC objects after I use them, etc. I did upgrade the JDBC driver to the latest available and it seems to have helped. I don't see the mem necessarily dropping, but multiple requests for data from the db don't seem to be using new chunks of mem each time (i.e. the mem doesn't increase/doesn't increase as fast). Can you please give 1.5.0b2 a try and let me know the results? Do the samething - 5 min interval with tests that won't trigger processes.

Windows Installer (WinXP and below)
ZIP file (Vista, Linux, Mac)

NOTE: If installing via the zip, please delete the following files after stopping SageTV and before unzipping this new build:

SageTV\sqlite*.dll
SageTV\libsqlite*.so
SageTV\JARs\sqlite*.jar

The Windows installer does this cleanup automatically.

Please report back the results.

[Slugger]

Originally Posted by Slugger

Yeah, I've been playing around with things myself this evening, too. Definitely convinced myself it was the db code. Your results further confirm it.

I've gone over my db code and I'm fairly certain I'm close()ing all the JDBC objects after I use them, etc. I did upgrade the JDBC driver to the latest available and it seems to have helped. I don't see the mem necessarily dropping, but multiple requests for data from the db don't seem to be using new chunks of mem each time (i.e. the mem doesn't increase/doesn't increase as fast). Can you please give 1.5.0b2 a try and let me know the results? Do the samething - 5 min interval with tests that won't trigger processes.

Windows Installer (WinXP and below)
ZIP file (Vista, Linux, Mac)

NOTE: If installing via the zip, please delete the following files after stopping SageTV and before unzipping this new build:

SageTV\sqlite*.dll
SageTV\libsqlite*.so
SageTV\JARs\sqlite*.jar

The Windows installer does this cleanup automatically.

Please report back the results.

Ok... I'm seeing a drastic improvement with 1.5.0b2... after chewing up 25MB or so it seems that it stops chewing up memory. I trigger runs and it uses 300kb or so and then releases it. Loading my job history tab (2500 rows) grabs a chunk of 10MB or so the first time but then never grabs more on subsequent reads of the data. Hopefully you're seeing the same results.

[madas]

So far so good on 1.5.0b2. A day without a major increase in memory. I'll try and repopulate the rules file tonight.

[Slugger]

Originally Posted by madas

So far so good on 1.5.0b2. A day without a major increase in memory. I'll try and repopulate the rules file tonight.

That's good to hear. Same results I'm seeing with 1.5.0b2. I'll wait until you post a result with your ruleset implemented, but I think the upgraded JDBC driver was the key to this issue. After I get a final word from you, I'll package up 1.5.0b2 and release it as the official 1.5.0 either tomorrow or Monday evening.