[defender013]

hi JR,

so even the new log shows exactly the same thing..


19:40:39 T:3836 M:1211912192 NOTICE: CThread:taticThread: Calling _endthreadex(123)
19:40:39 T:2856 M:1211912192 NOTICE: Saving settings
19:40:39 T:2856 M:1211465728 NOTICE: stop all
19:40:39 T:2856 M:1211465728 NOTICE: CApplication::Stop: About to call StopServices()
19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::NetworkMessage - Signaling network services to stop
19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - Stopping Event Server, bWait = 0
19:40:39 T:2856 M:1211465728 NOTICE: ES: Stopping event server
19:40:39 T:2856 M:1211465728 NOTICE: CEventServer::StopServer: about to call StopThread(0)
19:40:39 T:2856 M:1211465728 NOTICE: CEventServer::StopServer: StopThread(0) returned
19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - Event Server stopped, bWait = 0
19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - Stopping JSONRPC Server, bWait = 0
19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::StopServices - JSONRPC Server stopped, bWait = 0
19:40:39 T:2856 M:1211465728 NOTICE: CNetwork::NetworkMessage - Waiting for network services to stop
19:40:39 T:2856 M:1211465728 NOTICE: Webserver: Stopping...
19:40:39 T:2856 M:1211637760 NOTICE: WebServer: Stopped the webserver
19:40:39 T:2856 M:1211641856 NOTICE: Webserver: Stopped...
19:40:39 T:2856 M:1211641856 NOTICE: CThread::StopThread: about to call WaitForThreadExit(INFINITE)
19:40:39 T:2856 M:1211641856 NOTICE: CThread::WaitForThreadExit: about to call WaitForSingleObject(1028, -1)
19:40:40 T:2092 M:1213403136 NOTICE: ES: UDP Event server stopped
19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: pThread->Process() finished
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Run: About to call Cleanup
19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: Calling pThread->OnExit()
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: pThread->OnExit() finished
19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete()
19:40:40 T:2852 M:1213403136 DEBUG: Thread 2852 terminating
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
19:40:40 T:2852 M:1213403136 NOTICE: CThread:taticThread: Calling _endthreadex(123)
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: About to lock
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: Lock finished
19:40:40 T:2092 M:1213394944 NOTICE: CEventServer::Cleanup: About to start client loop
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Cleanup: Client loop finished
19:40:40 T:2092 M:1213403136 NOTICE: CEventServer::Run: Cleanup returned
19:40:40 T:2092 M:1213399040 NOTICE: CEventServer:rocess: Finished
19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: pThread->Process() finished
19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: Calling pThread->OnExit()
19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: pThread->OnExit() finished
19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete()
19:40:40 T:2092 M:1213399040 DEBUG: Thread 2092 terminating
19:40:40 T:2092 M:1213399040 NOTICE: CThread:taticThread: Calling _endthreadex(123)


i'm pretty puzzled.. looks like this is the same thing

i'll try to capture more logs and send them your way...

[jhsrennie]

Aha! Now we're making progress, even though it may not look like it to you!

When XBMC wants to stop a thread it sends that thread a stop request, then waits for the thread to stop using the Windows function "WaitForSingleObject". If I look at my log I can see:

Code:

(I've left these three lines in as a reference point)
NOTICE: Webserver: Stopping...
NOTICE: WebServer: Stopped the webserver
NOTICE: Webserver: Stopped...
NOTICE: CThread::StopThread: about to call WaitForThreadExit(INFINITE)
NOTICE: CThread::WaitForThreadExit: about to call WaitForSingleObject(1368, -1)
NOTICE: CThread::WaitForThreadExit: WaitForSingleObject(1368, -1) != WAIT_TIMEOUT

but in your log:

Code:

NOTICE: Webserver: Stopping...
NOTICE: WebServer: Stopped the webserver
NOTICE: Webserver: Stopped...
NOTICE: CThread::StopThread: about to call WaitForThreadExit(INFINITE)
NOTICE: CThread::WaitForThreadExit: about to call WaitForSingleObject(1028, -1)

the line

NOTICE: CThread::WaitForThreadExit: WaitForSingleObject(1028, -1) != WAIT_TIMEOUT

is missing. This means that XBMC is waiting for a thread to finish and it never does. Hence the hang.

The main problem in working out what's going wrong is that XBMC is multi-threaded, which means that different bits of it run simultaneously and write to the log file simultaneously, so the order that lines appear in the log file isn't always the same, and it's not obvious which thread produced which log entry. Nevertheless, it's clear from your log that the call to WaitForSingleObject(1028, -1) never returned.

The next step is to work out which thread is hanging. I might be able to do that without troubling you for yet more logging. Watch this space!!

JR

[jhsrennie]

Bingo! It's the RSS reader!

I've added some extra logging info around the RSS code. Please would you try it and see what your log shows when you get a hang. As usual it's on http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip.

Can you pop the whole log on pastebin.com - because of all that threading log entries can be widely scattered through the log so it's not just the last few entries that I need.

Anyhow, when I run XBMC I get:

Code:

NOTICE: Webserver: Stopping...
NOTICE: WebServer: Stopped the webserver
NOTICE: Webserver: Stopped...
NOTICE: CThread::StopThread: 1252 - CRssReader: about to call WaitForThreadExit(INFINITE)
NOTICE: CThread::WaitForThreadExit: 1252 - CRssReader: about to call WaitForSingleObject(1252, -1)
NOTICE: CThread::WaitForThreadExit: 1252 - CRssReader: WaitForSingleObject(1252, -1) != WAIT_TIMEOUT
NOTICE: CThread::StopThread: 1252 - CRssReader: WaitForThreadExit(INFINITE) returned

I confidently predict that if you get a hang the last two lines of the above will be missing.

Later: I've just updated XBMC-Debug.exe to add a few more lines of logging. If you sdownloaded it before 11:00 GMT please grab the updated copy. The updated copy has the build date set to 06/06/11 in the system info.

The log entries should now look like:

Code:

Webserver: Stopping...
WebServer: Stopped the webserver
Webserver: Stopped...
CRssManager::Stop: no. readers = 1
CRssManager::Stop: Deleting reader 1
CRssReader::~CRssReader: testing handle
CRssReader::~CRssReader: thread handle wait succeeded
CRssReader::~CRssReader: About to call StopThread
CThread::StopThread: 1332 - CRssReaderThread: about to call WaitForThreadExit(INFINITE)
CThread::WaitForThreadExit: 1332 - CRssReaderThread: about to call WaitForSingleObject(1332, -1)
CThread::WaitForThreadExit: 1332 - CRssReaderThread: WaitForSingleObject(1332, -1) != WAIT_TIMEOUT
CThread::StopThread: 1332 - CRssReaderThread: WaitForThreadExit(INFINITE) returned
CRssReader::~CRssReader: StopThread returned

Also, somewhere higher up in the log should be one or more lines looking like:

NOTICE: CRssReader:rocess: finished

and I'm particularly interested to check that all these lines are present in the log somewhere as i suspect the CRssReader:rocess() function may be hanging.

Thanks,

JR

[defender013]

hi JR,

will do, i will try this out tonight.

this is odd though, i do remember reading the RSS reader was a problem, and i also remember this was suppose to have been fixed late last yr, hence my thread title of [not the same as recently closed bug].

i will check this out tonight and get back to you

[defender013]

hi JR,

indeed you are correct,

here is the pastbin link
http://pastebin.com/VsbqrbJi

and i think the following here is what you are most interested in..

22:10:39 T:2768 M:906182656 NOTICE: Webserver: Stopping...
22:10:39 T:2768 M:906358784 NOTICE: WebServer: Stopped the webserver
22:10:39 T:2768 M:906358784 NOTICE: Webserver: Stopped...
22:10:39 T:2768 M:906358784 NOTICE: CRssManager::Stop: no. readers = 1
22:10:39 T:2768 M:906358784 NOTICE: CRssManager::Stop: Deleting reader 1
22:10:39 T:2768 M:906358784 NOTICE: CRssReader::~CRssReader: testing handle
22:10:40 T:3724 M:908488704 NOTICE: ES: UDP Event server stopped
22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: pThread->Process() finished
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Run: About to call Cleanup
22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: Calling pThread->OnExit()
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: About to call m_pSocket->Close()
22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: pThread->OnExit() finished
22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete()
22:10:40 T:3600 M:908488704 DEBUG: Thread 3600 terminating
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: m_pSocket->Close() finished
22:10:40 T:3600 M:908488704 NOTICE: CThread:taticThread: Calling _endthreadex(123)
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: About to lock
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: Lock finished
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Cleanup: About to start client loop
22:10:40 T:3724 M:908484608 NOTICE: CEventServer::Cleanup: Client loop finished
22:10:40 T:3724 M:908488704 NOTICE: CEventServer::Run: Cleanup returned
22:10:40 T:3724 M:908484608 NOTICE: CEventServer:rocess: Finished
22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: pThread->Process() finished
22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: Calling pThread->OnExit()
22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: pThread->OnExit() finished
22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: Calling pThread->IsAutoDelete()
22:10:40 T:3724 M:908484608 DEBUG: Thread 3724 terminating
22:10:40 T:3724 M:908484608 NOTICE: CThread:taticThread: Calling _endthreadex(123)
22:10:40 T:2768 M:908550144 NOTICE: CRssReader::~CRssReader: thread handle wait failed
22:10:40 T:2768 M:908550144 NOTICE: CRssReader::~CRssReader: About to call StopThread
22:10:40 T:2768 M:908550144 NOTICE: CThread::StopThread: 1012 - CRssReaderThread: about to call WaitForThreadExit(INFINITE)
22:10:40 T:2768 M:908546048 NOTICE: CThread::WaitForThreadExit: 1012 - CRssReaderThread: about to call WaitForSingleObject(1012, -1)

CRssReader handle wait failed...

just out of curiosity, how did you know it was the RSS? i mean you didnt have any actual failure logs pointing directly to it, how did you find out?

[defender013]

i forgot to mention,

you are also right, the CRss process did not finish, i didn't see such a line in the log...

how did you figure this one out?? was there something obviously wrong in the code?

[jhsrennie]

how did you figure this one out?? was there something obviously wrong in the code?

Hours and hours of work! :-)

I found every place in the source code where a new thread was created and I modified the code to add a name to the thread object so I could tell which thread was which. Then I ran it on my PC, which doesn't hang, compared my log to yours and spotted a pattern suggesting it was the RSSReader. Your log then proved it.

There wasn't anything wrong with the code, and in fact it seems to be hanging in a completely unexpected bit of the code. The RSSReader is successfully reading the RSS feed data, but appears to be hanging when it attempts to save the data to internal storage. To try and confirm this I've made another new version of http://swarchive.ratsauce.co.uk/xbmc/xbmc-debug.zip to test. The key log entries for this are (from my system):

Code:

NOTICE: CRssReader::Process: 1304: calling UpdateObserver
NOTICE: CRssReader::UpdateObserver: entered UpdateObserver
NOTICE: CRssReader::UpdateObserver: about to call getfeed
NOTICE: CRssReader::UpdateObserver: feed.size = 461
NOTICE: CRssReader::UpdateObserver: about to call g_graphicsContext.Lock
NOTICE: CRssReader::UpdateObserver: m_pObserver = 95223408
NOTICE: CRssReader::UpdateObserver: about to call OnFeedUpdate
NOTICE: CRssReader::UpdateObserver: about to call g_graphicsContext.Unlock
NOTICE: CRssReader::UpdateObserver: finished

If I'm right, you should find that if there's a hang, some of the above lines will be missing. I have no idea where it will be hanging because I can't see any obvious reason why anything in the UpdateObserver() function should hang, so it will be very interesting to see what your log shows.

JR

[defender013]

hi JR,

so it looks like CRss reader is not getting a graphics context lock?

23:43:07 T:1708 M:927412224 NOTICE: CRssReader:rocess: 1028: calling UpdateObserver
23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: entered UpdateObserver
23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: about to call getfeed
23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: feed.size = 461
23:43:07 T:1708 M:927412224 NOTICE: CRssReader::UpdateObserver: about to call g_graphicsContext.Lock

this graphics context lock i think is the last thing being called for the CRssReader thread.

could you be something related to my graphics driver or OS? just wondering if this in anyway would explain why aero on vista/7 is having a problem also

the full log is here...

http://pastebin.com/Hzzvug2Q

[defender013]

hi JR,

one more question..what exactly does this graphicContext.lock do?

i just did a quick search and saw it mentioned back in 2009 in regards to external players...

in my case, when xbmc freezes on shutdown, the entire system is pretty much screwed, mainly because the display freezes, and there is very little i can do (since i cant see anything else). I always suspected it might be some graphics related thing since I use an external player (and im always jumping in and out of focus).

but for these logs, i never even start anything, so i don't really understand this problem is coming from...

actually..do you think there is any chance this is happening because my external player never released a context lock (im going on really old forum posts here..)
i should mention that my xbmc box rarely gets rebooted, it is almost always in s3 sleep. I'll try rebooting the machine tomorrow and see if i can still get similar failures without ever calling the external player

thanks

[jhsrennie]

Ah, all that work and we're not much further forward.

The g_graphicsContext.Lock() function is used to stop more than one thread modifying critical variables at the same time. When a thread needs to modify anything in these critical variables it calls g_graphicsContext.Lock(), and it's guaranteed exclusive access to the data until it calls g_graphicsContext.Unlock(). As soon as a thread has called g_graphicsContext.Lock() any other thread that calls g_graphicsContext.Lock() will freeze until the first thread calls g_graphicsContext.Unlock().

So what's happening is that some other thread is calling g_graphicsContext.Lock() but then not calling g_graphicsContext.Unlock(). That means that the RSSReader calls g_graphicsContext.Lock() and freezes waiting for the other thread.

So it isn't a problem in the RSSReader after all. It's a problem in some other thread.

JR

[jhsrennie]

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

[defender013]

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...

[defender013]

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

[jhsrennie]

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

[defender013]

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