Threading Race Condition

fredzyda · May 8, 2012, 12:37am

I have the following problem:

If I enable multithreaded rendering in Windows under Panda 1.8.0, I get what appears to be a race condition in debug mode. It looks like a mutex that is acquired during a call to GraphicsEngine::make_buffer on the main thread and a lock inside of GeomVertexDataPipelineReader::check_array_readers are somehow causing the app to hang forever. It is a pretty consistent bug in that it happens every time I run and switching from Cull/Draw to /Draw causes the check_array_readers call to move around, but it still always hangs inside of the same two calls. Posted below are the relevant stack traces for the two threads:

 	ntdll.dll!775ef8b1() 	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
 	ntdll.dll!775ef8b1() 	
 	ntdll.dll!77608df4() 	
 	ntdll.dll!77608cd8() 	
 	libp3dtool_d.dll!MutexWin32Impl::acquire()  Line 34	C++
 	libpanda_d.dll!MutexDirect::acquire()  Line 73	C++
 	libpanda_d.dll!LightReMutexDirect::elevate_lock()  Line 85	C++
 	libpanda_d.dll!LightReMutexHolder::LightReMutexHolder(const LightReMutex & mutex={...})  Line 27	C++
 	libpanda_d.dll!GraphicsEngine::WindowRenderer::add_window(ov_set<PointerTo<GraphicsOutput>,IndirectLess<GraphicsOutput> > & wlist={...}, GraphicsOutput * window=0x0cf96a2c)  Line 2426 + 0x11 bytes	C++
 	libpanda_d.dll!GraphicsEngine::do_add_window(GraphicsOutput * window=0x0cf96a2c, const GraphicsThreadingModel & threading_model={...})  Line 1991	C++
 	libpanda_d.dll!GraphicsEngine::make_output(GraphicsPipe * pipe=0x037b642c, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & name="InsetWindowBuffer", int sort=0, const FrameBufferProperties & fb_prop={...}, const WindowProperties & win_prop={...}, int flags=2052, GraphicsStateGuardian * gsg=0x037bb61c, GraphicsOutput * host=0x037b8304)  Line 418	C++
>	libpanda_d.dll!GraphicsEngine::make_buffer(GraphicsOutput * host=0x037b8304, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & name="InsetWindowBuffer", int sort=0, int x_size=128, int y_size=128)  Line 148 + 0x8d bytes	C++

 	ntdll.dll!775ef8b1() 	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
 	ntdll.dll!775ef8b1() 	
 	KernelBase.dll!752e0a91() 	
 	libpanda_d.dll!ConditionVarWin32Impl::wait()  Line 48 + 0xf bytes	C++
 	libpanda_d.dll!ConditionVarDirect::wait()  Line 105	C++
 	libpanda_d.dll!CopyOnWritePointer::get_read_pointer()  Line 51	C++
 	libpanda_d.dll!CopyOnWritePointerTo<GeomVertexArrayData>::get_read_pointer()  Line 285 + 0xc bytes	C++
 	libpanda_d.dll!GeomVertexDataPipelineReader::make_array_readers()  Line 2394 + 0x13 bytes	C++
>	libpanda_d.dll!GeomVertexDataPipelineReader::check_array_readers()  Line 720	C++
 	libpanda_d.dll!Geom::draw(GraphicsStateGuardianBase * gsg=0x037bb61c, const GeomMunger * munger=0x0faa174c, const GeomVertexData * vertex_data=0x0fbe2a00, bool force=false, Thread * current_thread=0x037ba274)  Line 1219	C++
 	libpanda_d.dll!CullableObject::draw_inline(GraphicsStateGuardianBase * gsg=0x037bb61c, bool force=false, Thread * current_thread=0x037ba274)  Line 264	C++
 	libpanda_d.dll!CullableObject::draw(GraphicsStateGuardianBase * gsg=0x037bb61c, bool force=false, Thread * current_thread=0x037ba274)  Line 156	C++
 	libpanda_d.dll!CullHandler::draw(CullableObject * object=0x058090c4, GraphicsStateGuardianBase * gsg=0x037bb61c, bool force=false, Thread * current_thread=0x037ba274)  Line 27	C++
 	libpanda_d.dll!CullBinStateSorted::draw(bool force=false, Thread * current_thread=0x037ba274)  Line 90 + 0x19 bytes	C++
 	libpanda_d.dll!CullResult::draw(Thread * current_thread=0x037ba274)  Line 287	C++
 	libpanda_d.dll!GraphicsEngine::do_draw(CullResult * cull_result=0x0c65a274, SceneSetup * scene_setup=0x0c65a1e4, GraphicsOutput * win=0x037b8304, DisplayRegion * dr=0x0ab5319c, Thread * current_thread=0x037ba274)  Line 1951	C++
 	libpanda_d.dll!GraphicsEngine::draw_bins(GraphicsOutput * win=0x037b8304, DisplayRegion * dr=0x0ab5319c, Thread * current_thread=0x037ba274)  Line 1583	C++
 	libpanda_d.dll!GraphicsEngine::draw_bins(const ov_set<PointerTo<GraphicsOutput>,IndirectLess<GraphicsOutput> > & wlist={...}, Thread * current_thread=0x037ba274)  Line 1536	C++
 	libpanda_d.dll!GraphicsEngine::WindowRenderer::do_frame(GraphicsEngine * engine=0x037b6d4c, Thread * current_thread=0x037ba274)  Line 2523	C++
 	libpanda_d.dll!GraphicsEngine::RenderThread::thread_main()  Line 2712	C++

I appear to get this bug in both debug and release mode, but it is easier to get a clear stack trace in debug, for obvious reasons. Can anyone help? Thanks in advance!

drwr · May 8, 2012, 8:00pm

Hmm, the first way I would debug this would be to compile Panda with DEBUG_THREADS defined, which will (among other things) add code to specifically check for deadlock at every lock operation. If it find a deadlock, it’ll report the particular mutexes that are involved.

David

fredzyda · June 4, 2012, 10:53pm

It took me a while to get time to make a panda build, but I finally confirmed a deadlock. It seems to be in a different place than before, which is annoying, but perhaps I was getting lucky before and some other code change exposed this potential for deadlock as well. I got the following debug output:

****************************************************************
*****                 Deadlock detected!                   *****
****************************************************************

:thread(error): Thread TaskManager_AsynchronousLoader_0 attempted to lock ReMutex Pipeline 047E339C which is held by MainThread Main
:thread(error): MainThread Main is blocked waiting on CyclerMutex GeomNode::CData which is held by Thread TaskManager_AsynchronousLoader_0
:thread(error): Deadlock!

That seems bad. Here is the call stack for the loader thread:

 	libp3dtoolconfig_d.dll!Notify::assert_failure(const char * expression=0x01827e08, int line=205, const char * source_file=0x01827dc8)  Line 439 + 0x17 bytes	C++
 	libpanda_d.dll!MutexDebug::do_acquire(Thread * current_thread=0x05e34e44)  Line 206	C++
 	libpanda_d.dll!MutexDebug::acquire(Thread * current_thread=0x05e34e44)  Line 57	C++
 	libpanda_d.dll!LightReMutexHolder::LightReMutexHolder(const LightReMutex & mutex={...})  Line 27	C++
 	libpanda_d.dll!Pipeline::add_cycler(PipelineCyclerTrueImpl * cycler=0x1317daec)  Line 270 + 0xf bytes	C++
 	libpanda_d.dll!PipelineCyclerTrueImpl::PipelineCyclerTrueImpl(const PipelineCyclerTrueImpl & copy={...})  Line 80	C++
 	libpanda_d.dll!PipelineCycler<ClockObject::CData>::PipelineCycler<ClockObject::CData>(const PipelineCycler<ClockObject::CData> & copy={...})  Line 41 + 0x32 bytes	C++
 	libpanda_d.dll!Geom::Geom(const Geom & copy={...})  Line 72 + 0x65 bytes	C++
 	libpanda_d.dll!Geom::make_copy()  Line 119 + 0x29 bytes	C++
 	libpanda_d.dll!GeomTransformer::premunge_geom(const Geom * geom=0x1317e190, GeomMunger * munger=0x135d285c)  Line 1233 + 0x18 bytes	C++
 	libpanda_d.dll!GeomNode::do_premunge(GraphicsStateGuardianBase * gsg=0x048a8f14, const RenderState * node_state=0x0caab8d0, GeomTransformer & transformer={...})  Line 952 + 0x1e bytes	C++
 	libpanda_d.dll!SceneGraphReducer::r_premunge(PandaNode * node=0x15fbdffc, const RenderState * state=0x0cd6e3fc)  Line 1041	C++
 	libpanda_d.dll!SceneGraphReducer::r_premunge(PandaNode * node=0x15fb01cc, const RenderState * state=0x0caa4678)  Line 1045	C++
 	libpanda_d.dll!SceneGraphReducer::r_premunge(PandaNode * node=0x15faf4cc, const RenderState * state=0x00c8ef84)  Line 1045	C++
 	libpanda_d.dll!SceneGraphReducer::premunge(PandaNode * root=0x15faf4cc, const RenderState * initial_state=0x00c8ef84)  Line 220	C++
>	libpanda_d.dll!Loader::try_load_file(const Filename & pathname={...}, const LoaderOptions & options={...}, LoaderFileType * requested_type=0x047e49c4)  Line 300 + 0x42 bytes	C++
 	libpanda_d.dll!Loader::load_file(const Filename & filename={...}, const LoaderOptions & options={...})  Line 239 + 0x21 bytes	C++
 	libpanda_d.dll!Loader::load_sync(const Filename & filename={...}, const LoaderOptions & options={...})  Line 196 + 0x14 bytes	C++
 	libpanda_d.dll!ModelPool::ns_load_model(const Filename & filename={...}, const LoaderOptions & options={...})  Line 75 + 0x14 bytes	C++
 	libpanda_d.dll!ModelPool::load_model(const Filename & filename={...}, const LoaderOptions & options={...})  Line 54	C++
 	libpanda_d.dll!Loader::try_load_file(const Filename & pathname={...}, const LoaderOptions & options={...}, LoaderFileType * requested_type=0x047e49c4)  Line 274 + 0xd bytes	C++
 	libpanda_d.dll!Loader::load_file(const Filename & filename={...}, const LoaderOptions & options={...})  Line 239 + 0x21 bytes	C++
 	libpanda_d.dll!Loader::load_sync(const Filename & filename={...}, const LoaderOptions & options={...})  Line 196 + 0x14 bytes	C++
 	libpanda_d.dll!ModelLoadRequest::do_task()  Line 51 + 0x2c bytes	C++
 	libpanda_d.dll!AsyncTask::unlock_and_do_task()  Line 455 + 0xd bytes	C++
 	libpanda_d.dll!AsyncTaskChain::service_one_task(AsyncTaskChain::AsyncTaskChainThread * thread=0x05e34e44)  Line 770 + 0xf bytes	C++
 	libpanda_d.dll!AsyncTaskChain::AsyncTaskChainThread::thread_main()  Line 1556	C++
 	libpanda_d.dll!ThreadWin32Impl::root_func(void * data=0x05e34ea0)  Line 178	C++

And here’s the stack for the main thread that’s also trying to lock:

 	ntdll.dll!775ef8b1() 	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
 	ntdll.dll!775ef8b1() 	
 	KernelBase.dll!752e0a91() 	
 	msvcp90d.dll!std::_Lockit::~_Lockit()  Line 70 + 0x14 bytes	C++
>	libpanda_d.dll!std::_Iterator_base::~_Iterator_base()  Line 162 + 0x10 bytes	C++
 	libpanda_d.dll!std::_Iterator_with_base<std::bidirectional_iterator_tag,CharacterVertexSlider *,int,CharacterVertexSlider * const *,CharacterVertexSlider * const &,std::_Iterator_base>::~_Iterator_with_base<std::bidirectional_iterator_tag,CharacterVertexSlider *,int,CharacterVertexSlider * const *,CharacterVertexSlider * const &,std::_Iterator_base>()  + 0x3c bytes	C++
 	0018e8c0()	
 	msvcp90d.dll!_Mtxunlock(_RTL_CRITICAL_SECTION * _Mtx=0x505de338)  Line 54	C
 	msvcp90d.dll!std::_Lockit::~_Lockit()  Line 70 + 0x14 bytes	C++
 	libpanda_d.dll!std::_Iterator_base::~_Iterator_base()  Line 162 + 0x10 bytes	C++
 	libpanda_d.dll!std::_Iterator_with_base<std::bidirectional_iterator_tag,CharacterVertexSlider *,int,CharacterVertexSlider * const *,CharacterVertexSlider * const &,std::_Iterator_base>::~_Iterator_with_base<std::bidirectional_iterator_tag,CharacterVertexSlider *,int,CharacterVertexSlider * const *,CharacterVertexSlider * const &,std::_Iterator_base>()  + 0x3c bytes	C++
 	msvcp90d.dll!std::wcout()  + 0x1d0 bytes	C++
 	ccc35de5()

Any ideas?

fredzyda · June 15, 2012, 12:36am

Hmm, it looks like turning off asynchronous loading makes the deadlock assert go away, but nothing appears to ever render. If I break into the app, it looks like the threads aren’t all stuck waiting all the time, I just don’t ever seem to get output to the screen, which is bad. This could be two bugs or they could be related somehow. If I don’t set a threading-model, it all works fine, even with asynchronous loading on, but I could really use the frame rate boost that turning on cull and draw threads will give me. Any ideas?