Plugin: Sage Job Queue (SJQ)

[nyplayer]

Originally Posted by Slugger

Did those internal tasks eventually run (without the need to restart SJQ)?

No they never ran. I had to restart SJQ other Showanalyzers scheduled and completed but the tasks never ran. I had to restart SJQ then they ran.

I didn't have this problem with SJQ 343.

[Slugger]

Originally Posted by nyplayer

No they never ran. I had to restart SJQ other Showanalyzers scheduled and completed but the tasks never ran. I had to restart SJQ then they ran.

I didn't have this problem with SJQ 343.

Hmm... that tells me the internal task thread either died off (due to an uncaught exception) or it got stuck. I'm leaning towards the former, but the next time it happens can you get a thread dump of SJQ for me? That'll at least tell us what's going on with the internal task thread.

If the thread dump says the internal task client is dead then look for other Java stack traces in the log file from com.google.code.sagetvaddons.sjq.*

That code hasn't been touched in some time so if the thread is dying off (likely due to a NullPointerException lingering somewhere) then the bug's been in there for quite some time. I don't use the internal tasks myself so I'll be the first to admit that the internal task client is only lightly tested, but I'm sure if you can get the thread dumps it won't take much to track it down.

[nyplayer]

Slugger,

Will do when I get a chance right now I am back with SJQ343 and that works fine. I will put up the latest SJQ again and debug probably will not be till the morning.

[nyplayer]

Mon 4/6 7:06:55.969 Mon Apr 06 07:06:55 PDT 2009: SJQ Application Dump
	QueueLoader thread is alive...
		java.lang.Thread.sleep(Native Method)
		com.google.code.sagetvaddons.sjq.server.QueueLoader.run(QueueLoader.java:96)
		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:34)
		java.lang.Thread.run(Unknown Source)
	InternalTaskClient thread is dead!	Most recent LogCleaner thread is dead (this is normal behaviour)!
	Most recent FileCleaner thread is dead (this is normal behaviour)!

Mon 4/6 6:41:09.255 Sending record to server for A[1883613,1883590,"Married ... With Children",34240@0406.06:00,30]
Mon 4/6 6:41:12.974 java.sql.SQLException: database locked
Mon 4/6 6:41:12.974 	at org.sqlite.DB.execute(DB.java:270)
Mon 4/6 6:41:12.975 	at org.sqlite.DB.executeUpdate(DB.java:281)
Mon 4/6 6:41:12.975 	at org.sqlite.PrepStmt.executeUpdate(PrepStmt.java:77)
Mon 4/6 6:41:12.975 	at com.google.code.sagetvaddons.sjq.server.DataStore.markAsProcessed(DataStore.java:686)
Mon 4/6 6:41:12.976 	at com.google.code.sagetvaddons.sjq.server.TaskQueue.updateTask(TaskQueue.java:181)
Mon 4/6 6:41:12.976 	at com.google.code.sagetvaddons.sjq.server.TaskQueue.updateTask(TaskQueue.java:191)
Mon 4/6 6:41:12.976 	at com.google.code.sagetvaddons.sjq.server.InternalTaskClient.run(InternalTaskClient.java:47)
Mon 4/6 6:41:12.976 	at java.lang.Thread.run(Unknown Source)
Mon 4/6 6:41:12.977 Exception in thread "SJQ-InternalTaskClnt" Mon 4/6 6:41:12.977 java.lang.RuntimeException: java.sql.SQLException: database locked
Mon 4/6 6:41:12.977 	at com.google.code.sagetvaddons.sjq.server.DataStore.markAsProcessed(DataStore.java:691)
Mon 4/6 6:41:12.977 	at com.google.code.sagetvaddons.sjq.server.TaskQueue.updateTask(TaskQueue.java:181)
Mon 4/6 6:41:12.977 	at com.google.code.sagetvaddons.sjq.server.TaskQueue.updateTask(TaskQueue.java:191)
Mon 4/6 6:41:12.978 	at com.google.code.sagetvaddons.sjq.server.InternalTaskClient.run(InternalTaskClient.java:47)
Mon 4/6 6:41:12.978 	at java.lang.Thread.run(Unknown Source)
Mon 4/6 6:41:12.978 Caused by: java.sql.SQLException: database locked
Mon 4/6 6:41:12.978 	at org.sqlite.DB.execute(DB.java:270)
Mon 4/6 6:41:12.978 	at org.sqlite.DB.executeUpdate(DB.java:281)
Mon 4/6 6:41:12.978 	at org.sqlite.PrepStmt.executeUpdate(PrepStmt.java:77)
Mon 4/6 6:41:12.979 	at com.google.code.sagetvaddons.sjq.server.DataStore.markAsProcessed(DataStore.java:686)
Mon 4/6 6:41:12.979 	... 4 more

[Slugger]

Please reproduce with snapshot 454. This snapshot will do the thread dump automatically right at the time the exception is being thrown. Hopefully this will give me a clue as to what has the db locked at that time. Nothing should have the db locked long enough to cause this exception so it's probably a logic error somewhere, I just need a hint as to where to start looking.

[nyplayer]

Slugger,

I threw everything at the snapshot and no lockups.... but everytime I put up the 414 I get lockups. As you can see below everything ran ok. I will keep the snapshot up.

					
2081018	Married ... With Children	_TRANSCODE	Apr 6, 2009 10:43:07 AM	Apr 6, 2009 10:43:08 AM	Internal
2081019	Married ... With Children	_TRANSCODE	Apr 6, 2009 10:43:07 AM	Apr 6, 2009 10:43:08 AM	Internal
2078914	Duckworth Tribute	_TRANSCODE	Apr 6, 2009 10:43:06 AM	Apr 6, 2009 10:43:07 AM	Internal
2078914	Duckworth Tribute	AVIEDLCUT	Apr 6, 2009 10:35:00 AM	Apr 6, 2009 10:38:35 AM	192.168.2.170
2081018	Married ... With Children	AVIEDLCUT	Apr 6, 2009 10:35:02 AM	Apr 6, 2009 10:38:26 AM	192.168.99.1
2081019	Married ... With Children	AVIEDLCUT	Apr 6, 2009 10:35:02 AM	Apr 6, 2009 10:37:37 AM	192.168.99.1
2080680	Married ... With Children	PASS1XVID	Apr 6, 2009 9:46:12 AM	Apr 6, 2009 10:23:04 AM	192.168.2.170
2080677	Married ... With Children	PASS1XVID	Apr 6, 2009 9:46:12 AM	Apr 6, 2009 10:21:38 AM	192.168.2.170
2078914	Duckworth Tribute	PASS1XVID	Apr 6, 2009 9:46:12 AM	Apr 6, 2009 10:18:14 AM	192.168.99.1
2081012	Charmed	_MANUALREC	Apr 6, 2009 10:05:23 AM	Apr 6, 2009 10:05:28 AM	Internal
2081013	A Baby Story	_UNMANUALREC	Apr 6, 2009 9:19:03 AM	Apr 6, 2009 10:05:25 AM	Internal
2081012	Charmed	_UNMANUALREC	Apr 6, 2009 9:19:03 AM	Apr 6, 2009 10:05:23 AM	Internal
2081012	Charmed	SHOWANALYZER	Apr 6, 2009 9:10:56 AM	Apr 6, 2009 10:03:51 AM	192.168.2.170
2081013	A Baby Story	SHOWANALYZER	Apr 6, 2009 9:10:56 AM	Apr 6, 2009 9:32:05 AM	192.168.99.1
2080998	Charmed	_MANUALREC	Apr 6, 2009 9:10:56 AM	Apr 6, 2009 9:15:18 AM	Internal
2081000	Sabrina, the Teenage Witch	_UNMANUALREC	Apr 6, 2009 8:33:12 AM	Apr 6, 2009 9:05:15 AM	Internal
2081005	Sabrina, the Teenage Witch	_UNMANUALREC	Apr 6, 2009 8:33:12 AM	Apr 6, 2009 9:05:14 AM	Internal
2081006	Punk'd	_UNMANUALREC	Apr 6, 2009 8:33:13 AM	Apr 6, 2009 9:05:14 AM	Internal
2080998	Charmed	_UNMANUALREC	Apr 6, 2009 8:33:12 AM	Apr 6, 2009 9:05:13 AM	Internal
2081005	Sabrina, the Teenage Witch	SHOWANALYZER	Apr 6, 2009 8:33:12 AM	Apr 6, 2009 9:03:33 AM	192.168.99.1
2081006	Punk'd	SHOWANALYZER	Apr 6, 2009 8:33:13 AM	Apr 6, 2009 9:02:11 AM	192.168.2.170
2081000	Sabrina, the Teenage Witch	SHOWANALYZER	Apr 6, 2009 8:16:04 AM	Apr 6, 2009 8:33:13 AM	192.168.2.170
2080680	Married ... With Children	_MANUALREC	Apr 6, 2009 8:16:04 AM	Apr 6, 2009 8:16:53 AM	Internal
2080677	Married ... With Children	_MANUALREC	Apr 6, 2009 8:16:04 AM	Apr 6, 2009 8:16:53 AM	Internal
2080782	Sister, Sister	_UNMANUALREC	Apr 6, 2009 8:16:04 AM	Apr 6, 2009 8:16:53 AM	Internal
2080680	Married ... With Children	_UNMANUALREC	Apr 6, 2009 8:16:04 AM	Apr 6, 2009 8:16:53 AM	Internal

[Slugger]

Hmm.... I'm glad it's working ok now, but there's nothing I hate more than problems magically disappearing. The only difference between 414 and 454 is that 454 adds a call to the thread dumper inside the catch block where the original exception was being thrown.

The problem is either one of two things:

1. A very long read or write of the db was occurring, which caused the internal task thread to timeout. This could happen if a task client was dumping a large amount of output or you were loading a task log for a task with a lot of output. The DB driver's timeout is 3 seconds, which doesn't seem like a lot, but millions of rows can be written/read from the db in that short amount of time. I could see a problem in the case where you're trying to load a log within the GUI, though the read from the DB would be quick, I actually loop through the ResultSet and write back to the browser before closing the ResultSet - and writes can't write until all reads are closed.

2. There is a logic error in the internal task client where it's trying to write to the db while an outer method already has the lock in the db, causing contention and the timeout.

Either is possible, but #2 is more likely the cause. Keep me posted, b/c if it happens on 454 then the generated thread dump should be able to tell me which it is.

I could make a change to address #1, but I'd really rather hold off until I can get a thread dump. I'd rather make the change with some evidence that it's the problem instead of fixing things in the dark.

Just to be clear, when you say "lockups" you're referring to the scenario described in the stack dumps above where the InternalTaskClnt thread is dying off? Your system, SageTV, nor SJQ are actually hard locking, right? Just internal tasks get stuck in the queue (external tasks would continue to run fine).

[nyplayer]

Looks like it happened. Just internal tasks lockup all others continue fine... Including new ones(except internal tasks) . Could I be causing my own problems by running SJQ belownormal priority. I do not have SJQ running of my service but instead start the gui up in belownormal and I have SJQ load from the client properties.... but this is the same procedure I have always used. This started happening with the new update.... 343 has never failed me.

[Slugger]

Ok, that dump answered all my questions. I know the problem, I know the cause, I just don't know how I'm going to fix it.

Bare with me while I ponder a fix. I'll try to have a new snapshot up sometime this evening. How big is your current sjq.sqlite db file?

Running SJQ in lower priority is probably why you're running into it, but ultimately it's still something I should address. I should not rely on a system's processor speed or the priority at which I'm running at to determine if things are going to hit problems. Given I'm using SQLite in a multi-thread app where all threads are accessing the db file, there's always a chance this kind of contention can occur, but I should be able to minimize that risk more than the current version of SJQ does.

As a quick side note, 343 would not have this problem because 343 (and older) used a single DB connection across all threads and synchronized on that instance so if any thread was using the db for anything then the rest of the threads simply blocked until it was their turn. This lead to deadlock under certain conditions. Though I've solved that, the fact that SQLite is not a client/server DB and the fact that the LogCleaner algorithm is, by necessity, a brute force cleanup method, this scenario you're running into can occur.

[nyplayer]

My DB is about 90 meg.
BTW the reason why I run SJQ of the gui is that I can reset it without interfering with anybody else watching. I also like all scans to run below normal on my drives.

[Slugger]

Ok, try snapshot 455. Addresses the issue by monitoring the daemon threads and respawning them if they unexpectedly die off. I was trying to figure out a way to eliminate contention for the DB between the threads, but given the way SQLite works, any such solution is not possible in a multi-threaded app. I've got a few strategies to reduce the risk, but no solution is 100% fool proof so either way this kind of monitoring should be done.

I'm curious to know how often threads are having to be respawned. Can you report back in a day or few with the number of times you find these lines in your SageTV logs:

SJQ: Had to restart the xxx thread!

Where 'xxx' will be the name of the thread that restarted.

[Slugger]

Originally Posted by nyplayer

My DB is about 90 meg.
BTW the reason why I run SJQ of the gui is that I can reset it without interfering with anybody else watching. I also like all scans to run below normal on my drives.

SJQ can be started/stopped/upgraded/downgraded, etc. without having to stop SageTV at all. To stop SJQ while SageTV is running, just move the sjq.context.xml file out of the \SageTV\SageTV\jetty\contexts\ directory. To restart it, just put the file back in the directory. To simply force a restart of SJQ just modify the timestamp of the context file (open and save it in notepad).

Upgrades can be done the same way, just unzip the new version over the old one while SageTV is running and it'll upgrade.

[wayner]

I finally got around to upgrading to the latest version of SJQ. So far I am able to have logging enabled without any issues.

This isn't a complaint but personally I preferred the "original" SJQ 2 UI but maybe that is just me.

[nyplayer]

Originally Posted by Slugger

SJQ can be started/stopped/upgraded/downgraded, etc. without having to stop SageTV at all. To stop SJQ while SageTV is running, just move the sjq.context.xml file out of the \SageTV\SageTV\jetty\contexts\ directory. To restart it, just put the file back in the directory. To simply force a restart of SJQ just modify the timestamp of the context file (open and save it in notepad).

Upgrades can be done the same way, just unzip the new version over the old one while SageTV is running and it'll upgrade.

That works with upgrades... but when I touched the content it would rescan etc... but the Internal tasks still would not run. I had to completely restart SJQ.

[Slugger]

Originally Posted by wayner

I finally got around to upgrading to the latest version of SJQ. So far I am able to have logging enabled without any issues.

This isn't a complaint but personally I preferred the "original" SJQ 2 UI but maybe that is just me.

Preferred in what way? Functionally they should be equivalent, I agree aesthetically it doesn't quite look as appealing to the eye. The original library I was using for v2.0.0 was a wrapper on top of GWT that was causing little quirks here and there. So I dumped the eye candy to save the hassle of those little quirks. The biggest issue is that I have little (or no) artistic abilities. With some work a very appealing UI look can be achieved with stock GWT, I just don't have it in me. The old wrapper I was using (SmartGWT) already had polished UI widgets from the get go making me look a little better.

[wayner]

You're right Slugger - they are equivalent I agree that the old one looked more polished. On the new one the fonts are bigger and the columns for the data fields aren't wide enough causing them to wrap. As you say it is not a functional issue but it just isn't as pretty.

[nyplayer]

SJQ: Had to restart the InternalTaskClient thread! 3 times since yesterday. Not bad at all considering my rule file.

SJQ: Had to restart the QueueLoader thread! 1 time
My rule file below.

if [IsTV == "true" && IsScheduledRecording == "true" && Filename =$ ".mpg" && TranscodeQueueSize < "1"]{
    :PRIORITY 99
      _UNMANUALREC
    :PRIORITY 97
      SHOWANALYZER
}
if [IsTV == "true" && IsScheduledRecording == "true" && Filename =$ ".mpg" && TranscodeQueueSize >= "1"]{
    :PRIORITY 99
      _UNMANUALREC
    :PRIORITY 98
      SHOWANALYZERNT
}
//Archive Title
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".mpg" && (Title =="Little People, Big World" || (Title == "17 Kids and Counting" || (Title == "Extreme Makeover: Home Edition" || (Title == "Jon & Kate Plus 8" || (Title == "18 Kids and Counting" || (Title == "Table for 12"))))))]{
    :PRIORITY 50
      _ARCHIVE
}
//Archive Description
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".mpg" && (Description =* "osselin" || (Description =* "extuplet" || (Description =* "uggar")))]{
    :PRIORITY 50
      _ARCHIVE
}
//Archive Person
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".mpg" && (Person =="Goldie Hawn" || (Person == "Julia Roberts" || (Person == "Meg Ryan" || (Person == "Tom Hanks" || (Person == "Barbra Streisand")))))]{
    :PRIORITY 50
      _ARCHIVE
}
//ManualRec Title
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".mpg" && (Title =^ "Star Trek" || (Title == "Smallville" || (Title == "Tales From the Darkside" || (Title == "The Outer Limits" || (Title == "Charmed" || (Title == "Jake 2.0" || (Title == "Law & Order: Criminal Intent" || (Title == "Planet Earth" || (Title == "CSI: Crime Scene Investigation" || (Title == "Married ... With Children"))))))))))]{
    :PRIORITY 50
      _MANUALREC
}
//1Pass HQ Title Manual
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".mpg" && TranscodeQueueSize < "1" && (IsManualRecord == "true" || (IsArchived == "true"))]{
    :PRIORITY 1
      PASS1XVID
}
//1pass 30 Days Old Not watched
if [IsTV == "true" && IsActivelyRecording == "false" && IsArchived == "false" && IsManualRecord == "false" && Filename =$ ".mpg" && TranscodeQueueSize < "1" && MediaAge > "30D" && TimeOfDay > "00:01" && TimeOfDay < "17:00"]{
    :PRIORITY 1
      PASS1XVID
}
if [IsTV == "true" && IsActivelyRecording == "false" && TimeOfDay > "00:01" && TimeOfDay < "17:00" && IsArchived == "false" && FileExists == "////GForceNAS//sagetvnas//connected.txt" && Title != "Nancy Grace" && Title != "The Ellen DeGeneres Show" && Title != "NBA Basketball" && Filename =$ ".avi" && FileExists != "%d%\\%p%.inuse" && FileExists != "%d%\\%p%.edl" && (Filename =^ "J:" || (Filename =^ "j:" || (Filename =^ "M:" || (Filename =^ "m:" || (Filename =^ "N:" || (Filename =^ "n:" || (Filename =^ "O:" || (Filename =^ "o:"))))))))]{
   :TRANSCODEOPTS "Copy-avi Move Play" "false" "////GForceNAS//sagetvnas//sagetv"
    :PRIORITY 25
   _TRANSCODE
}
if [IsTV == "true" && IsActivelyRecording == "false" && TimeOfDay > "00:01" && TimeOfDay < "17:00" && (IsArchived == "true" || (Title == "Nancy Grace" || (Title == "The Ellen DeGeneres Show" || (Title == "NBA Basketball")))) && Filename =$ ".avi" && FileExists != "%d%\\%p%.inuse" && FileExists != "%d%\\%p%.edl" && (Filename =^ "M:" || (Filename =^ "m:" || (Filename =^ "N:" || (Filename =^ "n:" || (Filename =^ "O:" || (Filename =^ "o:"))))))]{
   :TRANSCODEOPTS "Copy-avi Move Play" "false" "j:\sageuncj"
    :PRIORITY 25
   _TRANSCODE
}
//Avi EDL Cut
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".avi"]{
      AVIEDLCUT  
}
//Watch DeleteTitle
if [IsTV == "true" && IsActivelyRecording == "false" && IsArchived == "false" && IsManualRecord == "false" && MediaAge > "40D" && (Title =="Nancy Grace" || (Title == "The Ellen DeGeneres Show" || (Title == "xxxxxxxxxxxx")))]{
    :PRIORITY 13
      _DELETE 
}
//1Pass HQ Title Manual
if [IsTV == "true" && IsActivelyRecording == "false" && Filename =$ ".mpg" && TranscodeQueueSize >= "1" && (IsManualRecord == "true" || (IsArchived == "true"))]{
    :PRIORITY 2
      PASS1XVIDNT
}
//1pass 30 Days Old Not watched
if [IsTV == "true" && IsActivelyRecording == "false" && IsArchived == "false" && IsManualRecord == "false" && Filename =$ ".mpg" && TranscodeQueueSize >= "1" && MediaAge > "30D" && TimeOfDay > "00:01" && TimeOfDay < "17:00"]{
    :PRIORITY 2
      PASS1XVIDNT
}

[Slugger]

Are all the exceptions "Database locked" exceptions? The QueueLoader dying off is never a good thing. Now thinking I should go back to a single thread to prevent the possibility of things dying off unexpectedly.

[nyplayer]

Originally Posted by Slugger

Are all the exceptions "Database locked" exceptions? The QueueLoader dying off is never a good thing. Now thinking I should go back to a single thread to prevent the possibility of things dying off unexpectedly.

YES all DB locked

Mon 4/6 20:11:42.503 Exception in thread "SJQ-QueueLoader" Mon 4/6 20:11:42.503 java.lang.RuntimeException: java.sql.SQLException: database locked
Mon 4/6 20:11:42.504 at com.google.code.sagetvaddons.sjq.server.DataStore.setSetting(DataStore.java:859)
Mon 4/6 20:11:42.504 at com.google.code.sagetvaddons.sjq.server.QueueLoader.run(QueueLoader.java:43)
Mon 4/6 20:11:42.504 at java.lang.Thread.run(Unknown Source)
Mon 4/6 20:11:42.504 Caused by: java.sql.SQLException: database locked
Mon 4/6 20:11:42.504 at org.sqlite.DB.execute(DB.java:270)
Mon 4/6 20:11:42.504 at org.sqlite.DB.executeUpdate(DB.java:281)
Mon 4/6 20:11:42.505 at org.sqlite.PrepStmt.executeUpdate(PrepStmt.java:77)
Mon 4/6 20:11:42.505 at com.google.code.sagetvaddons.sjq.server.DataStore.setSetting(DataStore.java:857)
Mon 4/6 20:11:42.505 ... 2 more

[Slugger]

Yeah, back to a single execution thread it is. I just can't reduce the risk of DB contention to an acceptable level. Going to be a couple weeks though as I'm getting ready to head to Vegas!!

Issue 63 opened for this.