lock contention - what can we do about it?

Milian Wolff mail at milianw.de
Sat Mar 5 18:36:32 UTC 2011 

Hey all,

I just ran duchainify to test floris patches and was negativley suprised by 
what top told me: Duchainify only used 50-70% of CPU... Considering that 
duchainify was using two threads and I have a dual core, something way above 
100% would be cool... But at least *something* above 100% would be required, 
no?

Using http://valgrind.org/docs/manual/drd-manual.html#drd-manual.lock-
contention and duchainify with a threshold of 50ms I see lots of cases where 
locks are hold for e.g. 200ms or more...

e.g.:

==23711== Thread 6:
==23711== Acquired at:
==23711==    at 0x4C35434: QMutex::lock() (drd_qtcore_intercepts.c:160)
==23711==    by 0x5D96D68: Utils::Set::Iterator::operator++() 
(setrepository.cpp:435)
==23711==    by 0x19254AAD: Utils::ConvenientIterator<rpp::pp_macro, 
Cpp::MacroIndexConversion>::operator++() (setrepository.h:48)
==23711==    by 0x1925118C: Cpp::EnvironmentFile::merge(Cpp::EnvironmentFile 
const&, CppPreprocessEnvironment*) (environmentmanager.cpp:562)
==23711==    by 0x18CC38DB: PreprocessJob::run() (preprocessjob.cpp:315)
==23711==    by 0x18CB5D7E: CPPParseJob::parseForeground() 
(cppparsejob.cpp:173)
==23711==    by 0x18CC5633: PreprocessJob::sourceNeeded(QString&, 
rpp::Preprocessor::IncludeType, int, bool) (preprocessjob.cpp:593)
==23711==    by 0x18F73F2C: rpp::pp::handle_include(bool, rpp::Stream&, 
rpp::Stream&) (pp-engine.cpp:213)
==23711==    by 0x18F735DA: rpp::pp::handle_directive(unsigned int, 
rpp::Stream&, rpp::Stream&) (pp-engine.cpp:131)
==23711==    by 0x18F7423E: rpp::pp::operator()(rpp::Stream&, rpp::Stream&) 
(pp-engine.cpp:266)
==23711==    by 0x18F73134: rpp::pp::processFileInternal(QString const&, 
QByteArray const&, QVector<unsigned int>&) (pp-engine.cpp:98)
==23711==    by 0x18F72FE5: rpp::pp::processFile(QString const&, QByteArray 
const&) (pp-engine.cpp:85)
==23711== Lock on mutex 0x17389270 was held during 480 ms (threshold: 50 ms).
==23711==    at 0x4C3573F: QMutex::unlock() (drd_qtcore_intercepts.c:205)
==23711==    by 0x5D96EE8: Utils::Set::Iterator::operator++() 
(setrepository.cpp:462)
==23711==    by 0x19254AAD: Utils::ConvenientIterator<rpp::pp_macro, 
Cpp::MacroIndexConversion>::operator++() (setrepository.h:48)
==23711==    by 0x1925118C: Cpp::EnvironmentFile::merge(Cpp::EnvironmentFile 
const&, CppPreprocessEnvironment*) (environmentmanager.cpp:562)
==23711==    by 0x18CC38DB: PreprocessJob::run() (preprocessjob.cpp:315)
==23711==    by 0x18CB5D7E: CPPParseJob::parseForeground() 
(cppparsejob.cpp:173)
==23711==    by 0x18CC5633: PreprocessJob::sourceNeeded(QString&, 
rpp::Preprocessor::IncludeType, int, bool) (preprocessjob.cpp:593)
==23711==    by 0x18F73F2C: rpp::pp::handle_include(bool, rpp::Stream&, 
rpp::Stream&) (pp-engine.cpp:213)
==23711==    by 0x18F735DA: rpp::pp::handle_directive(unsigned int, 
rpp::Stream&, rpp::Stream&) (pp-engine.cpp:131)
==23711==    by 0x18F7423E: rpp::pp::operator()(rpp::Stream&, rpp::Stream&) 
(pp-engine.cpp:266)
==23711==    by 0x18F73134: rpp::pp::processFileInternal(QString const&, 
QByteArray const&, QVector<unsigned int>&) (pp-engine.cpp:98)
==23711==    by 0x18F72FE5: rpp::pp::processFile(QString const&, QByteArray 
const&) (pp-engine.cpp:85)
==23711== mutex 0x17389270 was first observed at:
==23711==    at 0x4C34E8B: QMutex::QMutex(QMutex::RecursionMode) 
(drd_qtcore_intercepts.c:96)
==23711==    by 0x5D99C05: KDevelop::ItemRepository<Utils::SetNodeData, 
Utils::SetNodeDataRequest, false, false, 20u, 
1048576u>::ItemRepository(QString, KDevelop::ItemRepositoryRegistry*, unsigned 
int, KDevelop::AbstractRepositoryManager*) (itemrepository.h:1311)
==23711==    by 0x5D994B5: 
Utils::SetDataRepository::SetDataRepository(Utils::BasicSetRepository*, 
QString, KDevelop::ItemRepositoryRegistry*) (basicsetrepository.h:138)
==23711==    by 0x5D984CC: 
Utils::BasicSetRepository::BasicSetRepository(QString, 
KDevelop::ItemRepositoryRegistry*, bool) (setrepository.cpp:908)
==23711==    by 0x19251D8A: Cpp::MacroSetRepository::MacroSetRepository() 
(environmentmanager.h:119)
==23711==    by 0x1924EE98: Cpp::EnvironmentManager::EnvironmentManager() 
(environmentmanager.cpp:183)
==23711==    by 0x1924EEF5: Cpp::EnvironmentManager::init() 
(environmentmanager.cpp:190)
==23711==    by 0x18CA6303: CppLanguageSupport::CppLanguageSupport(QObject*, 
QList<QVariant> const&) (cpplanguagesupport.cpp:167)
==23711==    by 0x18CAEBD6: QObject* 
KPluginFactory::createInstance<CppLanguageSupport, QObject>(QWidget*, 
QObject*, QList<QVariant> const&) (kpluginfactory.h:473)
==23711==    by 0x87429C0: KPluginFactory::create(char const*, QWidget*, 
QObject*, QList<QVariant> const&, QString const&) (in 
/usr/lib/libkdecore.so.5.6.0)
==23711==    by 0x6788A57: KDevelop::IPlugin* 
KPluginFactory::create<KDevelop::IPlugin>(QWidget*, QObject*, QString const&, 
QList<QVariant> const&) (kpluginfactory.h:527)
==23711==    by 0x6788401: KDevelop::IPlugin* 
KService::createInstance<KDevelop::IPlugin>(QWidget*, QObject*, 
QList<QVariant> const&, QString*) const (kservice.h:551)
==23711==

or 

==23711== Thread 6:
==23711== Acquired at:
==23711==    at 0x4C35434: QMutex::lock() (drd_qtcore_intercepts.c:160)
==23711==    by 0x5D99190: Utils::Set::staticUnref() (setrepository.cpp:1109)
==23711==    by 0x5C8A544: Utils::StorableSet<KDevelop::IndexedTopDUContext, 
KDevelop::IndexedTopDUContextIndexConversion, 
KDevelop::RecursiveImportCacheRepository, true, 
Utils::DummyLocker>::~StorableSet() (setrepository.h:167)
==23711==    by 0x5C88509: 
KDevelop::ConvenientEmbeddedSetTreeFilterIterator<KDevelop::IndexedDeclaration, 
KDevelop::IndexedDeclarationHandler, KDevelop::IndexedTopDUContext, 
Utils::StorableSet<KDevelop::IndexedTopDUContext, 
KDevelop::IndexedTopDUContextIndexConversion, 
KDevelop::RecursiveImportCacheRepository, true, Utils::DummyLocker>, 
KDevelop::DeclarationTopContextExtractor>::~ConvenientEmbeddedSetTreeFilterIterator() 
(convenientfreelist.h:319)
==23711==    by 0x5C88A92: 
KDevelop::TopDUContext::FindDeclarationsAcceptor::operator()
(KDevelop::QualifiedIdentifier const&) (topducontext.cpp:925)
==23711==    by 0x5C8DB06: bool 
KDevelop::TopDUContext::applyAliases<KDevelop::TopDUContext::FindDeclarationsAcceptor>(KDevelop::QualifiedIdentifier 
const&, KSharedPtr<KDevelop::DUContext::SearchItem> const&, 
KDevelop::TopDUContext::FindDeclarationsAcceptor&, KDevelop::CursorInRevision 
const&, bool, KDevelop::TopDUContext::ApplyAliasesBuddyInfo*, unsigned int) 
const (topducontext.cpp:1068)
==23711==    by 0x5C8A8E0: void 
KDevelop::TopDUContext::applyAliases<KDevelop::TopDUContext::FindDeclarationsAcceptor>(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::TopDUContext::FindDeclarationsAcceptor&, 
KDevelop::CursorInRevision const&, bool) const (topducontext.cpp:1143)
==23711==    by 0x5C846C0: 
KDevelop::TopDUContext::findDeclarationsInternal(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::CursorInRevision const&, 
TypePtr<KDevelop::AbstractType> const&, 
KDevVarLengthArray<KDevelop::Declaration*, 40>&, KDevelop::TopDUContext 
const*, QFlags<KDevelop::DUContext::SearchFlag>, unsigned int) const 
(topducontext.cpp:951)
==23711==    by 0x19203101: 
Cpp::CppDUContext<KDevelop::TopDUContext>::findDeclarationsInternal(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::CursorInRevision const&, 
TypePtr<KDevelop::AbstractType> const&, 
KDevVarLengthArray<KDevelop::Declaration*, 40>&, KDevelop::TopDUContext 
const*, QFlags<KDevelop::DUContext::SearchFlag>, unsigned int) const 
(cppducontext.h:281)
==23711==    by 0x192720C2: Cpp::FindDeclaration::closeIdentifier(bool) 
(cppducontext.cpp:246)
==23711==    by 0x192092BE: 
Cpp::CppDUContext<KDevelop::DUContext>::findDeclarationsInternal(KDevelop::QualifiedIdentifier 
const&, KDevelop::CursorInRevision const&, TypePtr<KDevelop::AbstractType> 
const&, KDevVarLengthArray<KDevelop::Declaration*, 40>&, 
KDevelop::TopDUContext const*, QFlags<KDevelop::DUContext::SearchFlag>) const 
(cppducontext.h:363)
==23711==    by 0x19205310: 
Cpp::CppDUContext<KDevelop::DUContext>::findDeclarationsInternal(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::CursorInRevision const&, 
TypePtr<KDevelop::AbstractType> const&, 
KDevVarLengthArray<KDevelop::Declaration*, 40>&, KDevelop::TopDUContext 
const*, QFlags<KDevelop::DUContext::SearchFlag>, unsigned int) const 
(cppducontext.h:286)
==23711== Lock on mutex 0x605af40 was held during 240 ms (threshold: 50 ms).
==23711==    at 0x4C3573F: QMutex::unlock() (drd_qtcore_intercepts.c:205)
==23711==    by 0x5D991BB: Utils::Set::staticUnref() (setrepository.cpp:1113)
==23711==    by 0x5C8A544: Utils::StorableSet<KDevelop::IndexedTopDUContext, 
KDevelop::IndexedTopDUContextIndexConversion, 
KDevelop::RecursiveImportCacheRepository, true, 
Utils::DummyLocker>::~StorableSet() (setrepository.h:167)
==23711==    by 0x5C88509: 
KDevelop::ConvenientEmbeddedSetTreeFilterIterator<KDevelop::IndexedDeclaration, 
KDevelop::IndexedDeclarationHandler, KDevelop::IndexedTopDUContext, 
Utils::StorableSet<KDevelop::IndexedTopDUContext, 
KDevelop::IndexedTopDUContextIndexConversion, 
KDevelop::RecursiveImportCacheRepository, true, Utils::DummyLocker>, 
KDevelop::DeclarationTopContextExtractor>::~ConvenientEmbeddedSetTreeFilterIterator() 
(convenientfreelist.h:319)
==23711==    by 0x5C88A92: 
KDevelop::TopDUContext::FindDeclarationsAcceptor::operator()
(KDevelop::QualifiedIdentifier const&) (topducontext.cpp:925)
==23711==    by 0x5C8DB06: bool 
KDevelop::TopDUContext::applyAliases<KDevelop::TopDUContext::FindDeclarationsAcceptor>(KDevelop::QualifiedIdentifier 
const&, KSharedPtr<KDevelop::DUContext::SearchItem> const&, 
KDevelop::TopDUContext::FindDeclarationsAcceptor&, KDevelop::CursorInRevision 
const&, bool, KDevelop::TopDUContext::ApplyAliasesBuddyInfo*, unsigned int) 
const (topducontext.cpp:1068)
==23711==    by 0x5C8A8E0: void 
KDevelop::TopDUContext::applyAliases<KDevelop::TopDUContext::FindDeclarationsAcceptor>(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::TopDUContext::FindDeclarationsAcceptor&, 
KDevelop::CursorInRevision const&, bool) const (topducontext.cpp:1143)
==23711==    by 0x5C846C0: 
KDevelop::TopDUContext::findDeclarationsInternal(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::CursorInRevision const&, 
TypePtr<KDevelop::AbstractType> const&, 
KDevVarLengthArray<KDevelop::Declaration*, 40>&, KDevelop::TopDUContext 
const*, QFlags<KDevelop::DUContext::SearchFlag>, unsigned int) const 
(topducontext.cpp:951)
==23711==    by 0x19203101: 
Cpp::CppDUContext<KDevelop::TopDUContext>::findDeclarationsInternal(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::CursorInRevision const&, 
TypePtr<KDevelop::AbstractType> const&, 
KDevVarLengthArray<KDevelop::Declaration*, 40>&, KDevelop::TopDUContext 
const*, QFlags<KDevelop::DUContext::SearchFlag>, unsigned int) const 
(cppducontext.h:281)
==23711==    by 0x192720C2: Cpp::FindDeclaration::closeIdentifier(bool) 
(cppducontext.cpp:246)
==23711==    by 0x192092BE: 
Cpp::CppDUContext<KDevelop::DUContext>::findDeclarationsInternal(KDevelop::QualifiedIdentifier 
const&, KDevelop::CursorInRevision const&, TypePtr<KDevelop::AbstractType> 
const&, KDevVarLengthArray<KDevelop::Declaration*, 40>&, 
KDevelop::TopDUContext const*, QFlags<KDevelop::DUContext::SearchFlag>) const 
(cppducontext.h:363)
==23711==    by 0x19205310: 
Cpp::CppDUContext<KDevelop::DUContext>::findDeclarationsInternal(KDevVarLengthArray<KSharedPtr<KDevelop::DUContext::SearchItem>, 
256> const&, KDevelop::CursorInRevision const&, 
TypePtr<KDevelop::AbstractType> const&, 
KDevVarLengthArray<KDevelop::Declaration*, 40>&, KDevelop::TopDUContext 
const*, QFlags<KDevelop::DUContext::SearchFlag>, unsigned int) const 
(cppducontext.h:286)
==23711== mutex 0x605af40 was first observed at:
==23711==    at 0x4C34E8B: QMutex::QMutex(QMutex::RecursionMode) 
(drd_qtcore_intercepts.c:96)
==23711==    by 0x5D99C05: KDevelop::ItemRepository<Utils::SetNodeData, 
Utils::SetNodeDataRequest, false, false, 20u, 
1048576u>::ItemRepository(QString, KDevelop::ItemRepositoryRegistry*, unsigned 
int, KDevelop::AbstractRepositoryManager*) (itemrepository.h:1311)
==23711==    by 0x5D994B5: 
Utils::SetDataRepository::SetDataRepository(Utils::BasicSetRepository*, 
QString, KDevelop::ItemRepositoryRegistry*) (basicsetrepository.h:138)
==23711==    by 0x5D985C2: 
Utils::BasicSetRepository::BasicSetRepository(QString, 
KDevelop::ItemRepositoryRegistry*, bool) (setrepository.cpp:908)
==23711==    by 0x5D08345: 
KDevelop::RecursiveImportCacheRepository::repository() 
(persistentsymboltable.cpp:40)
==23711==    by 0x5C3DA33: KDevelop::DUChain::initialize() (duchain.cpp:1148)
==23711==    by 0x678A7EC: 
KDevelop::CorePrivate::initialize(KDevelop::Core::Setup, QString) 
(core.cpp:215)
==23711==    by 0x678B05E: KDevelop::Core::initialize(KSplashScreen*, 
KDevelop::Core::Setup, QString const&) (core.cpp:275)
==23711==    by 0x40465A: main (main.cpp:222)
==23711==


I've looked at the last one and what I notice is:


void Set::staticRef() {
  if(!m_tree)
    return;
    m_repository->m_mutex->lock();
    SetNodeData* data = m_repository-
>dataRepository.dynamicItemFromIndexSimple(m_tree);
    ++data->m_refCount;
    m_repository->m_mutex->unlock();
}

but looking into dynamicItemFromIndexSimple we see


    ThisLocker lock(m_mutex);
...


locks over locks... can't we somehow do better than what do now? At least 100% 
of CPU time for two threads ;-)

bye

PS: we should also think again about our spin locks, as they are afair not 
detectable by e.g. DRD and need to be tested as well. I've also heard that 
qmutex is supposedly much faster in Qt 4.8, lets see!
-- 
Milian Wolff
mail at milianw.de
http://milianw.de
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: <http://mail.kde.org/pipermail/kdevelop-devel/attachments/20110305/cbf4694a/attachment.sig>

More information about the KDevelop-devel mailing list