SageMC and random UI hangs (EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected)

[davidjade]

I posted this to the SageMC bug topic thread but it has since started to annoy me so badly that I feel I need to put it out there for comment/suggestions. I am hoping that someone may have some suggestions on how to resolve this.

Ever since I installed SageMC I have noticed that periodically, the UI hangs and I get the spinning wait circle. I've recently turned on debug logging and I can see that I get this message repeatedly whenever that happens:

EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = xxxxx

Sometimes the hang time is greater that 35,000 but usually it is around 8-10,000. The context of these messages in the log file always seems different. It just seems random to me.

I've always assumed that this was a Sage issue in general but I have since confirmed that I only get this when using SageMC.

my stats:
Latest Sage, latest SageMC, latest Java (update 7)
headless Server 2003 P4 server (single proc, 1gb RAM)
single HD100 client connected via 1gb switch
HD-PVR connected via s-video to DirecTV (SD only for the moment)
recording directory is set to a local drive that does not spin down
2 plugins: web UI & Sage recorder XML file generator

All in all, a pretty simple setup with not a lot of tweaking.

While my server is older, sage is really the only thing running on it and it seems to have plenty of horsepower. Note that it is a single CPU core though so perhaps this is a threading issue that most people don't encounter. This hang seems completely random but it seems to happen the most when sage is first woken up by my STX-HD100 (sage, not my server - it never sleeps). I sometime notice that the network activity light on my HD100 seems to blink slower or not at all while it is hung. Sometimes it will hang repeatedly sometime it won't hang for days. Restarting sage seems to have no effect as sometime it will hang right away. I can trigger these hangs both from the HD100 and the local server Sage UI. In every instance while it is hung my server's CPU is doing nothing at the time. The java heap seems fine as does the overal memory consumption on my sever. My drives are all local and not spinning down either. Switching back to the default SageTV3.xml however makes the UI hang go away completely.

Note that I have seen in another thread that this may be related to a Java bug but I have only seen this referenced once and have not pursued getting a java hotfix to try.

If anyone wants/needs more details, I have lots of log files.

david

[MeInMaui]

You could try increasing your max Java heap size (see this post). Other than that, I don't have any ideas.

Aloha,
Mike

[davidjade]

Tried that already (to 384, 512, etc...). The UI still freezes.

I really don't want to have to switch away from SageMC but it's getting harder to deal with a UI that periodically freezes for 15-60 seconds whenever I push a button on the remote.

david

[MeInMaui]

Can you post your log file? Maybe something else will become obvious. I recall having issues like this a couple years ago, but I haven't seen them in ages. Also, how much RAM does your system have?

Aloha,
Mike

[davidjade]

My system has 1gb and does little else besides run Sage. Attached is a zipped log file. It's large but it shows a lot of hangs in a fairly short period of time. This is pretty typicaly for me unfortunately.

thanks for offering to take a look at this.

david

davidjade 2008-09-03 sagetv_0.zip

[MeInMaui]

Just for kicks and giggles, try changing your main menu to the Text style. Is it more responsive then?

Aloha,
Mike

[davidjade]

Nevermind -- I found it
Sorry, can you describe to me how I do this? I know I saw this once but for the life of me I cannot find it now.

[MeInMaui]

On your main menu, open the Options Menu and select 'Customize Screen Layout'. From the menu that pops up, select the Customize button on the first line (Menu). Cycle through the menu styles until you get to Text. You will then have to hit the options key a few times to back out of all of the popup menus.

Aloha,
Mike

Edit: Sorry, I guess I type too slow. Let me know how it goes.

[davidjade]

I'm still seeing the random UI hangs. It's usually not the main menus that hang. Its usually something like the guide or hitting the Info button on the remote, etc...

david

[davidjade]

Quick update -

Since installing the Java 1.6 update 10 release I am not experiencing the UI hangs that I was when using the Java update 7 release. From a quick look at the SageTV debug logs I also appear to be no longer having the same UI thread hang error messages that I first reported, however I am now seeing a slightly different error message in the log:

EventThread-001e40b59f61 Hang Detected - hang time = 7384

These error messages however have no apparent effect on the overall UI and are less frequent (in fact just one instance so far in my initial testing).

So it seems to me that Java update 10 has "fixed" my UI thread hang errors for the time being.

So far update 10 is working well for me in all regards, although I may have a little more playback studder on my HD100 than before but who knows what is causing that...

david

[bstowers]

I have been having this exact issue on a SageClient system. I updated to Java 1.6 release 10, but it made no difference at all. Like the original poster, this only happens with SageMC; if I use the original UI, it never happens. Also, I've never had it happen on my main Sage system, only my SageClient.

Example debug log:

Sun 11/16 10:02:43.545 Found 1 partials using 153305088 bytes
Sun 11/16 10:02:43.695 VideoDiskspaceReqProportion: 0.35968552688122235
Sun 11/16 10:02:43.696 VideoDiskspaceFreeProportion: 0.2805051547461191
Sun 11/16 10:02:43.696 Disk Space Bar Update complete
Sun 11/16 10:03:00.299 VF.submitJob(VFJob[TimeAdjust r=0.0 t=150000 file=null ifn=null])
Sun 11/16 10:03:00.300 VF processing job VFJob[TimeAdjust r=0.0 t=150000 file=null ifn=null] nPlayin=true
Sun 11/16 10:03:00.301 VF processing on UI Thread VFJob[TimeAdjust r=0.0 t=150000 file=null ifn=null]
Sun 11/16 10:03:00.301 VideoFrame.timeSelected(Sun 11/16 4:01:23.618, true) currFile=MediaFile[id=3669113 A[3590082,3589919,"Saturday Night Live",10590@1116.02:29,93] host=TheTV encodedBy=Hauppauge HD PVR Capture Device Great-H.264 format=MPEG2-TS 0:00:00 20000 kbps [#0 Video[H.264 1280x720 progressive]#1 Audio[AC3 48000 Hz 2 channels 384 kbps MAIN idx=1 id=1100]] \\thetv\video2\SaturdayNightLive-3590082-0.ts, Seg0[Sun 11/16 2:29:00.003-Sun 11/16 4:02:00.000]]
Sun 11/16 10:03:00.302 VideoFrame.timeSelected2(Sun 11/16 4:01:23.618, true) currFile=MediaFile[id=3669113 A[3590082,3589919,"Saturday Night Live",10590@1116.02:29,93] host=TheTV encodedBy=Hauppauge HD PVR Capture Device Great-H.264 format=MPEG2-TS 0:00:00 20000 kbps [#0 Video[H.264 1280x720 progressive]#1 Audio[AC3 48000 Hz 2 channels 384 kbps MAIN idx=1 id=1100]] \\thetv\video2\SaturdayNightLive-3590082-0.ts, Seg0[Sun 11/16 2:29:00.003-Sun 11/16 4:02:00.000]] realDur=5580224
Sun 11/16 10:03:00.302 About to perform media time selection for 5543841
Sun 11/16 10:03:00.383 VF processing job null nPlayin=true
Sun 11/16 10:03:00.383 isRec=false rd=5580224 base=5543841
Sun 11/16 10:03:00.383 VF thread is now waiting for 0:00:36.133
Sun 11/16 10:03:02.930 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 750
Sun 11/16 10:03:03.680 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 1500
Sun 11/16 10:03:04.430 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 2250
Sun 11/16 10:03:05.180 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 3000
Sun 11/16 10:03:05.930 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 3750
Sun 11/16 10:03:06.680 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 4500
Sun 11/16 10:03:07.430 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 5250
Sun 11/16 10:03:08.180 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 6000
Sun 11/16 10:03:08.930 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 6750
Sun 11/16 10:03:09.680 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 7500
Sun 11/16 10:03:10.430 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 8250
Sun 11/16 10:03:11.180 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 9000
Sun 11/16 10:03:11.930 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 9750
Sun 11/16 10:03:12.680 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 10500
Sun 11/16 10:03:13.430 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 11250
Sun 11/16 10:03:14.180 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 12000
Sun 11/16 10:03:14.930 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 12750
Sun 11/16 10:03:15.680 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 13500
Sun 11/16 10:03:16.430 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 14250
Sun 11/16 10:03:17.180 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 15000
Sun 11/16 10:03:17.931 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 15751
Sun 11/16 10:03:18.681 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 16501
Sun 11/16 10:03:19.431 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 17251
Sun 11/16 10:03:20.181 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 18001
Sun 11/16 10:03:20.931 EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 18751
Sun 11/16 10:03:21.259 VF.submitJob(VFJob[TimeAdjust r=0.0 t=10000 file=null ifn=null])
Sun 11/16 10:03:21.260 VF processing job VFJob[TimeAdjust r=0.0 t=10000 file=null ifn=null] nPlayin=true
Sun 11/16 10:03:21.272 VF.submitJob(VFJob[TimeAdjust r=0.0 t=10000 file=null ifn=null])
Sun 11/16 10:03:21.342 CLICK
Sun 11/16 10:03:21.372 CLICK
Sun 11/16 10:03:21.405 processOptionsMenu optionsMenu=default:PRQST-1206888|OptionsMenu:OSDOptions
Sun 11/16 10:03:21.505 processOptionsMenu optionsMenu=default:PRQST-1205117|OptionsMenu:EditAR

It happens about 50% of the time when I try to do something like skip forward or back, or display the info banner. It will just stop responding until that hang timeout finishes, and then it will work fine for a short time.

Anyone have any ideas? It's really driving me crazy.

[KJake]

I had the same problem. It ended up being a side-effect of a different issue. I'm not sure that you have the same underlying issue, but if you read my post below, it may help you troubleshoot the issue with SageTV support (or on your own).

http://forums.sagetv.com/forums/show...128#post260128

[bstowers]

Originally Posted by KJake

I had the same problem. It ended up being a side-effect of a different issue. I'm not sure that you have the same underlying issue, but if you read my post below, it may help you troubleshoot the issue with SageTV support (or on your own).

http://forums.sagetv.com/forums/show...128#post260128

Offline files are not enabled at all on the PC. Thanks anyway.

[KJake]

Originally Posted by bstowers

Offline files are not enabled at all on the PC. Thanks anyway.

Actually, offline files wasn't exactly my issue, it was Sage looking for files that it thought should be in the library. Anyways, I would suggest following the bulletpoints on that page and opening a case with SageTV support. They helped me get to the bottom of my issue.

[bstowers]

Originally Posted by KJake

Actually, offline files wasn't exactly my issue, it was Sage looking for files that it thought should be in the library. Anyways, I would suggest following the bulletpoints on that page and opening a case with SageTV support. They helped me get to the bottom of my issue.

Well, I really don't think Frey is going to want to try to help with this since it only happens when I use SageMC, like I mentioned in my first post. Has anyone had any luck getting them to look at problems that only occur when you use an add on?

I mean, if i follow bullet point #1:

Switch to the default STV (no imports).

Then technically my problem is fixed, but I can't use that default interface.

[KJake]

A couple suggestions:
* Your dynamic menu xml is causing a NPE looking for an icon, open your xml file and remove any references to icons that don't exist on your system (or place the icons in the folder it is looking for).

* If you use the diskbar try turning it off.
* If you use the RSS ticker try turning it off (or make sure it is set to off).
* Try switching to the default SageMC theme.

And I would try those things one at a time, in that order.

If none of that helps, please do try my suggestion anyways and post the Zip file here instead of sending it off to Sage support. I didn't really read before that this was a SageMC only issue. And, while this probably isn't a good thing, just setting ui/thread_hang_delay_to_dump=2000 in your Sage.properties will make Sage give up quicker and you won't need to wait for 46545+

[KJake]

Originally Posted by davidjade

Tried that already (to 384, 512, etc...). The UI still freezes.

Uh, I got confused that there are two separate things in this thread.....

[bstowers]

Originally Posted by KJake

A couple suggestions:
* Your dynamic menu xml is causing a NPE looking for an icon, open your xml file and remove any references to icons that don't exist on your system (or place the icons in the folder it is looking for).

I reviewed the file, but all the icon files appear to be there. Not sure what to make of that since I did a fresh install as one of my attempts to fix this.

* If you use the diskbar try turning it off.

Done, didn't seem to affect the problem.

* If you use the RSS ticker try turning it off (or make sure it is set to off).

Checked and found that it was already disabled.

* Try switching to the default SageMC theme.

Done, didn't seem to affect the problem.

And I would try those things one at a time, in that order.

If none of that helps, please do try my suggestion anyways and post the Zip file here instead of sending it off to Sage support.

Attached.

And, while this probably isn't a good thing, just setting ui/thread_hang_delay_to_dump=2000 in your Sage.properties will make Sage give up quicker and you won't need to wait for 46545+

I checked my SageClient.properties, and this value was already set to 2000.

[KJake]

Sorry about that, I was going based off things in the log posted earlier in the thread, which wasn't yours...so I said some things that may have not made sense...and I'm also nott that familiar with the Client software, so I may continue to say things that don't make sense.

Could you attach or PM your SageClient.properties too?

Does the path C:\Program Files\SageTV\SageTV\GeneratedThumbnails exist and are there recently created files in it?

Try setting Detailed Setup > Customize > Regularly rescan import directories to No

The debug log doesn't really give me any hints, but I'm not a Sage developer either, so I'm just guessing here...but this still feels filesystem related. Does this only ever happen in the video playback screen? Could you explain your Sage setup to me a little (client/server stats, storage situation, network setup)?

-KJake

[bstowers]

Originally Posted by KJake

Sorry about that, I was going based off things in the log posted earlier in the thread, which wasn't yours...so I said some things that may have not made sense...and I'm also nott that familiar with the Client software, so I may continue to say things that don't make sense.

Hahah, not to worry.

Could you attach or PM your SageClient.properties too?

Attached.

Does the path C:\Program Files\SageTV\SageTV\GeneratedThumbnails exist and are there recently created files in it?

Yes, and yes, in that order. As recently as tonight.

Try setting Detailed Setup > Customize > Regularly rescan import directories to No

It was set that way already.

The debug log doesn't really give me any hints, but I'm not a Sage developer either, so I'm just guessing here...but this still feels filesystem related. Does this only ever happen in the video playback screen?

Yes, it only happens during playback, but I really don't do anything else with it (that is, don't play music, etc, just recorded TV). Typically, it'll go something like this: I'll be watching something and come up to a commercial. I'll hit the large skip forward button, which it will do, and then I will hit the small skip forward but that does not happen until the thing times out, and then all the button mashes will catch up at once. I _think_ the spinning cursor actually happens after the first big skip, not when I do the small skip. This is not the only scenario that causes it, though. Typically, pulling up the info banner on a playing show will most always do it. Another curious thing is that it seems that once I'm doing a certain action, I can keep doing it. That is, if I'm doing several small skips forward, I can do quite a lot of them without the hang, but when I throw in a different operation to that like any other type of skip, that's when I'll get nailed with it. I've fast forwarded through entire 60 minute shows using the big skip without the spinning cursor, but only if I use the big skip exclusively.

Could you explain your Sage setup to me a little (client/server stats, storage situation, network setup)?

The server is a PC in my living room that is used as our primary playback and record system. It is not being used for playback typically when the client is being used. I've had it online for about a month now, but the data file is probably a few years old (upgraded from old systems). It's a Core 2 Quad Q6600 (2.4 GHz) with 3 gig of ram running Vista Home Premium with SP1. It has 2 drives, 500 MB and 1 TB and currently has about 900 MB of that free. It uses a Hauppage HD-PVR for capture from a DirecTV box. So far, it has been pretty solid since I put it into service. The server runs Sage from a "standard" user account, not an admin account. Well, the UI portion of Sage. It uses the Sage service to record, which is running under an admin account.


The client is an AMD Phenom 8650 triple core (2.3 GHz) with 2 gig of ram running Windows XP Pro SP3. I built this one about 2 months back and have had not a bit of trouble from it besides this one issue. I use it for a few other things, notably VMWare is installed for software testing, but is not being used (or running at all) when I have this problem.

They are both networked via Cat6 into a LinkSys gigabit / wireless N router. I have noticed that the server usually is only connected at 100 Mbps, not 1 Gbps, but I haven't tracked down why yet (not relishing going into the attic to inspect the wire I had ran between rooms). Doubt that has anything to do with this. The client and the server both access the storage drives via UNC path names. The UNC shares are set up to give full access control to everything that connects to them.

I had the same server / client setup with some older machines, and I never saw this behavior then. The client was way underpowered to play the HD stuff, though, which is why i rebuilt it. The playback was just very choppy on that machine, but it would skip around just fine and never had this hang issue at all.


Thanks for the effort on this, even if we don't get it figured out. I really appreciate it.