Some operations on queues with Ring policy are extremely slow
-------------------------------------------------------------
Key: QPID-3909
URL: https://issues.apache.org/jira/browse/QPID-3909
Project: Qpid
Issue Type: Bug
Components: C++ Broker
Affects Versions: 0.12
Environment: Ubuntu 10.0.4
Reporter: Jeff Armstrong
When performing certain operations on queues with Ring policy, they can cause
such a large slowdown that enqueuing/dequeuing on that queue can stall almost
indefinitely. These slowdowns don't seem to apply when using no policy or
Reject policy (RING_STRICT was not tested).
1) Acquiring (but not accepting) a set of messages, then acquiring and
accepting a second set of messages causes a major slowdown. Acquiring 10,000
messages, then acquiring and accepting a subsequent 10,000 messages caused a
stall of about 10 seconds. Acquiring 100,000 and then acquiring and accepting
200,000 messages caused stalls upward of an hour. Looking at backtraces, the
broker is always inside RingQueuePolicy::find(), so this is likely where all
the work is occurring.
Here is a typical backtrace:
#0 boost::intrusive_ptr<qpid::broker::Message>::operator= (this=0x239b510,
rhs=...) at /usr/local/include/boost/smart_ptr/intrusive_ptr.hpp:134
#1 0x00007f3504f5dcb7 in qpid::broker::QueuedMessage::operator=
(this=0x239b510) at ./qpid/broker/QueuedMessage.h:32
#2 0x00007f3504f9de1f in std::__copy_move_backward<false, false,
std::random_access_iterator_tag>::__copy_move_b<std::_Deque_iterator<qpid::broker::QueuedMessage,
qpid::broker::QueuedMessage&, qpid::broker::QueuedMessage*>,
std::_Deque_iterator<qpid::broker::QueuedMessage, qpid::broker::QueuedMessage&,
qpid::broker::QueuedMessage*> > (__first=..., __last=..., __result=...)
at /usr/include/c++/4.4/bits/stl_algobase.h:546
#3 0x00007f3504f9da92 in std::__copy_move_backward_a<false,
std::_Deque_iterator<qpid::broker::QueuedMessage, qpid::broker::QueuedMessage&,
qpid::broker::QueuedMessage*>,
std::_Deque_iterator<qpid::broker::QueuedMessage, qpid::broker::QueuedMessage&,
qpid::broker::QueuedMessage*> > (__first=..., __last=..., __result=...) at
/usr/include/c++/4.4/bits/stl_algobase.h:595
#4 0x00007f3504f9d739 in std::__copy_move_backward_a2<false,
std::_Deque_iterator<qpid::broker::QueuedMessage, qpid::broker::QueuedMessage&,
qpid::broker::QueuedMessage*>,
std::_Deque_iterator<qpid::broker::QueuedMessage, qpid::broker::QueuedMessage&,
qpid::broker::QueuedMessage*> > (__first=..., __last=..., __result=...) at
/usr/include/c++/4.4/bits/stl_algobase.h:605
#5 0x00007f3504f9cfce in
std::copy_backward<std::_Deque_iterator<qpid::broker::QueuedMessage,
qpid::broker::QueuedMessage&, qpid::broker::QueuedMessage*>,
std::_Deque_iterator<qpid::broker::QueuedMessage, qpid::broker::QueuedMessage&,
qpid::broker::QueuedMessage*> > (__first=..., __last=..., __result=...) at
/usr/include/c++/4.4/bits/stl_algobase.h:640
#6 0x00007f3504f9c465 in std::deque<qpid::broker::QueuedMessage,
std::allocator<qpid::broker::QueuedMessage> >::erase (this=0x7f34f0003d20,
__position=...) at /usr/include/c++/4.4/bits/deque.tcc:174
#7 0x00007f3504fccb97 in qpid::broker::RingQueuePolicy::find
(this=0x7f34f0003c90, m=..., q=..., remove=true) at
qpid/broker/QueuePolicy.cpp:304
#8 0x00007f3504fcc350 in qpid::broker::RingQueuePolicy::dequeued
(this=0x7f34f0003c90, m=...) at qpid/broker/QueuePolicy.cpp:232
#9 0x00007f3504faf1fb in qpid::broker::Queue::dequeued (this=0x7f34f00479e0,
msg=...) at qpid/broker/Queue.cpp:715
#10 0x00007f3504faed12 in qpid::broker::Queue::dequeue (this=0x7f34f00479e0,
ctxt=0x0, msg=...) at qpid/broker/Queue.cpp:671
#11 0x00007f3504f4daab in qpid::broker::DeliveryRecord::accept (this=0x2f54e50,
ctxt=0x0) at qpid/broker/DeliveryRecord.cpp:115
#12 0x00007f3504ff86ee in boost::_mfi::mf1<bool, qpid::broker::DeliveryRecord,
qpid::broker::TransactionContext*>::operator() (this=0x7f34fca9eaf0, t=...,
a1=0x0)
at /usr/local/include/boost/bind/mem_fn_template.hpp:181
#13 0x00007f3504ff7e09 in boost::_bi::list2<boost::arg<1>,
boost::_bi::value<qpid::broker::TransactionContext*> >::operator()<bool,
boost::_mfi::mf1<bool, qpid::broker::DeliveryRecord,
qpid::broker::TransactionContext*>,
boost::_bi::list1<qpid::broker::DeliveryRecord&> > (this=0x7f34fca9eb00, f=...,
a=...) at /usr/local/include/boost/bind/bind.hpp:296
#14 0x00007f3504ff6608 in boost::_bi::bind_t<bool, boost::_mfi::mf1<bool,
qpid::broker::DeliveryRecord, qpid::broker::TransactionContext*>,
boost::_bi::list2<boost::arg<1>,
boost::_bi::value<qpid::broker::TransactionContext*> >
>::operator()<qpid::broker::DeliveryRecord> (this=0x7f34fca9eaf0, a1=...) at
/usr/local/include/boost/bind/bind_template.hpp:32
#15 0x00007f3504ff41af in
qpid::broker::IsInSequenceSetAnd<boost::_bi::bind_t<bool,
boost::_mfi::mf1<bool, qpid::broker::DeliveryRecord,
qpid::broker::TransactionContext*>, boost::_bi::list2<boost::arg<1>,
boost::_bi::value<qpid::broker::TransactionContext*> > > >::operator()
(this=0x7f34fca9eae0, dr=...) at qpid/broker/SemanticState.cpp:754
#16 0x00007f3504ff25ef in
std::remove_if<std::_Deque_iterator<qpid::broker::DeliveryRecord,
qpid::broker::DeliveryRecord&, qpid::broker::DeliveryRecord*>,
qpid::broker::IsInSequenceSetAnd<boost::_bi::bind_t<bool,
boost::_mfi::mf1<bool, qpid::broker::DeliveryRecord,
qpid::broker::TransactionContext*>, boost::_bi::list2<boost::arg<1>,
boost::_bi::value<qpid::broker::TransactionContext*> > > > > (__first=...,
__last=..., __pred=...) at /usr/include/c++/4.4/bits/stl_algo.h:1159
#17 0x00007f3504fef8f1 in qpid::broker::SemanticState::accepted
(this=0x7f34f0003498, commands=...) at qpid/broker/SemanticState.cpp:791
#18 0x00007f35050000f3 in
qpid::broker::SessionAdapter::MessageHandlerImpl::accept (this=0x7f34f0003668,
commands=...) at qpid/broker/SessionAdapter.cpp:489
#19 0x00007f3504885004 in
qpid::framing::MessageAcceptBody::invoke<qpid::framing::AMQP_ServerOperations::MessageHandler>
(this=0x7f34fb193f70, invocable=...) at ./qpid/framing/MessageAcceptBody.h:63
#20 0x00007f3504882f65 in
qpid::framing::AMQP_ServerOperations::MessageHandler::Invoker::visit
(this=0x7f34fca9ee10, body=...) at qpid/framing/ServerInvoker.cpp:534
#21 0x00007f35048cadd6 in qpid::framing::MessageAcceptBody::accept
(this=0x7f34fb193f70, v=...) at ./qpid/framing/MessageAcceptBody.h:67
#22 0x00007f350488025a in qpid::framing::AMQP_ServerOperations::Invoker::visit
(this=0x7f34fca9ee90, body=...) at qpid/framing/ServerInvoker.cpp:218
#23 0x00007f35048cadd6 in qpid::framing::MessageAcceptBody::accept
(this=0x7f34fb193f70, v=...) at ./qpid/framing/MessageAcceptBody.h:67
#24 0x00007f3505015c2e in qpid::framing::invoke<qpid::broker::SessionAdapter>
(target=..., body=...) at ./qpid/framing/Invoker.h:67
#25 0x00007f3505010c8b in qpid::broker::SessionState::handleCommand
(this=0x7f34f00032c0, method=0x7f34fb193f70, id=...) at
qpid/broker/SessionState.cpp:210
#26 0x00007f35050120b7 in qpid::broker::SessionState::handleIn
(this=0x7f34f00032c0, frame=...) at qpid/broker/SessionState.cpp:364
#27 0x00007f3505019aa5 in
qpid::framing::Handler<qpid::framing::AMQFrame&>::MemFunRef<qpid::framing::Handler<qpid::framing::AMQFrame&>::InOutHandlerInterface,
&(qpid::framing::Handler<qpid::framing::AMQFrame&>::InOutHandlerInterface::handleIn(qpid::framing::AMQFrame&))>::handle
(this=0x7f34f0003450, t=...) at ./qpid/framing/Handler.h:67
#28 0x00007f3504921f52 in qpid::amqp_0_10::SessionHandler::handleIn
(this=0x7f34f00028e0, f=...) at qpid/amqp_0_10/SessionHandler.cpp:93
#29 0x00007f3505019aa5 in
qpid::framing::Handler<qpid::framing::AMQFrame&>::MemFunRef<qpid::framing::Handler<qpid::framing::AMQFrame&>::InOutHandlerInterface,
&(qpid::framing::Handler<qpid::framing::AMQFrame&>::InOutHandlerInterface::handleIn(qpid::framing::AMQFrame&))>::handle
(this=0x7f34f00028f0, t=...) at ./qpid/framing/Handler.h:67
#30 0x00007f3504f3fe12 in
qpid::framing::Handler<qpid::framing::AMQFrame&>::operator()
(this=0x7f34f00028f0, t=...) at ./qpid/framing/Handler.h:42
#31 0x00007f3504f3b86e in qpid::broker::Connection::received
(this=0x7f34f00041e0, frame=...) at qpid/broker/Connection.cpp:164
#32 0x00007f3504efbb7a in qpid::amqp_0_10::Connection::decode
(this=0x7f34f0004d60, buffer=0x7f34f00373a0 "\017\001", size=28) at
qpid/amqp_0_10/Connection.cpp:58
#33 0x00007f3504fe69eb in qpid::broker::SecureConnection::decode
(this=0x7f34f0006650, buffer=0x7f34f00373a0 "\017\001", size=28) at
qpid/broker/SecureConnection.cpp:42
#34 0x00007f35049613bc in qpid::sys::AsynchIOHandler::readbuff
(this=0x7f34f0005910, buff=0x7f34f0006860) at qpid/sys/AsynchIOHandler.cpp:135
#35 0x00007f350506e022 in boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler,
qpid::sys::AsynchIO&, qpid::sys::AsynchIOBufferBase*>::operator()
(this=0x7f34f0002f90, p=0x7f34f0005910, a1=...,
a2=0x7f34f0006860) at /usr/local/include/boost/bind/mem_fn_template.hpp:274
#36 0x00007f350506d3b4 in
boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
boost::arg<1>, boost::arg<2> >::operator()<boost::_mfi::mf2<void,
qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>, boost::_bi::list2<qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*&> > (this=0x7f34f0002fa0, f=..., a=...) at
/usr/local/include/boost/bind/bind.hpp:385
---Type <return> to continue, or q <return> to quit---
#37 0x00007f350506cd3a in boost::_bi::bind_t<void, boost::_mfi::mf2<void,
qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>,
boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
boost::arg<1>, boost::arg<2> > >::operator()<qpid::sys::AsynchIO,
qpid::sys::AsynchIOBufferBase*> (this=0x7f34f0002f90, a1=...,
a2=@0x7f34fcaa0568)
at /usr/local/include/boost/bind/bind_template.hpp:61
#38 0x00007f350506c5ef in
boost::detail::function::void_function_obj_invoker2<boost::_bi::bind_t<void,
boost::_mfi::mf2<void, qpid::sys::AsynchIOHandler, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>,
boost::_bi::list3<boost::_bi::value<qpid::sys::AsynchIOHandler*>,
boost::arg<1>, boost::arg<2> > >, void, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>::invoke (function_obj_ptr=..., a0=...,
a1=0x7f34f0006860) at
/usr/local/include/boost/function/function_template.hpp:153
#39 0x00007f3504852c2e in boost::function2<void, qpid::sys::AsynchIO&,
qpid::sys::AsynchIOBufferBase*>::operator() (this=0x7f34f0002f88, a0=...,
a1=0x7f34f0006860)
at /usr/local/include/boost/function/function_template.hpp:1013
#40 0x00007f3504850a28 in qpid::sys::posix::AsynchIO::readable
(this=0x7f34f0002e30, h=...) at qpid/sys/posix/AsynchIO.cpp:428
#41 0x00007f3504855f04 in boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
qpid::sys::DispatchHandle&>::operator() (this=0x7f34f0002e50, p=0x7f34f0002e30,
a1=...)
at /usr/local/include/boost/bind/mem_fn_template.hpp:162
#42 0x00007f3504855478 in
boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>, boost::arg<1>
>::operator()<boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO,
qpid::sys::DispatchHandle&>, boost::_bi::list1<qpid::sys::DispatchHandle&> >
(this=0x7f34f0002e60, f=..., a=...) at
/usr/local/include/boost/bind/bind.hpp:306
#43 0x00007f3504854b44 in boost::_bi::bind_t<void, boost::_mfi::mf1<void,
qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>, boost::arg<1>
> >::operator()<qpid::sys::DispatchHandle> (this=0x7f34f0002e50, a1=...) at
/usr/local/include/boost/bind/bind_template.hpp:32
#44 0x00007f35048541ad in
boost::detail::function::void_function_obj_invoker1<boost::_bi::bind_t<void,
boost::_mfi::mf1<void, qpid::sys::posix::AsynchIO, qpid::sys::DispatchHandle&>,
boost::_bi::list2<boost::_bi::value<qpid::sys::posix::AsynchIO*>, boost::arg<1>
> >, void, qpid::sys::DispatchHandle&>::invoke (function_obj_ptr=..., a0=...)
at /usr/local/include/boost/function/function_template.hpp:153
#45 0x00007f35049657b4 in boost::function1<void,
qpid::sys::DispatchHandle&>::operator() (this=0x7f34f0002e48, a0=...) at
/usr/local/include/boost/function/function_template.hpp:1013
#46 0x00007f3504964d8f in qpid::sys::DispatchHandle::processEvent
(this=0x7f34f0002e38, type=qpid::sys::Poller::READABLE) at
qpid/sys/DispatchHandle.cpp:280
#47 0x00007f350485f6dc in qpid::sys::Poller::Event::process
(this=0x7f34fcaa0d80) at ./qpid/sys/Poller.h:131
#48 0x00007f350485e820 in qpid::sys::Poller::run (this=0x1155ac0) at
qpid/sys/epoll/EpollPoller.cpp:519
#49 0x00007f350496a15f in qpid::sys::Dispatcher::run (this=0x7fffa722f970) at
qpid/sys/Dispatcher.cpp:37
#50 0x00007f350485807f in runRunnable (p=0x7fffa722f970) at
qpid/sys/posix/Thread.cpp:35
#51 0x00007f35034809ca in start_thread (arg=<value optimized out>) at
pthread_create.c:300
#52 0x00007f350398170d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#53 0x0000000000000000 in ?? ()
2) Killing a session which had acquired, but not accepted messages, then
connecting with a new session causes a long slowdown dependent on the number of
unacked messages. I've lost the backtraces, but the slowdown seemed to stem
from the operation which copied the unacked messages from the old session to
the new one.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
