Plugin: Sage Job Queue (SJQ) v3

[nyplayer]

HandBrake512MP4 {
:CPU "LOW"
:RESOURCES 40
"c:\\mediashrink\\mediashrink.bat \"%c%\""
}

[evilpenguin]

Here's the exception your were looking for, looks like it backs up your theory...

java.lang.IllegalStateException: Form too large504836>200000
	at org.mortbay.jetty.Request.extractParameters(Request.java:1545)
	at org.mortbay.jetty.Request.getParameter(Request.java:843)
	at com.google.code.sagetvaddons.sjq.server.SJQServlet.doPost(SJQServlet.java:114)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:230)
	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
	at org.mortbay.jetty.Server.handle(Server.java:326)
	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:879)
	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)

Thanks for figuring that out

[Slugger]

Glad that was it! So to all SJQv3 users: You need to increase Jetty's max POST size in order to prevent issues with the task client's ability to flush its buffered task output back to the server. I've updated both the beta upgrade wiki doc and the SJQv3 User's Guide with instructions on how to do this. This Jetty reconfiguration is especially important for users who run ShowAnalyzer against H.264 files from SJQ because ShowAnalyzer will produce the amount of output that will cause you to hit this issue.

I've already talked to jreichen and the post limit will be increased by default in the next release of the Jetty plugin for SageTV (no scheduled release date for it at this time).

[awhenry]

Originally Posted by Slugger

I'm just not seeing how a queue loader run consumes 100% of a single core for 20 seconds

Well, you are correct it seems. After examining the logs more closely, I can see it isn't the queue loader, it is the file cleaner that runs immediately afterward that is really the CPU hog:

2009-12-06 20:05:14,069 INFO  [MediaFileQueueLoader]: Run completed [1077ms]
2009-12-06 20:05:14,070 INFO  [VacuumCleaner]: Thread finished [1ms]
2009-12-06 20:05:14,129 INFO  [LogCleaner]: Thread finished [59ms]
2009-12-06 20:05:25,092 INFO  [SystemMessageQueueLoader]: Run completed [59ms]
2009-12-06 20:05:49,219 INFO  [InternalTaskClient]: Run completed [0ms]
2009-12-06 20:05:58,741 INFO  [FileCleaner]: Thread finished [44671ms]

I'm not sure what most people have for file cleaner entries, but I am looking for 17 file extensions to delete against three video file types. Are other users encountering run times like these? Other than reducing the number of file extensions I search for (which doesn't seem feasible without potentially leaving orphaned files around) I don't see much way to control this process.

Would it be possible to uncouple it from the queue loader process perhaps? Or to perform the file cleaner function in a less zealous manner? Personally, if I could get the file cleaner to run only once a day overnight, that would be acceptable. Alternatively, I wouldn't mind it running every queue loader interval if it was a little less demanding on resources, even if it took longer to complete.

Thanks for helping narrow down the problem. I'm interested in any suggestions you might have from here.

[Slugger]

Hmm... that's just way too slow. It's not the number of file types you search for and delete in the settings because those are all combined into three regular expressions to match against, whether you check for one file extension or 500 is (mostly) irrelevant. I say 'mostly' because Java's regular expression library is not exactly the most efficient/best performing one of all time, but still 44.6 seconds is ridiculous.

The more likely causes of performance issues with the file cleaner are:

• How many tv recording directories do you have registered with SageTV? To take 44.6 seconds, however, would require some ridiculous file count in your directories.
• How many total files reside in these directories? (See above)
• How fast are your hard drives? Might they be spun down when the FileCleaner starts and therefore need time to spin up?
• Are any of the drives network drives? Are there issues accessing those network drives in a timely fashion?
• Is it possible a hard drive is showing early signs of failing?

I would venture to guess that the problem is somewhere in the above list, but to test a code problem on my part, you could change your FileCleaner settings to something much more simplistic and see if the time required comes way down.

As a point of comparison, I check for and delete three different file extensions if there is no matching mpg|ts|mkv and I have one recording directory on a local disk and there is usually between 420-475 files in that directory at any time and my FileCleaner runs for 650-735ms. Sometimes as high as 1050ms if the system is busy or whatever. I've never come close to 44.6 seconds.

I could (and probably should) decouple these threads from the media queue loader, but it's legacy code that was in place before I went multi-threaded and don't really want to rip it out unless I'm given evidence that there's a problem with the code that needs fixing, in which case I'd probably separate it away from the queue loader processes.

[awhenry]

Originally Posted by Slugger

• How many tv recording directories do you have registered with SageTV? To take 44.6 seconds, however, would require some ridiculous file count in your directories.
• How many total files reside in these directories? (See above)
• How fast are your hard drives? Might they be spun down when the FileCleaner starts and therefore need time to spin up?
• Are any of the drives network drives? Are there issues accessing those network drives in a timely fashion?
• Is it possible a hard drive is showing early signs of failing?

I would venture to guess that the problem is somewhere in the above list, but to test a code problem on my part, you could change your FileCleaner settings to something much more simplistic and see if the time required comes way down.

As a point of comparison, I check for and delete three different file extensions if there is no matching mpg|ts|mkv and I have one recording directory on a local disk and there is usually between 420-475 files in that directory at any time and my FileCleaner runs for 650-735ms. Sometimes as high as 1050ms if the system is busy or whatever. I've never come close to 44.6 seconds.

Thanks for the response.

I have five video directories defined, four local disks and one network location (I am assuming import directories are irrelevant in this context as I do not have them set to be scanned). At the moment, these directories contain 4275 files combined. I have all my drives set to never spin down to avoid any recording problems, and also to avoid wear on the drives from spinning up and down repeatedly. I do not believe there is any network problem, as viewing shows stored on the one networked drive works fine. Also, if I watch the network traffic when the file cleaner runs, I see a short burst of about 50Mbps for 2-3 seconds on the lan which I take to be the sum of the interaction with the file server. In any case, the network location holds only a tiny minority of the total file count (around 300 files total). Regarding a failing hard drive, I don't think so, though it is hard to be 100% certain with things like that. I hear no unpleasant noises from any drives, they are all fairly new, and I haven't encountered any errors in the OS or noticed any problems accessing files stored on them. I am running Windows 7, which I believe has support for SMART, and it has not informed me of any impending failures.

As to the testing, the amount of time it takes seems to depend not on how many file extensions are searched for but rather how many files match the regex. If I enter a long regex of various extensions that I know will not match any files, the file cleaner completes in under 100ms. If I enter just a single extension that will match existing files the run time increases to around 5000ms. Two extensions that will match files and it rises to 12000ms. I imagine things would be a great deal worse for me if all 17 extensions I have configured actually matched files! Fortunately in many cases they do not.

As an aside, will file cleaner operate on import directories if I set SJQ to scan imported videos? Currently I have only TV recordings selected to scan.

Thanks for your help. Looking forward to any suggestions you might have.

[Slugger]

Originally Posted by awhenry

Thanks for the response.

I have five video directories defined, four local disks and one network location (I am assuming import directories are irrelevant in this context as I do not have them set to be scanned). At the moment, these directories contain 4275 files combined. I have all my drives set to never spin down to avoid any recording problems, and also to avoid wear on the drives from spinning up and down repeatedly. I do not believe there is any network problem, as viewing shows stored on the one networked drive works fine. Also, if I watch the network traffic when the file cleaner runs, I see a short burst of about 50Mbps for 2-3 seconds on the lan which I take to be the sum of the interaction with the file server. In any case, the network location holds only a tiny minority of the total file count (around 300 files total). Regarding a failing hard drive, I don't think so, though it is hard to be 100% certain with things like that. I hear no unpleasant noises from any drives, they are all fairly new, and I haven't encountered any errors in the OS or noticed any problems accessing files stored on them. I am running Windows 7, which I believe has support for SMART, and it has not informed me of any impending failures.

As to the testing, the amount of time it takes seems to depend not on how many file extensions are searched for but rather how many files match the regex. If I enter a long regex of various extensions that I know will not match any files, the file cleaner completes in under 100ms. If I enter just a single extension that will match existing files the run time increases to around 5000ms. Two extensions that will match files and it rises to 12000ms. I imagine things would be a great deal worse for me if all 17 extensions I have configured actually matched files! Fortunately in many cases they do not.

As an aside, will file cleaner operate on import directories if I set SJQ to scan imported videos? Currently I have only TV recordings selected to scan.

Thanks for your help. Looking forward to any suggestions you might have.

No, the file cleaner only operates on SageTV registered tv recording directories. It never scans import directories (currently, but I do have plans to change this in the future).

Given the results you've reported above, I see a possible optimization to the process. If you have time today to test a private build then PM me and I'll give you the details.

[MitchSchaft]

Any ideas why my comskip jobs fail at 99%? I started using SJQ just last week from regular ol' comskip. I attached some copy/pastes from the logs.

[evilpenguin]

Looks like you're doing live comskip and that's just what the logs look like. Once it reaches the end of the file it just stays at 99% until the file stops being recorded.

I think the reason it ended up in the fail queue is that comskip returns a 1 for success. Just add this to your client config and you should be good...

COMSKIP {
:RETURNCODE 1
"C:/Program Files/SageTV/SageTV/ComskipMonitor/comskip80_025/comskip.exe \"%c%\"

}

[MitchSchaft]

It's not live, it's scanning all the shows in the recorded tv directory one after another. If it is live, how do I change it? I guess I could post my comskip.ini?

[evilpenguin]

What's your server rule set look like?

[MitchSchaft]

oops, forgot to post that. I used the rule in the v3 guide:

if [IsObjMediaFile == true && $.IsTVFile{} == true && $.IsNotManualOrFavorite{} == false] {
   :PRIORITY 10 # Optional, default priority is zero
   COMSKIP
}

[Slugger]

Snapshot 690 is now available. This build includes a much improved algorithm for the FileCleaner thread. Tests show a literal 99.86% performance gain using the new FileCleaner. All users are encouraged to upgrade.

NOTE: Please read the updated user guide docs concerning the file cleaner. The second input used to be a regular expression, but is now a simple delimited list of file extensions to check for. The delimiter is the '|' character and if you just have a list of extensions like 'mpg|ts|mkv' then there should be no change required, but if you actually used regular expression matching then you MUST CHANGE THIS VALUE TO A SIMPLE DELIMITED LIST BEFORE UPGRADING. Failure to do so will result in files being deleted unexpectedly. You've been warned!

Thanks to awhenry for testing the various builds over the last couple days since he had an environment that really exposed the poor algorithm originally implemented and was able to verify the performance gains for me. Under the old algorithm the FileCleaner thread was taking about 44 seconds to complete each time on his system. With the new algorithm, the run time is now 63ms (a gain of 99.86%)!

[awhenry]

Originally Posted by Slugger

99.86% performance gain

Fantastic, really.


Well done.

[awhenry]

Originally Posted by Slugger

Completed and failed tasks should show all the output produced. At the very least, it should show those two header lines like above. If those lines aren't being produced for external tasks (tasks run on a task client) then something's wrong.

Now that my file cleaner issues are resolved, I guess I can revisit my log problems. I'm sure this one will be easier to solve.

As I mentioned before, none of my tasks (active or completed) show any log info when I select "view log". I checked a little more closely, and I can see that the tasks initially start off logging as you indicated they should. However when the log cleaner process runs, it wipes out all the logged info for every task. After this occurs nothing further ever appears in the task log for a task until the task is completed, at which point the full and complete command line output of the task shows up until the next log cleaner run, at which time it is deleted. I have my log purge settings set to the defaults I think (weekly/weekly/monthly). I am using the latest client version.

I'm not sure how to troubleshoot this. Any ideas why this would be happening? Is there a config file entry that might control this?

On the topic of logs, three other quick questions. First, when viewing the server logs, clicking "Clear Log" does not clear the log (the banner message does appear saying the logs were cleared, but all the log entries remain). Is this supposed to work in the current version? Second, is there a way to disable the log entry warning that an IPv6 interface was detected? This message comprises 95% of my log entries, and it is a bit difficult sometimes to find the signal in all that noise. Finally, is there something I can edit to allow the running task to submit logs more frequently, so that I can see the output while it is running? This isn't a huge issue, but it would be nice to be able to see the ongoing progress, especially if you think something has gone sideways with the process.

Thanks for any assistance you can provide, and for the work you have already done.

[Slugger]

Originally Posted by awhenry

Now that my file cleaner issues are resolved, I guess I can revisit my log problems. I'm sure this one will be easier to solve.

As I mentioned before, none of my tasks (active or completed) show any log info when I select "view log". I checked a little more closely, and I can see that the tasks initially start off logging as you indicated they should. However when the log cleaner process runs, it wipes out all the logged info for every task. After this occurs nothing further ever appears in the task log for a task until the task is completed, at which point the full and complete command line output of the task shows up until the next log cleaner run, at which time it is deleted. I have my log purge settings set to the defaults I think (weekly/weekly/monthly). I am using the latest client version.

I'm not sure how to troubleshoot this. Any ideas why this would be happening? Is there a config file entry that might control this?

Assuming you don't have the SQLite CLP installed on your system, I'm going to have to devise a new debug panel in the app to dump the contents of your database file for me to review. This is one of those cases where the cause/bug is probably really simply, but unless you have the tools to get me the output I need to see or I go and put in the tedious effort of writing more debug tools in the SJQ GUI then it's going to be harder than it should be track down.

Let's start with something simple. Set all the log types to flush monthly. Run the queue loader manually (which triggers the log cleaner). Do your logs still all get wiped out?

On the topic of logs, three other quick questions. First, when viewing the server logs, clicking "Clear Log" does not clear the log (the banner message does appear saying the logs were cleared, but all the log entries remain). Is this supposed to work in the current version?

Is it suppose to? Sure. Does it? No. Do I know about it? Yes. Will it be fixed before beta ends for SJQv3. Yes.

Second, is there a way to disable the log entry warning that an IPv6 interface was detected? This message comprises 95% of my log entries, and it is a bit difficult sometimes to find the signal in all that noise.

Don't have IPv6 myself so didn't realize that this warning was issued on every connection to the servlet. It's fixed in my local tree and will be a part of the next snapshot.

Finally, is there something I can edit to allow the running task to submit logs more frequently, so that I can see the output while it is running? This isn't a huge issue, but it would be nice to be able to see the ongoing progress, especially if you think something has gone sideways with the process.

Currently, no. If you open up an issue ticket I might consider adding this as a config option to the task client.

[Slugger]

Originally Posted by awhenry

Now that my file cleaner issues are resolved, I guess I can revisit my log problems. I'm sure this one will be easier to solve.

As I mentioned before, none of my tasks (active or completed) show any log info when I select "view log". I checked a little more closely, and I can see that the tasks initially start off logging as you indicated they should. However when the log cleaner process runs, it wipes out all the logged info for every task. After this occurs nothing further ever appears in the task log for a task until the task is completed, at which point the full and complete command line output of the task shows up until the next log cleaner run, at which time it is deleted. I have my log purge settings set to the defaults I think (weekly/weekly/monthly). I am using the latest client version.

Originally Posted by Slugger

Assuming you don't have the SQLite CLP installed on your system, I'm going to have to devise a new debug panel in the app to dump the contents of your database file for me to review. This is one of those cases where the cause/bug is probably really simply, but unless you have the tools to get me the output I need to see or I go and put in the tedious effort of writing more debug tools in the SJQ GUI then it's going to be harder than it should be track down.

Let's start with something simple. Set all the log types to flush monthly. Run the queue loader manually (which triggers the log cleaner). Do your logs still all get wiped out?

Do NOT set all your logs to flush monthly and test as I've suggested. I've found the cause of the bug and will build a snapshot with the fix some time today. It's another integer overflow bug. I get caught by this way too many times in Java:

long interval = 30 * 24 * 60 * 60 * 1000; // 30 days converted to ms

I expect Java to convert the right hand side to longs and return 2.592 billion, but it doesn't; Java treats them all as ints unless explicitly cast. And since 30 days converted to ms is larger than the max value of an int, you get an overflow and that expression actually returns a negative number to the caller, which is why setting your logs to flush monthly actually ends up flushing them every time. To remedy this situation until the snapshot is available, set your logs to flush weekly (or daily), since the integer will not overflow, it'll work as expected.

[Slugger]

More fixes; recommended that users upgrade.

• Fix issue 102: Replenish lost DataStore connections to the pool
• Fix issue 101: Disallow multiple instances of work threads from running simultaneously
• Fix integer overflow bug with LogCleaner that cleared the logs every time the QueueLoader ran if the logs were set to purge monthly
• Fix bug where IPv6 detection log message was being logged on every connection to the servlet instead of just once per the life of the application

[skiingwiz]

Originally Posted by Slugger

I get caught by this way too many times in Java:

long interval = 30 * 24 * 60 * 60 * 1000; // 30 days converted to ms

I'm not sure if you know this, but it may help. If you tell java that any of those values on the RHS are longs, it will promote the whole thing to a long. So you can just add an L to one of them, like this (note the L after 1000):

long interval = 30 * 24 * 60 * 60 * 1000L; // 30 days converted to ms

[Slugger]

Yeah, I know about it, but I always forget to do it and then it's a bug that someone has to discover (usually in an undesirable way). If I'm assigning the value to a long, Java should treat the expression as a long! Or at the very least a compiler warning would be nice. A compiler warning would be enough to make me look at what I'm doing and make the appropriate change (either assign to an int instead or ensure the expression returns a long).