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

[Václav Z. <vha...@gm...>]

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