[QPID-2567] [c++] Timer - possible thread lock ordering violation

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.7
• Fix Version/s: 0.17
• Component/s: C++ Broker

Environment

RHEL-6 beta

• Assignee: Andrew Stitcher
• Reporter: Kim van der Riet
• Created: 04/May/10 15:15
• Updated: 29/Jul/13 18:54
• Resolved: 05/Jul/12 20:45

Description

Starting the broker using valgrind and the helgrind thread check tool shows several lock order violations centered around the qpid::sys::Timer class.

valgrind --tool=helgrind .libs/lt-qpidd --auth no --log-enable info+

results in the following message (and others that are similar):

==31280== Thread #2: lock order "0x597D548 before 0x59AE350" violated
==31280== at 0x4A0679C: pthread_mutex_lock (hg_intercepts.c:464)
==31280== by 0x4E8C27B: qpid::sys::Mutex::lock() (Mutex.h:116)
==31280== by 0x4E8CD82: qpid::sys::ScopedLock<qpid::sys::Mutex>::ScopedLock(qpid::sys::Mutex&) (Mutex.h:33)
==31280== by 0x56346FF: qpid::sys::Timer::add(boost::intrusive_ptr<qpid::sys::TimerTask>) (Timer.cpp:162)
==31280== by 0x4EFDCD0: qpid::broker::LinkRegistry::Periodic::fire() (LinkRegistry.cpp:73)
==31280== by 0x563344C: qpid::sys::TimerTask::fireTask() (Timer.cpp:57)
==31280== by 0x5634917: qpid::sys::Timer::fire(boost::intrusive_ptr<qpid::sys::TimerTask>) (Timer.cpp:190)
==31280== by 0x5633E84: qpid::sys::Timer::run() (Timer.cpp:119)
==31280== by 0x5525BEE: qpid::sys::(anonymous namespace)::runRunnable(void*) (Thread.cpp:35)
==31280== by 0x4A0A1A5: mythread_wrapper (hg_intercepts.c:201)
==31280== by 0x31D6C07950: start_thread (pthread_create.c:301)
==31280== by 0x31D68E4D3C: clone (clone.S:115)
==31280== Required order was established by acquisition of lock at 0x597D548
==31280== at 0x4A095F6: pthread_cond_wait_WRK (hg_intercepts.c:653)
==31280== by 0x4A096B8: pthread_cond_wait@* (hg_intercepts.c:675)
==31280== by 0x4EF587A: qpid::sys::Condition::wait(qpid::sys::Mutex&) (Condition.h:63)
==31280== by 0x4EF5932: qpid::sys::Monitor::wait() (Monitor.h:41)
==31280== by 0x5633AA6: qpid::sys::Timer::run() (Timer.cpp:98)
==31280== by 0x5525BEE: qpid::sys::(anonymous namespace)::runRunnable(void*) (Thread.cpp:35)
==31280== by 0x4A0A1A5: mythread_wrapper (hg_intercepts.c:201)
==31280== by 0x31D6C07950: start_thread (pthread_create.c:301)
==31280== by 0x31D68E4D3C: clone (clone.S:115)
==31280== followed by a later acquisition of lock at 0x59AE350
==31280== at 0x4A0679C: pthread_mutex_lock (hg_intercepts.c:464)
==31280== by 0x4E8C27B: qpid::sys::Mutex::lock() (Mutex.h:116)
==31280== by 0x4E8CD82: qpid::sys::ScopedLock<qpid::sys::Mutex>::ScopedLock(qpid::sys::Mutex&) (Mutex.h:33)
==31280== by 0x5633B97: qpid::sys::Timer::run() (Timer.cpp:108)
==31280== by 0x5525BEE: qpid::sys::(anonymous namespace)::runRunnable(void*) (Thread.cpp:35)
==31280== by 0x4A0A1A5: mythread_wrapper (hg_intercepts.c:201)
==31280== by 0x31D6C07950: start_thread (pthread_create.c:301)
==31280== by 0x31D68E4D3C: clone (clone.S:115)

Running perftest against this broker shows numerous read/write conflicts too.