Plugin: Sage Job Queue (SJQ)

[rsagetv99]

Hey, I just PM'd you.

Also, how would I rebuild the wiz.bin? Is there a way to repair it without losing my viewing history and pointers to my current recordings?

[rsagetv99]

FYI I did a repair_mismatched_media=true last night, and brought sage down and back up this morning, but I am still having the problem.

[Slugger]

Try snapshot 484, should fix the problem. I do not have time to run any thorough testing on this build so please report back your findings.

[rsagetv99]

Originally Posted by Slugger

Try snapshot 484, should fix the problem. I do not have time to run any thorough testing on this build so please report back your findings.

Man, I hope you didn't create a new build just for my problem. I was willing to wait until you moved.

If you did, hopefully it did not take a lot of time, and thanks a lot!

I already loaded it and it looks like it is working.

[Skirge01]

Slugger, I know you're busy, so take your time. Perhaps someone else will be able to help me out. The SJQ service keeps crashing on both my XP client and my WHS box. I can't figure out what's causing it. I see this in the wrapper.log on the server:

INFO   | jvm 1    | 2009/06/26 17:11:42 | Connection refused: connect
INFO   | jvm 1    | 2009/06/26 17:32:24 | Exception in thread "Thread-294" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://mediaserver:8125/sjq/SJQ?proto=2&cmd=writeLog
INFO   | jvm 1    | 2009/06/26 17:32:24 | 	at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
INFO   | jvm 1    | 2009/06/26 17:32:24 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
INFO   | jvm 1    | 2009/06/26 17:32:24 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
INFO   | jvm 1    | 2009/06/26 17:32:24 | Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://mediaserver:8125/sjq/SJQ?proto=2&cmd=writeLog
INFO   | jvm 1    | 2009/06/26 17:32:24 | 	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
INFO   | jvm 1    | 2009/06/26 17:32:24 | 	... 3 more
INFO   | jvm 1    | 2009/06/26 22:01:13 | Exception in thread "Thread-323" java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://mediaserver:8125/sjq/SJQ?proto=2&cmd=writeLog
INFO   | jvm 1    | 2009/06/26 22:01:13 | 	at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:01:13 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.dumpBuffer(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:01:13 | 	at com.google.code.sagetvaddons.sjqc.IOMonster.run(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:01:13 | Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://mediaserver:8125/sjq/SJQ?proto=2&cmd=writeLog
INFO   | jvm 1    | 2009/06/26 22:01:13 | 	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:01:13 | 	... 3 more
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: Encountered an error running main:
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: java.lang.RuntimeException: java.io.IOException: Server returned HTTP response code: 500 for URL: http://mediaserver:8125/sjq/SJQ?proto=2&cmd=writeLog
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at com.google.code.sagetvaddons.sjqc.TaskClient.log(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at com.google.code.sagetvaddons.sjqc.TaskClient.pop(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at com.google.code.sagetvaddons.sjqc.TaskClient.run(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at com.google.code.sagetvaddons.sjqc.TaskClient.main(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at java.lang.reflect.Method.invoke(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:236)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: Caused by: java.io.IOException: Server returned HTTP response code: 500 for URL: http://mediaserver:8125/sjq/SJQ?proto=2&cmd=writeLog
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
INFO   | jvm 1    | 2009/06/26 22:02:05 | WrapperSimpleApp: 	... 11 more
STATUS | wrapper  | 2009/06/26 22:02:07 | <-- Wrapper Stopped

But, I have no clue what any of that means.

[Slugger]

What version of SJQ are you running? If anything below official 2.1.4 then upgrade to the latest snapshot. This looks like the DB locking problems seen in 2.1.3 and older. Errors that should be fixed in 2.1.4 and above.

[Skirge01]

SJQ is 2.1.4.466 and SJQC is 2.1.4.468

[Slugger]

Need to see the server logs then. The 500 errors reported by the SJQC client would be caused by the server throwing an exception. Check the server logs in SJQ and paste in the exception(s) seen.

[Slugger]

Originally Posted by Slugger

Need to see the server logs then. The 500 errors reported by the SJQC client would be caused by the server throwing an exception. Check the server logs in SJQ and paste in the exception(s) seen.

Also, try upgrading to the latest snapshot build. Let me know if the problems persist with the latest snapshot build.

[Skirge01]

Unless there are exceptions that don't actually write the word "exception" to the log, I don't see any. I'm attaching the current log for your better trained eyes. I'm upgrading to sjqc 2.1.5.484 on both PCs, but I don't see a more recent sjq service for me to install on the server. Did I overlook it? I'm hesitant to change over from service to non-service and alter something that gets rid of the issue, but I'm at your disposal.

EDIT: When I went to install the client, I remembered that I was running them as services and noticed that there isn't a later build than 468. I also realized that SJQ isn't installed as a service on the server, so I'm installing the latest there. I think I'm writing this too early in the morning! Sorry for the confusion here.

[Slugger]

2009/06/28 09:31:52.589	LogCleaner instance finished [47937ms]
{snip}
2009/06/28 09:35:54.386	FileCleaner instance finished [289734ms]

This is your problem. The log cleaner thread is taking 45+ seconds to run and the file cleaner thread is taking 289+ (nearly five minutes) to run (some earlier entries show it taking more than 5 minutes). Clients trying to connect are probably going to time out b/c the db is probably being locked somewhere during that 5 mins for too long. Based on your logs, you are having the SJQ file cleaner scan network drives. Obviously something is making that take way too long and is the likely root of all the other problems. I'd still try upgrading the server to the latest snapshot and try again, but I don't expect it to help - you need to fix whatever issue is causing a file scan on your network drives to take 5+ minutes when it should be but a few seconds, tops. The slow log cleaner is probably a product of the file cleaner so I suspect if you fix the network drive issue (or worst case stop using the file cleaner in SJQ) then the rest of the issues should fix themselves.

If SJQ server isn't throwing exceptions, then something else is. Any 500 HTTP response by Jetty should result in an exception being thrown, if not by SJQ then by Jetty. Check the Jetty logs (enable them, if necessary). There might be a system and/or Jetty problem behind all of this.

[Skirge01]

Any chance this is simply due to the amount of storage I have? I've currently got about 6TB in storage, containing about 1k TV recordings and over 4k files in the storage pool when you factor in edl, log, txt, my, properties, and jpg files.

I did use slower, WD Green drives, but this would be the very first time that I've seen any sort of disk bottleneck.

I'll also turn on logging for Jetty and keep an eye out for any issues.

[Slugger]

SJQ simply gets a directory listing, even with the largest of file counts in a directory, it should never take ~5 minutes to scan through a list. If you continue to have problems then try disabling use of the file cleaner feature in SJQ. If that fixes the problems then we at least know exactly what's causing the problems then we can try to narrow down the issue within the SJQ code through some debug builds.

Definitely can't do any debug builds for probably at least a week as my Sage system is offline, shutdown, and sitting in a box on a floor at the new house. Probably going to be at least a week or so before I even think about unpacking stuff in the new office. So for now, I'd definitely try disabling the file cleaner and see if that at least stops the clients from failing. Getting any exception dumps from the Jetty logs would also be helpful as we'll need to track down the root cause of the 500 errors the clients are seeing.

[Skirge01]

Thanks, Slugger. Take your time.

I turned off the file cleaner as of the 28th and I haven't had any frozen threads since. I'll give it about a week before I say that definitively stopped the problem.

I'm also going to run some I/O tests on my drives to see if there's an obvious bottleneck there. I have the WD Green drives and a lone Samsung F1 I haven't replaced with a WD yet. That actually reminds me... my single Samsung F1 is not formatted in 64k blocks like the WD's yet. I don't know if that might be a barrier. I'll still run HD_Tach to see what kind of performance I'm getting on them.

[Slugger]

It might not be h/w... typically, when dealing with network drives, I'd start investigating your DNS setup. Is your Sage server able to quickly resolve your network drive names (i.e. \\hostname\...)? My general experience with network file systems when things start to take way too long is some kind of network config problem. Perhaps the JVM is trying to resolve your hostname via DNS and then going to a hosts file or something only after it times out? That would explain why the scans are so slow, but don't appear to error out. I'd start there before doing any h/w tests.

Since disabling the file cleaner has the log clener been running quicker?

[Skirge01]

Just pulled it up now and saw this:

2009/06/30 15:01:03.465	LogCleaner instance started
2009/06/30 15:01:03.465	FileCleaner instance started
2009/06/30 15:01:03.465	File cleaner settings cannot be empty!
2009/06/30 15:02:01.169	LogCleaner instance finished [57704ms]

Given how SJQ is yelling at me, I'm not sure if I "disabled" file cleaner the proper way. I just cleared out all the settings. Therefore, I'm not sure if the lack of improvement for log cleaner is really telling us anything.

[Skirge01]

Sorry, forgot to answer the first part of your question. Regarding the network browsing, it sure seems to happen pretty quickly, but, to be honest, I'm not sure how quick it should be. I pull up network shares off my WHS box all the time when copying Blu-rays over and the folders pop up within a couple of seconds, no matter which computer I'm using. I enabled jumbo frames for my entire network about 2 months ago, but I wouldn't think that would slow something like this down, unless I missed a NIC and jumbo frames aren't enabled someplace. I'll try to verify this, as well as possibly turning off jumbo frames for testing purposes.

[loki]

Originally Posted by Slugger

It will expand media vars on the file name, not on the transcode profile name. If you want the latter, open a defect and I can probably add that quickly sometime when I return home next week.

SJQ - love this plugin to SageTV! Been using SJQ for the last two months, offloading comskip/transcoding from my underpowered sagetv server to desktop.

Also adding variables to custom commands would really be a nice additional feature,any plans for this?

# Sample Server Config 
# Run video convert on The Daily Show 
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "The Daily Show" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 9
HBCONVERT tv 2pass
} 

# Run video convert on The Colbert Show
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "The Colbert Show" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 8
HBCONVERT tv 1pass
} 

# Run video convert on Phineas and Ferb
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "Phineas and Ferb" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 7
HBCONVERT cartoon
}

# Sample Clients Config
:MAPDIR "D:\\MyVideos" "\\\\pvr01\\Videos"

COMSKIP {
:CPU LOW
:MAX 2
"C:\\dvd\\tools\\comskip.bat" "%c%" 
}

HBCONVERT {
:CPU low
:MAX 1
# where %1 %2 .... would be options passed from the server to the client
"C:\\dvd\\tools\\hbconvert.bat" "%c%" "%1" "%2" 
}

[nyplayer]

loki,
What kind of variables do you want to pass? You can pass any variable to a batch job


I currently do this

Makes a Directory with the title name.

mkdir {
:CPU BELOWNORMAL
:MAX 1
"s:\\SJQSAGE\\mkdir.bat \"%c%\" %t%"
}


I also Do this

PASS1XVID {
:CPU BELOWNORMAL
:MAX 2
"S:\\mysagelocal\\MPG2AVIHB.bat \"%c%\" c:\\sjqencode 448 800 1"
}



SHRINK {
:CPU BELOWNORMAL
:MAX 1
"C:\\SHRINK\\mediaShrink.exe \"%c%\" /inPlace /divx /cutComm /cliBitrate 1000 /onePass /horizontalScale 512 /mp4"
}

[loki]

Originally Posted by nyplayer

loki,
What kind of variables do you want to pass? You can pass any variable to a batch job


I currently do this

Makes a Directory with the title name.

mkdir {
:CPU BELOWNORMAL
:MAX 1
"s:\\SJQSAGE\\mkdir.bat \"%c%\" %t%"
}


I also Do this

PASS1XVID {
:CPU BELOWNORMAL
:MAX 2
"S:\\mysagelocal\\MPG2AVIHB.bat \"%c%\" c:\\sjqencode 448 800 1"
}



SHRINK {
:CPU BELOWNORMAL
:MAX 1
"C:\\SHRINK\\mediaShrink.exe \"%c%\" /inPlace /divx /cutComm /cliBitrate 1000 /onePass /horizontalScale 512 /mp4"
}

nyplayer


was trying to have the 'server' config do the checking logic and pass options to the called client job, kind of like how the :TRANSCODEOPTS field works. This way keep everything to a single job name in the client config.

So the following non-working sample would call HBCONVERT with two options

option 1: tv
option 2: 1pass

# Run video convert on The Colbert Show
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "The Colbert Show" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 8
HBCONVERT tv 1pass
}

From your example I would need a client job per option set?

HBCONVERT {
:CPU low
:MAX 1
"C:\\dvd\\tools\\hbconvert.bat" "%c%" 
}

HBCONVERT2PASS {
:CPU low
:MAX 1
"C:\\dvd\\tools\\hbconvert.bat" "%c%" twopass
}

HBCONVERTCARTOON {
:CPU low
:MAX 1
"C:\\dvd\\tools\\hbconvert.bat" "%c%"  cartoon
}

Gonna give your idea a try now, thanks for the help.