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

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

Hi,

Thank you for your answer. 
Ok, it sounds likely that the QueueLimit is too low, I will try and raise it.
There are multiple asyncAppenders defined in the configuration file, I forgot to mention that. I only posted the configuration for the one that was blocked.

Jesper Andersen


-----Original Message-----
From: Václav Zeman [mailto:vha...@gm...] 
Sent: 17. marts 2014 15:34
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 14:09, Andersen, Jesper Behrens (E W EN R&D DT ES 2 1) wrote:

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

The QueueLimity property says how many events can be in the queue between the worker thread and other threads. Your configuration says it will be only 100. If you reach the limit, which is guarded by the semaphore, then the next put_event() will block on it.

What I find confusing is that you have so many threads in
Queue::get_events() even though your configuration shows only one AsyncAppender.

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