Plugin: Sage Job Queue (SJQ) v3

[evilpenguin]

Originally Posted by Slugger

Hmm... sounds like the task client threads created for chewing up the output died off. Let me try something... can you test a new task client build?

Yep, just post it on the thread and i'll give it a shot.

[Slugger]

Hmm... my idea was already implemented in the code. Are you running the task client as a service? If so, can you go to the install directory then into the logs dir then look at wrapper.log, is there an exception dump in there?

[evilpenguin]

Nope, i'm running in a client window right now. I am getting these errors, but I figured they were unrelated. Then again, since I don't understand any of this I prolly shouldn't make assumptions like that

Exception in thread "Thread-288" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
        at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
        ... 3 more
Exception in thread "Thread-295" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
        at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
        ... 3 more
Exception in thread "Thread-343" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
        at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
        at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8080/sjq/SJQ?proto=4&cmd=writeLog
        at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
        ... 3 more

Edit: wonder if its related to this...

Active tasks: the task client actually buffers the output and will only flush it to the server every 5000 lines or so. If your task doesn't produce more than 5000 lines of output then it will all just be flushed in batch at the end of the task. External tasks should, however, always have two lines visible b/c the server writes a couple lines showing the time the task started, it's priority, and the command line that was executed. Something like this:

And that ~2 hours of comskip produces ~5000 lines.

[Slugger]

Ok, now we're getting somewhere.

The IOMonster threads are indeed dying off. They try to flush the output back to the server and the server is throwing back a 500 HTTP response, which the client doesn't like and the thread dies off. When the IO consumer dies off, the native process that was running will hang. So now I know why you're seeing the hang, now I need to know why the server is not completing the logging of the output.

In an ideal world, you're always running Sage with its debug logging turned on and you've enabled Jetty's logging. So now you need to match those client exceptions with the exceptions that are logged in the Jetty debug logs. If you don't live in my Utopian world ( ), then you'll need to turn on Sage debug logging and Jetty logging and reproduce this and get the server side exception that's causing the client side ones you've provided above.

[Slugger]

I just tried to reproduce the problem on my install, but was unable to. I just wrote a program that dumped 10240 lines of output to stdout and the task client gleefully flushed all 10240 lines (in two separate flushes) to the server and the server wrote them to the db with no issues. Since I can't reproduce the problem, I'm going to need someone who can to get the server side exception corresponding to the task client exceptions EP provided above.

[evilpenguin]

Ok, now that I know what's going on, that shouldn't be a problem.

[tomfisk]

Originally Posted by Slugger

Please let me know if you can reproduce this on 675. Also, if you see this error again, please take a snapshot of the server threads and provide that output in addition (take that snapshot from the tools menu). Also, please increase the logging to DEBUG level in sjq.log4j.properties. It's going to produce tonnes of output, but it will be more helpful in hopefully identifying the problem.

OK...happened again. I didn't get a chance to increase the level of debugging. That'll be next:

2009-12-03 14:56:30,078 ERROR [DataStore]: SQL error
java.sql.SQLException: database locked
	at org.sqlite.DB.execute(DB.java:270)
	at org.sqlite.DB.executeUpdate(DB.java:281)
	at org.sqlite.PrepStmt.executeUpdate(PrepStmt.java:77)
	at com.google.code.sagetvaddons.sjq.server.DataStore.setSetting(DataStore.java:930)
	at com.google.code.sagetvaddons.sjq.server.MediaFileQueueLoader.run(MediaFileQueueLoader.java:48)
	at java.lang.Thread.run(Unknown Source)
2009-12-03 15:01:24,781 INFO  [SJQServlet]: Checking client '127.0.0.1': 100 resources free.
2009-12-03 15:06:24,781 INFO  [SJQServlet]: Checking client '127.0.0.1': 100 resources free.

And here's the snapshot:

Thu Dec 03 17:19:56 CST 2009: SJQ Application Dump 
MediaQueueLoader thread is dead! 
SysMsgQueueLoader thread is alive...
 java.lang.Thread.sleep(Native Method) com.google.code.sagetvaddons.sjq.server.SystemMessageQueueLoader.run(SystemMessageQueueLoader.java:77) java.lang.Thread.run(Unknown Source) 
ClientMonitor thread is alive... 
java.lang.Thread.sleep(Native Method) 
com.google.code.sagetvaddons.sjq.server.ClientMonitor.run(ClientMonitor.java:38) 
java.lang.Thread.run(Unknown Source) 
InteralTaskClient thread is alive...
 java.lang.Thread.sleep(Native Method) com.google.code.sagetvaddons.sjq.server.InternalTaskClient.run(InternalTaskClient.java:63) 
java.lang.Thread.run(Unknown Source) 
Most recent LogCleaner thread is dead (this is normal behaviour)! 
Most recent FileCleaner thread is dead (this is normal behaviour)! 
Most recent VacuumCleaner thread is dead (this is normal behaviour)!

[Slugger]

You need to restart SJQ after changing the log level. You'll know if it worked because the log will start to produce way, way more output.

[awhenry]

Originally Posted by Slugger

The one big thing I'd suggest is to rearrange your rules so that it can short circuit out as quick as possible and therefore make as few Sage API calls as possible.

Quick question on this point. Does that mean that the "$.<function>" calls are of primary concern, and the others are more or less "free"? For instance, is a "FileExists" insignificant compared to a "$.IsWatchedCompletely{}"? Or should I consider them all equally when shuffling them around to make the most likely to fail appear first?

Incidentally, I didn't mean to mislead you. I also have a Q6600, and the behavior I am seeing is 25% utilization overall (100% of one CPU core), though it lasts far more than a second for me, more like 20. Too bad SageTV doesn't appear to make use of SMP. That was one advantage of Comskip Monitor that I didn't fully appreciate at the time: I didn't have to care how much CPU its poll took since it and SageTV were on different cores.

Thanks for the info!

[Slugger]

Originally Posted by awhenry

Quick question on this point. Does that mean that the "$.<function>" calls are of primary concern, and the others are more or less "free"? For instance, is a "FileExists" insignificant compared to a "$.IsWatchedCompletely{}"? Or should I consider them all equally when shuffling them around to make the most likely to fail appear first?

Incidentally, I didn't mean to mislead you. I also have a Q6600, and the behavior I am seeing is 25% utilization overall (100% of one CPU core), though it lasts far more than a second for me, more like 20. Too bad SageTV doesn't appear to make use of SMP. That was one advantage of Comskip Monitor that I didn't fully appreciate at the time: I didn't have to care how much CPU its poll took since it and SageTV were on different cores.

Thanks for the info!

I'm not really sure... without any knowledge of the inner workings of SageTV I can't really say if the API calls are more expensive than, say, a FileExists call. I don't know what's spiking the CPU. Is it looping through the list of MediaFile objects or is it calling all those API calls on an object? I don't know and without the source code for SageTV, I can only speculate. I would imagine that a non API call would be cheaper, but is it? I don't know. What I can say with certainty, is that rearranging your rulesets to reduce the avg number of API calls on the bulk of your objects has got to be less taxing than having a ruleset where you're more likely to make more API calls. How much of a gain will it be? Again, I don't know.

But if it's spiking a core for 20 seconds then I'm now guessing it's more of a function of the number of objects that it's processing on each run. How big is the set of objects being scanned? On my Q6600 I have SJQ only process tv recordings, I have about 685 and it takes less than two seconds for each run of the queue loader and I do some rather funky things in my rulesets. For a core to be 100% for 20 seconds I might expect you to be processing close to 10000 objects, and if you are processing that many then there's not much you can do about it other than reduce the size of the list being scanned. If you're only scanning tv files and you have 10000 then I doubt there's much that can be done other than to try and optimize your rules and hope for the best.

[Slugger]

Snapshot 676 turns back on the logging of how much time each thread takes to run at the INFO level instead of DEBUG. Those of you having problems please move to 676 and get me some timings.

Thanks.

[Slugger]

Q6600, 2GB RAM, WinXP SP3, Java 1.6.0_17, SageTV 6.6.1, ~685 recordings (+/- whatever it recorded tonight) and snapshot 676 of SJQ constantly reports between 2.4 and 2.7 seconds for the queue loader to run with this ruleset:

/*
# Create a single task to dump 10K plus lines of output to test the client flushing data back to server error reported on the forums
if [IsObjMediaFile == true && $.GetShowTitle{} == "House"] {
  NOISE
}
*/

# Move syndicated shows, movies, plus anything else marked for archival to the NAS
if [IsObjMediaFile == true && $.IsTVFile{} == true && (TimeUntilNextRecording >= "4H" || FreeSpacePercentage < 7) && $.IsFileCurrentlyRecording{} == false && (((($.GetShowCategory{} == "Movie" && $.GetShowSubCategory{} != "Documentary") || $.GetShowTitle{} =% "Friends|Seinfeld|Night Court|Three's Company|Family Guy|Married \\.\\.\\. With Children") && $.IsLibraryFile{} == false) || ($.IsLibraryFile{} == true && Filename !^ "\\\\nas"))] {
   :MOVERECOPTS "\\\\nas\\tv"
   :FAILALERT "true"
   _MOVEREC
}

# Test rule for mediashrink experiment; basically don't queue up anything except that one episode of Three's Company for testing purposes
if [IsObjMediaFile == true && $.IsTVFile{} == true && $.IsAiringHDTV{} == false && $.GetShowCategory{} != "Movie" && $.GetShowTitle{} == "Three's Company" && Filename =$ ".ts" && $.IsFileCurrentlyRecording{} == false && $.GetShowEpisode{} == "Doctor in the House"] {
   :PRIORITY -10
   #:SCANMEDIA "true"
   MEDIASHRINK
}

/*
# Old SDCOMM task; not used anymore; keep for reference
if [IsObjMediaFile == true && $.IsTVFile{} == true && $.IsFileCurrentlyRecording{} == false && $.IsWatchedCompletely{} == false && $.GetChannelName{} !% "HBOC.+|M|MXS|MFUN|MFEST|MHD" && $.GetChannelNumber{} !% "8\\d\\d|9\\d\\d" && $.GetShowTitle{} !% "MLB Baseball|NFL.*Football|NHL Hockey|College Basketball|College Football" && $.GetShowExternalID{} != NoShow && ($.IsManualRecord{} == true || $.IsFavorite{} == true) && FileExists != "%d%/%p%.edl" && Filename =$ ".mpg"] {
   :PRIORITY 10
   SDCOMM
}
*/

# Comskip HDPVR recordings; use different task name so we can assign more req'd resources for HDPVR processing
if [IsObjMediaFile == true && $.IsTVFile{} == true && Filename =$ ".ts" && $.IsFileCurrentlyRecording{} == false && $.IsWatchedCompletely{} == false && $.GetChannelName{} !% "HBOC.+|M|MXS|MFUN|MFEST|MHD|HDNTCAN" && $.GetChannelNumber{} !% "8\\d\\d|9\\d\\d" && $.GetShowTitle{} !% "MLB Baseball|NFL.*Football|NHL Hockey|College Basketball|College Football" && $.GetShowExternalID{} != NoShow && ($.IsManualRecord{} == true || $.IsFavorite{} == true) && FileExists != "%d%/%p%.edl"] {
   :PRIORITY 5
   HDCOMSKIP
}

# Comskip recordings from PVR-250s; we can do lots of these ones simultaneously
if [IsObjMediaFile == true && $.IsTVFile{} == true && Filename =$ ".mpg" && $.IsFileCurrentlyRecording{} == false && $.IsWatchedCompletely{} == false && $.GetChannelName{} !% "HBOC.+|M|MXS|MFUN|MFEST|MHD|HDNTCAN" && $.GetChannelNumber{} !% "8\\d\\d|9\\d\\d" && $.GetShowTitle{} !% "MLB Baseball|NFL.*Football|NHL Hockey|College Basketball|College Football" && $.GetShowExternalID{} != NoShow && ($.IsManualRecord{} == true || $.IsFavorite{} == true) && FileExists != "%d%/%p%.edl"] {
   :PRIORITY 10
   SDCOMSKIP
}

# Download fanart as needed
if [IsObjMediaFile == true && $.IsTVFile{} == true && ($.GetShowCategory{} !% "Special|Standup|Documentary" || $.GetShowSubCategory{} !% "Special|Standup|Documentary") && FileExists != "D:/FANART/TV/$.GetShowTitle{}" && ($.IsManualRecord{} == true || $.IsFavorite{} == true) && $.IsLibraryFile{} == false] {
   :PRIORITY -5
   TVMETADATA
}

2009-12-04 00:51:48,302 INFO  [MediaFileQueueLoader]: MediaFileQueueLoader completed [2500ms]

If your media queue loader is reporting a run time up and around 20 seconds and your object pool being processed is not in the order of 10000 objects then we either need to look at exactly what you're doing in your ruleset or start looking at other variables (OS, Java version, Sage version, RAM, etc.).

[Slugger]

Turns out through some experimentation that the FileExists test is way more expensive than any Sage API test, which given the disk I/O isn't too surprising. Adding this test to my ruleset:

if [IsObjMediaFile == true && FileExists == "%d%/%p%.mkv" && Filename !$ ".mkv"] {
   :RELINKOPTS "$.GetAiringID{}" "%d%/%p%.mkv"
   _RELINK
}

Increased the avg run time of the media queue loader from 2.5 seconds to 8.6 seconds on a media list of ~695 recordings. However, during the 8 seconds my CPU only spikes to about 15% (or ~60% of a single core), but was usually around 9-11% (~35-40% of a single core). I'm just not seeing how a queue loader run consumes 100% of a single core for 20 seconds (again, unless you're processing thousands more objects).

NOTE: The _RELINK internal task referenced above is not committed yet, but will be soon. The _RELINK task will allow you to relink the airing info from one recording to another (perfect for relinking the airing info after transcoding a recording with EP's mediaShrink tool).

[Slugger]

Snapshot 679 includes a fix for an integer overflow bug that caused the db vacuum process to run each and every time the media queue loader was triggered instead of once every 30 days as intended. Though it shouldn't have caused 'database locked' errors, it certainly could have (the SQLite vacuum command is by far one of the most expensive db operations on an SQLite database). With this discovery I reverted the fix I applied in 677 so that the app is once again more concurrent/zippy. If people start to see database locked errors again with 679 please let me know and I'll reapply that fix on top of 679. All snapshots between 665 and 677, inclusive, have been pulled from the downloads site and should be avoided by users due to the integer overflow bug. Users of any of these snapshots should move forward to 679 or later.

679 also includes the _RELINK internal task. User guide updated with details on its usage (read those docs carefully before using this task; should be treated with same level of caution as _MOVEREC task). (Again, with that obligatory warning, I'm happily using the _RELINK task with excellent results.)

[nyplayer]

Slugger,

About the relink how exactly do you schedule it do you include it with your mediashrink rule? Do you base it on mediashrink returning a 0 code. ?

[Slugger]

Nope, I use a separate rule. I actually use the rule posted a few above this. I look for an mkv matching a non-mkv and if they both exist I relink the airing info. A recent bug in mediaShrink has prevented me from fully testing my sol'n so I'll post a more complete example once I'm done testing, but I committed the _RELINK task because it was already implemented in my local tree along with the integer overflow fix (and I've tested the _RELINK task enough on its own to be confident with it).

[MitchSchaft]

After installing this latest version, none of my clients show up. Did I break it?

[Slugger]

Originally Posted by MitchSchaft

After installing this latest version, none of my clients show up. Did I break it?

What version did you upgrade from? Server 679 requires task client 655. If you are using client 655 then there's a chance the client tried to connect to the server while you were upgrading and if so it would have died off - just restart the task client and you should be good to go.

[MitchSchaft]

Opening D:\Recorded TV\Frontline-ObamasWar-153628-0.mpg
No INI file found in current directory. Searching PATH...
No INI file found in PATH...
No INI file found anywhere!!!!
Commercials were found.
Comskip 0.80.025, made using:

What does the 'no ini found' refer to?

[razrsharpe]

thats likely output from the comskip log... and it probably means that no ini file was specified in the commandline, or found in the current directory... so comskip ran using just the defaults... you can specify the ini file using:

--ini %PATHTOINIFILE%