XBMC shutdown error [not the same as recently closed bug]

I've found one place where an error might cause a call to g_graphicsContext.Unlock() to be missed. I've added some logging to check for this and put it on http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip as usual. Can you try this, and if you get a hang see if there's a line in the log:

CApplication::Render: g_Windowing.BeginRender() returned FALSE - LOCK NOT RELEASED

Thanks,

JR

hi JR,

wow you're really good at this.. the line you were expecting to see is in fact there... i've also included some lines above it as i feel it might be helpful..

broken log:
08:30:54 T:188 M:1041518592 DEBUG: CWinEventsWin32::WndProcWindow is active
08:30:54 T:188 M:1041821696 DEBUG: CWinEventsWin32::WndProcWindow lost focus
08:30:54 T:188 M:1041018880 DEBUG: D3DERR_DEVICELOST
08:30:54 T:188 M:1040695296 NOTICE: CApplication::Render: g_Windowing.BeginRender() returned FALSE - LOCK NOT RELEASED

working log:
08:30:45 T:2468 M:1070505984 DEBUG: CWinEventsWin32::WndProcWindow is active
08:30:45 T:2468 M:1070505984 DEBUG: CWinEventsWin32::WndProcWindow gained focus
08:30:45 T:2468 M:1070407680 DEBUG: CRenderSystemDX::CreateDevice on adapter 0
08:30:45 T:2468 M:1067925504 DEBUG: CRenderSystemDX::CreateDevice - adapter 0: ati2dvag.dll, ATI Radeon HD 4200, VendorId 4098, DeviceId 38672
08:30:45 T:2468 M:1067925504 DEBUG: CRenderSystemDX::CreateDevice - texture caps: 0x0001EC45
08:30:45 T:2468 M:1067921408 DEBUG: CRenderSystemDX::CreateDevice - RENDER_CAPS_DXT
08:30:45 T:2468 M:1067921408 DEBUG: CRenderSystemDX::CreateDevice - RENDER_CAPS_NPOT
08:30:45 T:2468 M:1067921408 DEBUG: CRenderSystemDX::CreateDevice - RENDER_CAPS_DXT_NPOT


im wondering if there's something i'm doing with eventghots that's causing a problem... i'll take a look and get back to you.

http://pastebin.com/LZmncUFC

JR, one more piece of info. It looks like sometimes even when i CAN successfully shut down, the LOCK NOT RELEASED still shows up. It just happens to show up AFTER the Rss process itself has finished, thus allowing me to shut down gracefully...

hi JR,

sorry i'd like to get you a working log also so you can compare...but for some reason... now im almost always getting LOCK NOT RELEASED

the one i posted for you earlier must be a complete stroke of luck.

i will try again later tonight.

is it just me? or does this just seem like a problem on my graphics card/driver? i recently did an update to the latest set of drivers, although i've been having this problem on/off for a few months now (dating back to the camelot days)

thx

OK, I think I have some good news for you. I think I've fixed the bug. Give my new version of http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip a try and see if it fixes the hangs.

This is what I think is happening. The main thread in XBMC is calling the g_graphicsContext.Lock() function to allow it access to critical variables, then refreshing the screen, then calling g_graphicsContext.Unlock(). But if there's an error it abandons the screen refresh and fails to call g_graphicsContext.Unlock(). This means that the RSSReader hangs when it calls g_graphicsContext.Lock() to try and use the same memory.

The error that's causing the problem is the D3DERR_DEVICELOST error that you've already noticed, and as you've also noticed whether the hang happens depends on whether the D3DERR_DEVICELOST error happens before or after the RSSReader has finished. This is going to vary depending on how long the RSSReader takes to read data from the Internet, so sometimes XBMC will hang and sometimes it won't. Ironically, the error itself is harmless. It's only because of the bug in XBMC that the D3DERR_DEVICELOST error is causing XBMC to hang.

In my latest version of XBMC-Debug.exe I've left all the logging in, but I've changed the code so that if the D3DERR_DEVICELOST error occurs the code correctly calls the Unlock() function, and this should fix the problem. If this works I can strip out all the logging and build a shiny new version of Dharma with the bug fixed. There is a maintenance release, v10.1, out soon, and although in theory it's now closed to changes, my guess is that this bug is serious enough that the fix will be added to v10.1.

JR

hi JR,

thank you for your detailed explanation, i am currently in corporate drone mode, so i won't be able to try this out until later tonight.

quick question though, why is this particular error harmless? I mean just based on the log, it almost looks like xbmc is trying to control the graphics to do...something? So when it fails, how come its not a big deal?

thanks

defender013 Wrote:why is this particular error harmless? I mean just based on the log, it almost looks like xbmc is trying to control the graphics to do...something? So when it fails, how come its not a big deal?

XBMC just retries after the error, and it obviously succeeds otherwise it wouldn't work :-) I think the error happens the first time XBMC tries to render the screen, and it seems to happen only once.

JR

ah that makes so much sense...

i was wondering how i could possibly see anything on screen if rendering failed...
i will try out the fixed patch tonight

JR, just wanted to thank you again for seeing this through, i mean we're on page 5 of a thread where we are the only 2 posting ..lol.

thanks a lot for your help

hi JR!

looks like the problem may have been fixed! see the logging below...

20:56:31 T:3496 M:942567424 DEBUG: CWinEventsWin32::WndProcWindow lost focus
20:56:31 T:3496 M:942567424 DEBUG: D3DERR_DEVICELOST
20:56:31 T:3496 M:942546944 DEBUG: CApplication::Render: g_Windowing.BeginRender() returned false, calling unlock
20:56:31 T:3496 M:942542848 DEBUG: CAnnouncementManager - Announcement: ApplicationStop from xbmc
20:56:31 T:3904 M:942505984 NOTICE: CThread::staticThread: pThread->Process() finished
20:56:31 T:3904 M:942505984 NOTICE: Previous line repeats 1 times.
20:56:31 T:3904 M:942505984 NOTICE: CThread::staticThread: Calling pThread->OnExit()
20:56:31 T:3904 M:942501888 NOTICE: Previous line repeats 1 times.
20:56:31 T:3904 M:942501888 NOTICE: CThread::staticThread: pThread->OnExit() finished
20:56:31 T:3904 M:942501888 NOTICE: Previous line repeats 1 times.
20:56:31 T:3904 M:942501888 NOTICE: CThread::staticThread: Calling pThread->IsAutoDelete()
20:56:31 T:3904 M:942497792 NOTICE: Previous line repeats 1 times.
20:56:31 T:3904 M:942497792 DEBUG: Thread 3904 terminating (autodelete)
20:56:31 T:3900 M:942485504 DEBUG: Thread 3900 terminating (autodelete)
20:56:31 T:3904 M:942485504 NOTICE: CThread::staticThread: Calling _endthreadex(123)
20:56:31 T:2588 M:942592000 NOTICE: Previous line repeats 1 times.
20:56:31 T:2588 M:942592000 DEBUG: FileCurl::Close(04C2FCE4) http://feeds.feedburner.com/xbmc
20:56:31 T:2588 M:942592000 DEBUG: Got rss feed: http://feeds.feedburner.com/xbmc
20:56:31 T:2588 M:942632960 DEBUG: RSS feed encoding: UTF-8
20:56:31 T:2588 M:942628864 DEBUG: Parsed rss feed: http://feeds.feedburner.com/xbmc
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::Process: 1036: calling UpdateObserver
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: entered UpdateObserver
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: about to call getfeed
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: feed.size = 461
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: about to call g_graphicsContext.Lock
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: m_pObserver = 44343000
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: about to call OnFeedUpdate
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: about to call g_graphicsContext.Unlock
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::UpdateObserver: finished
20:56:31 T:2588 M:942624768 NOTICE: CRssReader::Process: 1036: finished


it has not failed my usual power on/power off testing. I'll now use it normally and see if anything pops up. I"ll let you know

thanks a bunch!

btw... do you think the contextLock debug messages should just be included by default? Maybe even with a argument passed in to show which thread called it? Seems like it would save a lot of work in the future if similar problems pop up again.

At last! :-)

Annoyingly I've just missed getting the fix into v10.1, but I can do a custom build of v10.1 for anyone affected by the bug.

Deciding what to log and what not to log is always a tricky issue. I think the logging in XBMC is OK as it is, apart possibly from adding some extra logging to identify which thread is which. Yes, I did have to add lots of extra logging to identify this bug, but that's only because I can't reproduce the bug on my system. Normally I'd just run XBMC in a debugger and this makes it easy to find bugs.

Anyhow, thanks again for all the effort you've put in. It's great that we've got a result :-)

JR

hi JR,

a custom build would be really nice! since i have no idea when 10.2 is going to come out...

btw, do i need to file this as a bug? or are you going to take care of that already?