Re: [Log4cplus-devel] Thread blocking when calling ev.gatherThreadSpecificData ();

[Andersen, J. B. (E W EN R&D DT ES 2 1) <jes...@si...>]

Thread 1428 is the blocking thread. 
When I click on the ::Queue::put_event in the calls stack Visual studio says that the next line in execution is: SemaphoreGuard semguard (sem);

Maybe it is just waiting for the sem??


1844	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::ConfigurationWatchDogThread::run	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::ConfigurationWatchDogThread::run() Line 639	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

11340	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::thread::Queue::get_events	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::thread::Queue::get_events(std::deque<log4cplus::spi::InternalLoggingEvent,std::allocator<log4cplus::spi::InternalLoggingEvent> > * buf) Line 171	 
 	 	log4cplus.dll!log4cplus::`anonymous namespace'::QueueThread::run() Line 71	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

5076	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::thread::Queue::get_events	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::thread::Queue::get_events(std::deque<log4cplus::spi::InternalLoggingEvent,std::allocator<log4cplus::spi::InternalLoggingEvent> > * buf) Line 171	 
 	 	log4cplus.dll!log4cplus::`anonymous namespace'::QueueThread::run() Line 71	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

10480	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::thread::Queue::get_events	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::thread::Queue::get_events(std::deque<log4cplus::spi::InternalLoggingEvent,std::allocator<log4cplus::spi::InternalLoggingEvent> > * buf) Line 171	 
 	 	log4cplus.dll!log4cplus::`anonymous namespace'::QueueThread::run() Line 71	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

7460	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::thread::Queue::get_events	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::thread::Queue::get_events(std::deque<log4cplus::spi::InternalLoggingEvent,std::allocator<log4cplus::spi::InternalLoggingEvent> > * buf) Line 171	 
 	 	log4cplus.dll!log4cplus::`anonymous namespace'::QueueThread::run() Line 71	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

9384	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::thread::Queue::get_events	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::thread::Queue::get_events(std::deque<log4cplus::spi::InternalLoggingEvent,std::allocator<log4cplus::spi::InternalLoggingEvent> > * buf) Line 171	 
 	 	log4cplus.dll!log4cplus::`anonymous namespace'::QueueThread::run() Line 71	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

1428	0	Worker Thread	Win32 Thread	log4cplus.dll!log4cplus::thread::Queue::put_event	Time Critical
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!log4cplus::thread::Queue::put_event(const log4cplus::spi::InternalLoggingEvent & ev) Line 58	 
 	 	log4cplus.dll!log4cplus::AsyncAppender::append(const log4cplus::spi::InternalLoggingEvent & ev) Line 172	 
 	 	log4cplus.dll!log4cplus::Appender::doAppend(const log4cplus::spi::InternalLoggingEvent & event) Line 288	 
 	 	log4cplus.dll!log4cplus::spi::LoggerImpl::callAppenders(const log4cplus::spi::InternalLoggingEvent & event) Line 60	 
 	 	log4cplus.dll!log4cplus::detail::macro_forced_log(const log4cplus::Logger & logger, int log_level, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & msg, const char * filename, int line, const char * func) Line 86	 
 	 	
                    MyApplication()
 	 	
                     winmm.dll!745d3af0()	 
 	 	winmm.dll!745da535()	 
 	 	winmm.dll!745da434()	 

9928	0	Worker Thread	Win32 Thread	log4cplus.dll!std::basic_filebuf<char,std::char_traits<char> >::overflow	Normal
 	 	ntdll.dll!7748fa12()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748fa12()	 
 	 	log4cplus.dll!std::basic_filebuf<char,std::char_traits<char> >::overflow(int _Meta) Line 336	 
 	 	log4cplus.dll!std::operator<<<char,std::char_traits<char>,std::allocator<char> >(std::basic_ostream<char,std::char_traits<char> > & _Ostr, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & _Str) Line 518	 
 	 	log4cplus.dll!log4cplus::pattern::PatternConverter::formatAndAppend(std::basic_ostream<char,std::char_traits<char> > & output, const log4cplus::spi::InternalLoggingEvent & event) Line 370	 
 	 	log4cplus.dll!log4cplus::PatternLayout::formatAndAppend(std::basic_ostream<char,std::char_traits<char> > & output, const log4cplus::spi::InternalLoggingEvent & event) Line 1109	 
 	 	log4cplus.dll!log4cplus::FileAppender::append(const log4cplus::spi::InternalLoggingEvent & event) Line 372	 
 	 	log4cplus.dll!log4cplus::RollingFileAppender::append(const log4cplus::spi::InternalLoggingEvent & event) Line 504	 
 	 	log4cplus.dll!log4cplus::Appender::doAppend(const log4cplus::spi::InternalLoggingEvent & event) Line 288	 
 	 	log4cplus.dll!log4cplus::`anonymous namespace'::QueueThread::run() Line 77	 
 	 	log4cplus.dll!log4cplus::thread::impl::ThreadStart::threadStartFuncWorker(void * arg) Line 216	 
 	 	log4cplus.dll!`anonymous namespace'::threadStartFunc(void * param) Line 185	 

3196	0	Worker Thread	Win32 Thread	log4cplus.dll!std::basic_string<char,std::char_traits<char>,std::allocator<char> >::_Copy	Normal
 	 	ntdll.dll!7748f8c1()	 
 	 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	 
 	 	ntdll.dll!7748f8c1()	 
 	 	log4cplus.dll!std::basic_string<char,std::char_traits<char>,std::allocator<char> >::_Copy(unsigned int _Newsize, unsigned int _Oldlen) Line 1932	 
 	 	ws2_32.dll!754b2f7d()	 
 	 	ntdll.dll!7748fd81()	 
 	 	ws2_32.dll!754b6958()	 
 	 	ws2_32.dll!754b68cd()	 

 	 	MyApplication()

 	 	kernel32.dll!76cc339a()	 




-----Original Message-----
From: Václav Zeman [mailto:vha...@gm...] 
Sent: 14. marts 2014 13:48
To: Andersen, Jesper Behrens (E W EN R&D DT ES 2 1)
Cc: log...@li...
Subject: Re: [Log4cplus-devel] Thread blocking when calling ev.gatherThreadSpecificData ();

On 14 March 2014 13:43, Andersen, Jesper Behrens (E W EN R&D DT ES 2 1) wrote:
> Hi,
>
> Setup:
> log4cplus version 1.1.2.0.
> Compiled for Windows XP target platform
> Compiled using visual studio 2010 compiler as dynamic libraries.
> Logging is done from multiple threads.
>
> Loggers are configured with the AsyncAppender and a sub RollingFileAppender
> like this:
> ########################################################################
> ## log file configuration (to disable, remove it from the rootLogger) ##
> ##
> log4cplus.appender.IRlogfile=log4cplus::AsyncAppender
> log4cplus.appender.IRlogfile.QueueLimit=100
>
> log4cplus.appender.IRlogfile.Appender=log4cplus::RollingFileAppender
> log4cplus.appender.IRlogfile.Appender.layout=log4cplus::PatternLayout
> log4cplus.appender.IRlogfile.Appender.BufferSize=10000
> log4cplus.appender.IRlogfile.Appender.ImmediateFlush=true
> ##
> ## The name and location for the log file
> log4cplus.appender.IRlogfile.Appender.File=d:/IRCore.log.txt
> ##
> ## The frequency at which log files will be rotated
> log4cplus.appender.IRlogfile.Appender.DatePattern='.'yyyy-MM-dd
> ##
> ## The maximum size of log files before they are rotated
> log4cplus.appender.IRlogfile.Appender.MaxFileSize=10MB
> ##
> ## The number of backup log files to keep
> log4cplus.appender.IRlogfile.Appender.MaxBackupIndex=10
> ##
> ## pattern used for the log file
> log4cplus.appender.IRlogfile.Appender.layout.ConversionPattern=%D{%Y-%m-%d
> %H:%M:%S.%q};%c;%m%n
>
>
> I have experienced one of my threads blocked for aprox. 1500 ms.
> This triggered my watchdog thread to write a minidump file. This mini dump
> indicated that the blocking thread was located somewhere in the
> ev.gatherThreadSpecificData() method.
>
> Maybe my configuration is faulted?
>
> From the source I can see it must have been in one of the these methods the
> block occured:
>
>     getNDC ();
>     getMDCCopy ();
>     getThread ();
>     getThread2 ();
>
> Can anybody see / explain why a block can occur?

I have no explanation. Could you post the tail of the thread stack?

-- 
VZ