deadlock within logging?

[Alex Wu]

We have this stack trace:

Thread 66 (LWP 2509):
#0  0x00007efd2489489c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007efd24890065 in _L_lock_858 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007efd2488feba in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3  0x00007efd18a3db47 in net_instaweb::SharedCircularBuffer::Write(base::BasicStringPiece<std::string> const&, net_instaweb::MessageHandler*) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#4  0x00007efd188d0de4 in net_instaweb::SystemMessageHandler::AddMessageToBuffer(net_instaweb::MessageType, base::BasicStringPiece<std::string>) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#5  0x00007efd186250eb in net_instaweb::ApacheMessageHandler::MessageSImpl(net_instaweb::MessageType, std::string const&) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#6  0x00007efd188d08fc in net_instaweb::SystemMessageHandler::MessageVImpl(net_instaweb::MessageType, char const*, __va_list_tag*) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#7  0x00007efd186e9407 in net_instaweb::MessageHandler::Message(net_instaweb::MessageType, char const*, ...) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so


This thread own the muxt others are waitin for:
Thread 56 (LWP 2499):
#0  0x00007efd2489489c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007efd24890065 in _L_lock_858 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2  0x00007efd2488feba in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3  0x00007efd188d0d91 in net_instaweb::SystemMessageHandler::AddMessageToBuffer(net_instaweb::MessageType, base::BasicStringPiece<std::string>) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#4  0x00007efd186250eb in net_instaweb::ApacheMessageHandler::MessageSImpl(net_instaweb::MessageType, std::string const&) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#5  0x00007efd188d08fc in net_instaweb::SystemMessageHandler::MessageVImpl(net_instaweb::MessageType, char const*, __va_list_tag*) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so
#6  0x00007efd186e9407 in net_instaweb::MessageHandler::Message(net_instaweb::MessageType, char const*, ...) () from /opt/bg/deploy/apache24/modules/mod_pagespeed_ap24.so

there are  more than 5  of this thread. The function call AddMessageToBuffer waitng for the mutex locked by the thread 66 (the first one).

No any trace to show who locks the mutex thread 66 is waiting for within CircularBuffer code. Have this deadlock seen before?

Alex

[Otto van der Schaaf]

Well, I haven't seen this trace earlier, but I just looked at the code for a bit and observed that the code path in question would try to take two different locks: 

The one you observe (in SystemMessageHandler::AddMessageToBuffer [1]), and subsequently one in SharedCircularBuffer::Write [2] while still holding the first lock.

At first sight, that seems kind of tricky...

[1] https://github.com/pagespeed/mod_pagespeed/blob/master/pagespeed/system/system_message_handler.cc#L77

[2] https://github.com/pagespeed/mod_pagespeed/blob/d76bc188e663e4b065be7cc02cc84c8fed77c362/pagespeed/kernel/sharedmem/shared_circular_buffer.cc#L106

Otto

--
You received this message because you are subscribed to the Google Groups "pagespeed-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to pagespeed-de...@googlegroups.com.
To post to this group, send email to pagesp...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/pagespeed-dev/c06164c3-7749-43a1-b340-f8eae5ec456e%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Alex Wu]

The question is why in apache message handler, it calls AddMessageToBuffer?
void ApacheMessageHandler::MessageSImpl(
    MessageType type, const GoogleString& message) {
  int log_level = GetApacheLogLevel(type);
  ap_log_error(APLOG_MARK, log_level, APR_SUCCESS, server_rec_,
               "[%s %s @%ld] %s",
               kModuleName, version_.c_str(), static_cast<long>(getpid()),
               message.c_str());
  AddMessageToBuffer(type, message);
}

it seems useless and expensive call.

Alex

[kspoe...@we-amp.com]

It might be that the deadlock is caused by anohther apache process becuase it is in the SharedCircularbBuffer.

if this happens again, try to get a dump of all apache http server processes, so that we can find the root cause.

[Alex Wu]

what is the usage of

AddMessageToBuffer(type, message);

in a logging of debugging mrssage code?

It seems to me, no use at all. I have removed this line, expect no more deadlock from this line.

Aled