Plugin: Sage Job Queue (SJQ) v3

[skiingwiz]

Originally Posted by Slugger

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.

I agree 100%. This is a case that would be especially easy for the compiler to check for and warn about.

The way that I usually make sure not to fall victim to this problem is to actually multiply the numbers and put the whole value in the assignment. The compiler will complain if you try to use 2592000000 as a literal without the 'L'.

Anyway, back on topic!

[ohpleaseno]

christ almighty i wish i had a clue what you two were talking about.

[Slugger]

I'm going into coding shutdown mode starting next Fri, Dec 18 until sometime in the middle of Jan at which time I plan on starting my next SageTV project. I plan on moving SJQv3 out of beta by next Friday. With that in mind, this is the time to test, test, test and raise any issues/feature requests (large feature requests are likely to be pushed back to 3.0.1 at this time, but don't be afraid to ask).

I have just uploaded what I expect to be the final builds for SJQv3. Unless I discover something or someone brings something to my attention, these builds will likely just be relabelled official SJQv3 next Friday. Please test these as much as possible before then.

Server Changes in Snapshot 693

• Employ an in-memory caching strategy for the FileExists and FreeSpacePercentage tests. Since use of the FileExists test typically checks for files in the same small set of directories over and over again, I now cache the listings of those directories in memory for a short period of time and then these tests check the cache for files instead of constant disk reads (I was shocked to learn that the JRE itself doesn't do this kind of thing); up to 80% performance gain seen in my own environment with this change.

Task Client Changes in Snapshot 694

• Rework the task client output buffer to use CharBuffer instead of reading and storing lines in a List<String>; this is much faster and much less memory intensive
• Fix build process to use native ant task for uploading to Google Code project (most won't care about this, but I do)
• Make task client buffer size configurable via sjqc.properties file. Default is 199000 bytes, which keeps it under the default max size of a POST request that Jetty will accept. If you increase this value, you need to increase the max POST request size Jetty will accept (see install instructions in User Guide). You may want to reduce this value so that the task client will flush the task output to the server logs more frequently, however I strongly discourage a value of less than, say, 10000 as it will just cause too much unnecessary network traffic (YMMV).

[evilpenguin]

That's excellent news. So far 692 has been working fantastic and i'll load up you're latest build tonight for some more testing.

A question about the logs: why is SJQ throwing away my line padding? I worked hard pretty printing mediaShrink's logs so i'd prefer if SJQ didn't flatten them

SJQ:

Welcome to mediaEngine v2.0 (Built on 10:11:30.01 12-09-2009 )
Staring Proccesing at

+ Executable   : D:\upnp2podcast\mediaScraper\mediaEngine.exe
+ EXE path     : D:\upnp2podcast\mediaScraper
+ Parsing switches
- optionsString: "/batch" "/onlyWhenVprj" "/saveLog" "/defaultProfile" "autoEncode" "/findFileRegEx" "avi|mpg|mkv|mp4|mpeg|VIDEO_TS|ts|ogm|divx|mpts|dvr-ms" "/mediaShrink" "fixBug" "\\EVE\Data3\SageRecordings\SamanthaWho-TheEx-4767942-0.mpg" "/inPlace" "/batch" "/onePass" "/highProfile" "/cliBitrate" "1500" "/verticalScale" "540"

Normal Log:

 Welcome to mediaEngine v2.0 (Built on 10:11:30.01 12-09-2009 )
 Staring Proccesing at  

  + Executable   : D:\upnp2podcast\mediaScraper\mediaEngine.exe
  + EXE path     : D:\upnp2podcast\mediaScraper
  + Parsing switches
    - optionsString: "/batch" "/onlyWhenVprj" "/saveLog" "/defaultProfile" "autoEncode" "/findFileRegEx" "avi|mpg|mkv|mp4|mpeg|VIDEO_TS|ts|ogm|divx|mpts|dvr-ms" "/mediaShrink" "fixBug" "D:\Test Content\QAM_720p_HDTV_43.mpg"

[evilpenguin]

Prolly a semi-large feature request, but can you add a tab for the mediaFile's episode name in the active/failed/completed tab? Also, and more importantly, the same thing for the media debugger suggestions.

[wayner]

Originally Posted by Slugger

I'm going into coding shutdown mode starting next Fri, Dec 18 until sometime in the middle of Jan at which time I plan on starting my next SageTV project.

What's the next project Slugger?

[ohpleaseno]

on unedit: SJQ wouldn't recognize my password

solution: restarted my Sage server

[Slugger]

Originally Posted by ohpleaseno

nvm

If you don't mind, would you post what the problem was/solution since someone else is bound to hit the same thing at some point.

[Slugger]

Originally Posted by evilpenguin

That's excellent news. So far 692 has been working fantastic and i'll load up you're latest build tonight for some more testing.

A question about the logs: why is SJQ throwing away my line padding? I worked hard pretty printing mediaShrink's logs so i'd prefer if SJQ didn't flatten them

java.lang.String.trim()... a lazy developer's cure all to all problems String related. I went ahead and dumped trim() and implemented proper logic in snapshot 696. I didn't test it though so you'll have to report back if it actually fixed it (worst case scenario is the formatting is just worse than it was so I didn't take much [any] time to test it).

Originally Posted by evilpenguin

Prolly a semi-large feature request, but can you add a tab for the mediaFile's episode name in the active/failed/completed tab? Also, and more importantly, the same thing for the media debugger suggestions.

Also in 696; again no testing so you'll have to test it for me.

[Slugger]

Originally Posted by wayner

What's the next project Slugger?

No comment. I don't want to get anyone excited nor commit myself to anything in case the inspiration passes me by when the new year rolls around.

[nyplayer]

Slugger,

Is this normal nothing appears to be kicking off also 696 shows 693 in about.

2009-12-10 18:09:21,515 WARN  [Butler]: Thu Dec 10 18:09:21 PST 2009: SJQ Application Dump
	MediaQueueLoader thread is alive...
		java.io.WinNTFileSystem.list(Native Method)
		java.io.File.list(Unknown Source)
		com.google.code.sagetvaddons.sjq.server.tests.FieldFileExists.fileExists(FieldFileExists.java:46)
		com.google.code.sagetvaddons.sjq.server.tests.FieldFileExists.run(FieldFileExists.java:99)
		com.google.code.sagetvaddons.sjq.server.RulesParser$Evaluator.internalTest(RulesParser.java:227)
		com.google.code.sagetvaddons.sjq.server.RulesParser$Evaluator.runTest(RulesParser.java:142)
		com.google.code.sagetvaddons.sjq.server.RulesParser$Evaluator.evalTest(RulesParser.java:129)
		com.google.code.sagetvaddons.sjq.server.RulesParser$Evaluator.(RulesParser.java:85)
		com.google.code.sagetvaddons.sjq.server.RulesParser$Evaluator.(RulesParser.java:108)
		com.google.code.sagetvaddons.sjq.server.RulesParser.loadQ(RulesParser.java:265)
		com.google.code.sagetvaddons.sjq.server.RulesParser.(RulesParser.java:239)
		com.google.code.sagetvaddons.sjq.server.MediaFileQueueLoader.run(MediaFileQueueLoader.java:73)
		java.lang.Thread.run(Unknown Source)
	SysMsgQueueLoader thread is alive...
		com.google.code.sagetvaddons.sjq.server.SystemMessageQueueLoader.run(SystemMessageQueueLoader.java:55)
		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:68)
		java.lang.Thread.run(Unknown Source)
	No LogCleaner thread has ever been created (this is ABNORMAL)!
	No FileCleaner thread has ever been created (this is ABNORMAL)!
	No VacuumCleaner thread has ever been created (this is ABNORMAL)!

PS went back to 692 and everything is working again.

[Slugger]

I reported a similar looking thread dump awhile back. It is a definite bug with the JRE. SJQ is causing it, sort of, but the problem is that the java.io.File.list() method is calling the underlying native method (java.io.WinNTFileSystem.list()) and that native method is looping/blocked/whatever. The javadocs make no mention of the method blocking under any circumstances so the fact that it is blocking is a bug. If you're seeing the same symptoms as I was, then your CPU is not pegged at 100%, but is probably at 0%, which leads me to believe the method is blocked/deadlocked. So it's a JRE bug, as far as I can tell. The other possibility is that SJQ has got into a hard, endless loop of calling that test, but if that were the case, you'd see your CPU pegged at 100%.

Unfortunately, the only remedy may be to reboot the system as trying to stop/kill SJQ or Sage did not work for me and eventually hard locked my system. I'd wait until your evening's recordings are done before trying to remedy the situation.

[Slugger]

Originally Posted by nyplayer

PS went back to 692 and everything is working again.

Does going back to 696 always reproduce this? If so, then I might owe Sun an apology.

[Slugger]

Originally Posted by Slugger

Does going back to 696 always reproduce this? If so, then I might owe Sun an apology.

And if it does please let me know because I'd like to add some debug statements to trace the code and see if it's indeed blocking like I think it is or if SJQ is in some kind of infinite loop.

[nyplayer]

Slugger,

It just does not schedule anything as most of my rules check for exists or not exists files. So it sits there at 0%... no lockups.

Ps I run SJQ from the client on my server not from the service so restarting SJQ is no problem.

[Slugger]

Originally Posted by nyplayer

Slugger,

It just does not schedule anything as most of my rules check for exists or not exists files. So it sits there at 0%... no lockups.

Ps I run SJQ from the client on my server not from the service so restarting SJQ is no problem.

Is the thread snapshot looking the same (queue loader thread stuck in java.io.File.list())? I'll build a debug build tomorrow, I'll PM you the details of where to download it. Are you possibly checking on a network drive via the FileExists test? I highly doubt SJQ is into an infinite loop and I really believe this is a JRE bug. But we'll find out more once I get that debug build.

[nyplayer]

Slugger,

No lockups no high CPU usage. Rules not looking for existence of a file run fine.

2009-12-10 21:01:34,593 INFO  [SystemMessageQueueLoader]: Run completed [93ms]
2009-12-10 21:02:12,671 WARN  [FieldFileExists]: Adding '\\192.168.2.155\j$\sageuncj' to the cache!
2009-12-10 21:02:13,718 WARN  [FieldFileExists]: Done reading '\\192.168.2.155\j$\sageuncj'!
2009-12-10 21:02:13,718 WARN  [FieldFileExists]: Adding 'c:\controls' to the cache!
2009-12-10 21:02:13,718 WARN  [FieldFileExists]: Done reading 'c:\controls'!
2009-12-10 21:02:13,765 WARN  [FieldFileExists]: Adding '\\NYPLAYER\sageunct$' to the cache!
2009-12-10 21:02:19,390 WARN  [FieldFileExists]: Done reading '\\NYPLAYER\sageunct$'!
2009-12-10 21:02:24,500 WARN  [FieldFileExists]: Adding 'M:\importuncm' to the cache!
2009-12-10 21:02:24,515 WARN  [FieldFileExists]: Done reading 'M:\importuncm'!
2009-12-10 21:02:25,421 WARN  [FieldFileExists]: Adding '\\192.168.2.155\j$\importuncj' to the cache!
2009-12-10 21:02:25,437 WARN  [FieldFileExists]: Done reading '\\192.168.2.155\j$\importuncj'!
2009-12-10 21:02:26,328 WARN  [FieldFileExists]: Adding '\\192.168.2.155\importuncj' to the cache!
2009-12-10 21:02:26,328 WARN  [FieldFileExists]: Done reading '\\192.168.2.155\importuncj'!
2009-12-10 21:02:28,015 WARN  [FieldFileExists]: Adding 'M:\sagem' to the cache!
2009-12-10 21:02:28,031 WARN  [FieldFileExists]: Done reading 'M:\sagem'!
2009-12-10 21:02:29,062 WARN  [FieldFileExists]: Adding 'N:\sagen' to the cache!
2009-12-10 21:02:29,078 WARN  [FieldFileExists]: Done reading 'N:\sagen'!

It appears that if it looks for existence of a file it will not run the rule..... even though the files do exist.


this rule runs

//QFIX ALL TV
if [IsObjMediaFile == true && FileExists != "%d%/%p%.qfix" && FileExists != "c:\\controls\\oktoreboot.txt" && FileExists != "c:\\controls\\Stoprunning.txt" && $.GetAiringChannelNumber{} !="35" && $.GetAiringChannelNumber{} !="36" && Filename =$ ".mpg" && $.IsTVFile{} == "true" && $.IsNotManualOrFavorite{} == "false" && $.IsFileCurrentlyRecording{} == "false" && $.GetNumberOfSegments{} == "1" && $.GetMediaTitle{} != "Not Recording"] {
   :RUNQLOADER "true"    
    :PRIORITY 998
     SJQFIXShow
}

This rule doesn't run but if I backoff to 692 it runs ok. qfix ... vprj file exists and also my recordings are manual.

//VRDCUT NO Arhive
if [IsObjMediaFile == true && FileExists == "%d%/%p%.qfix" && FileExists == "%d%/%p%.vprj" && FileExists != "%d%/%p%.donecut" && FileExists != "c:\\controls\\oktoreboot.txt" && FileExists != "c:\\controls\\Stoprunning.txt" && Filename =$ ".mpg" && $.IsTVFile{} == "true" && $.IsManualRecord{} == "true" && $.IsLibraryFile{} == "false" && $.IsFileCurrentlyRecording{} == "false" && $.GetNumberOfSegments{} == "1"] {
  :RUNQLOADER "true"
    :PRIORITY 905
  SJQVRDCUT
}

[Slugger]

What do you mean it doesn't run? It's running, but not loading anything into the queue as expected? Can you get a thread dump for me? Are you still seeing the MediaQueueLoader thread dump that's stuck in the java.io.File.list() method? If so, are those extra debug messages looping? Did all the dirs scan? Are all your recording dirs listed in that previous output? I'm just getting a little confused as the actual problem here.

If it's just that it's not loading tasks into the queue as expected then run a single file through the media debugger and get that output, is it the FileExists test that is definitely returning the wrong result?

[evilpenguin]

Originally Posted by Slugger

Prolly a semi-large feature request, but can you add a tab for the mediaFile's episode name in the active/failed/completed tab? Also, and more importantly, the same thing for the media debugger suggestions.

This works great in 696

I'm running some encodes tonight so i'll report back on the log changes tomorrow.

[nyplayer]

Slugger,


Ding Ding Ding .. your test appears to be case sensitive now.
Task not being added to que, It finds the first file qfix but does not find the 2nd vprj.

2009-12-11 01:59:14,312 WARN  [MediaFileQueueLoader]: Processing 'Law & Order'...
2009-12-11 01:59:14,312 WARN  [RulesParser]: 	Line 2: Evaluating 'IsObjMediaFile == "true"' == true
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 01:59:14,312 WARN  [FieldFileExists]: Adding 'M:\sagem' to the cache!
2009-12-11 01:59:14,312 WARN  [FieldFileExists]: Done reading 'M:\sagem'!
2009-12-11 01:59:14,312 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists == "%d%/%p%.qfix"' == true
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 01:59:14,312 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 01:59:14,312 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists == "%d%/%p%.vprj"' == false

This ran.. I changed case in Vprj

2009-12-11 02:12:06,828 WARN  [FieldFileExists]: Done reading 'M:\sagem'!
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists == "%d%/%p%.qfix"' == true
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists == "%d%/%p%.Vprj"' == true
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists != "%d%/%p%.donecut"' == true
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 02:12:06,828 WARN  [FieldFileExists]: Adding 'c:\controls' to the cache!
2009-12-11 02:12:06,828 WARN  [FieldFileExists]: Done reading 'c:\controls'!
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists != "c:\controls\oktoreboot.txt"' == true
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating 'FileExists != "c:\controls\Stoprunning.txt"' == true
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%c%' == 'M:\sagem\LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%d%' == 'M:\sagem'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%f%' == 'LawOrder-MurderBook-5105542-0.mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%e%' == 'mpg'
2009-12-11 02:12:06,828 WARN  [MediaVariables]: 	MediaVar '%p%' == 'LawOrder-MurderBook-5105542-0'
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating 'Filename =$ ".mpg"' == true
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating '$.IsTVFile{} == "true"' == true
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating '$.IsManualRecord{} == "true"' == true
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating '$.IsLibraryFile{} == "false"' == true
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating '$.IsFileCurrentlyRecording{} == "false"' == true
2009-12-11 02:12:06,828 WARN  [RulesParser]: 	Line 2: Evaluating '$.GetNumberOfSegments{} == "1"' == true