playing with mutrace
Boudewijn Rempt
boud at valdyas.org
Wed Sep 16 08:25:02 CEST 2009
Hi!
Lennart Poettering recently made a new tool, mutrace -- see http://0pointer.de/blog/projects/mutrace.html. Initially it didn't work with
KDE apps but Lennart made it work, so I'm presenting here the first bit of mutrace output for Krita!
A bit of drawing, a gradient, the blur filter a second layer and a bit of drawing.
boud at valdiesalie:~/kde/src/svn/kdelibs/kdeui/icons> mutrace --hash-size=40000 krita
mutrace: 0.1 sucessfully initialized for process krita (pid 9802).
X Error: BadAtom (invalid Atom parameter) 5
Major opcode: 20 (X_GetProperty)
Resource id: 0x0
Enchant dict for "en_US" 0x8f16d98
Enchant dict for "en_US" 0x8f16d98
Enchant dict for "en_US" 0x8f16d98
Enchant dict for "en_US" 0x8f16d98
Enchant dict for "en_US" 0x8f16d98
QLayout: Attempting to add QLayout "" to QWidget "KritaShape/KisToolBrushoption widget", which already has
a layout
Object::connect: No such signal KoSliderCombo::valueChanged(int,bool)
Object::connect: (receiver name: 'KritaFill/KisToolGradient')
QLayout: Attempting to add QLayout "" to QWidget "KritaShape/KisToolLine", which already has a layout
QObject::connect: Cannot connect KoMainWindow::restoringDone() to (null)::removeUnusedOptionWidgets()
** (process:9802): WARNING **: 1 dictionaries weren't free'd.
mutrace: Showing statistics for process krita (pid 9802).
mutrace: 2756 mutexes used.
Mutex #289 (0x0x87fa018) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0x124) [0xb80a42a4]
/usr/lib/libQtCore.so.4 [0xb7eadd63]
/usr/lib/libQtCore.so.4(_ZN6QMutexC1ENS_13RecursionModeE+0x37) [0xb7ea92c7]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisTileManagerC1Ev+0x71) [0xb7a99b91]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisTileManager8instanceEv+0x4e) [0xb7a9a0ae]
/home/boud/kde/inst/lib/libkritaimage.so.6 [0xb7a96523]
/home/boud/kde/inst/lib/libkritaimage.so.6 [0xb7a96974]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN19KisTiledDataManagerC2EjPKh+0x81) [0xb7a92ae1]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisPaintDeviceC1E16KisWeakSharedPtrI7KisNodeEPK12KoColorSpaceRK7QString+0x1b6)
[0xb7b1a806]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN13KisGroupLayerC1E16KisWeakSharedPtrI8KisImageERK7QStringh+0x24f)
[0xb7aef9df]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN8KisImage4initEP14KisUndoAdapteriiPK12KoColorSpace+0xee)
[0xb7af5f3e]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN8KisImageC1EP14KisUndoAdapteriiPK12KoColorSpaceRK7QString+0xea)
[0xb7af62ca]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d72071]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN7KisDoc27loadXMLERK13KoXmlDocumentP7KoStore+0x375)
[0xb7cc1da5]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument33loadNativeFormatFromStoreInternalEP7KoStore+0x38a)
[0xb76d023a]
Mutex #1354 (0x0x808f92c) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_lock+0x58) [0xb80a4108]
/usr/lib/libglib-2.0.so.0(g_source_attach+0x97) [0xb56c3ae7]
/usr/lib/libQtCore.so.4(_ZN27QEventDispatcherGlibPrivateC2EP13_GMainContext+0xc8) [0xb7fcedf8]
/usr/lib/libQtGui.so.4 [0xb5bc0f3d]
/usr/lib/libQtGui.so.4 [0xb5bc1023]
/usr/lib/libQtGui.so.4(_ZN19QApplicationPrivate21createEventDispatcherEv+0x90) [0xb5b87640]
/usr/lib/libQtCore.so.4(_ZN16QCoreApplication4initEv+0xac) [0xb7fa64dc]
/usr/lib/libQtCore.so.4(_ZN16QCoreApplicationC2ER23QCoreApplicationPrivate+0x47) [0xb7fa65e7]
/usr/lib/libQtGui.so.4(_ZN12QApplicationC2ERiPPcbi+0x5a) [0xb5b25b7a]
/usr/lib/libkdeui.so.5(_ZN12KApplicationC2Eb+0x4e) [0xb69e0cbe]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN13KoApplicationC1Ev+0x2e) [0xb76b3d5e]
/home/boud/kde/inst/lib/libkdeinit4_krita.so(kdemain+0x16d) [0xb809f9ed]
krita [0x80488b2]
Mutex #1002 (0x0x8804180) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0x124) [0xb80a42a4]
/usr/lib/libQtCore.so.4 [0xb7eadd63]
/usr/lib/libQtCore.so.4(_ZN6QMutexC1ENS_13RecursionModeE+0x37) [0xb7ea92c7]
/home/boud/kde/inst/lib/libkritaimage.so.6 [0xb7a9693f]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN19KisTiledDataManagerC2EjPKh+0x81) [0xb7a92ae1]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisPaintDeviceC1E16KisWeakSharedPtrI7KisNodeEPK12KoColorSpaceRK7QString+0x1b6)
[0xb7b1a806]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN13KisPaintLayerC1E12KisSharedPtrI8KisImageERK7QStringhPK12KoColorSpace+0x158)
[0xb7b234c8]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6c66d]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6f9b7]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d70d81]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d7212a]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN7KisDoc27loadXMLERK13KoXmlDocumentP7KoStore+0x375)
[0xb7cc1da5]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument33loadNativeFormatFromStoreInternalEP7KoStore+0x38a)
[0xb76d023a]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument25loadNativeFormatFromStoreERK7QString+0xa6)
[0xb76d0d46]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument16loadNativeFormatERK7QString+0x1a1)
[0xb76d1071]
Mutex #83 (0x0x9368274) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_lock+0x58) [0xb80a4108]
/usr/lib/libglib-2.0.so.0(g_source_attach+0x97) [0xb56c3ae7]
/usr/lib/libQtCore.so.4(_ZN27QEventDispatcherGlibPrivateC1EP13_GMainContext+0xc8) [0xb7fcf098]
/usr/lib/libQtCore.so.4(_ZN20QEventDispatcherGlibC1EP7QObject+0x3b) [0xb7fcf3ab]
/usr/lib/libQtCore.so.4 [0xb7eae3a4]
/usr/lib/libQtCore.so.4 [0xb7eae549]
/lib/libpthread.so.0 [0xb7e4c1b5]
/lib/libc.so.6(clone+0x5e) [0xb58493be]
Mutex #1968 (0x0x8505f50) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0x124) [0xb80a42a4]
/usr/lib/libQtCore.so.4 [0xb7eadd63]
/usr/lib/libQtCore.so.4(_ZN6QMutexC1ENS_13RecursionModeE+0x37) [0xb7ea92c7]
/home/boud/kde/inst/lib/libkritaimage.so.6 [0xb7a9693f]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN19KisTiledDataManager4readEP7KoStore+0x15b)
[0xb7a9219b]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisPaintDevice4readEP7KoStore+0x37) [0xb7b19c37]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6902e]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6ab8b]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN13KisPaintLayer6acceptER14KisNodeVisitor+0x18)
[0xb7b20d38]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisNodeVisitor8visitAllEP7KisNodeb+0x57)
[0xb7b18a87]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d68529]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN13KisGroupLayer6acceptER14KisNodeVisitor+0x18)
[0xb7aece68]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6d2a2]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN7KisDoc215completeLoadingEP7KoStore+0xcd) [0xb7cc27fd]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument33loadNativeFormatFromStoreInternalEP7KoStore+0x140)
[0xb76cfff0]
Mutex #798 (0x0x88c40c8) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0x124) [0xb80a42a4]
/usr/lib/libQtCore.so.4 [0xb7eadd63]
/usr/lib/libQtCore.so.4(_ZN6QMutexC1ENS_13RecursionModeE+0x37) [0xb7ea92c7]
/home/boud/kde/inst/lib/libkoresources.so.6(_ZN24KoResourceServerProviderC1Ev+0x6be) [0xb732831e]
/home/boud/kde/inst/lib/libkoresources.so.6(_ZN24KoResourceServerProvider8instanceEv+0x4e)
[0xb732859e]
/home/boud/kde/inst/lib/kde4/karbondockersplugin.so [0xb12f7055]
/home/boud/kde/inst/lib/kde4/karbondockersplugin.so [0xb12fc43b]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN12KoMainWindow16createDockWidgetEP13KoDockFactory+0x56f)
[0xb76ecf9f]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN6KoView16createDockWidgetEP13KoDockFactory+0x3f)
[0xb771289f]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN6KoViewC2EP10KoDocumentP7QWidget+0x448) [0xb7714528]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN8KisView2C1EP7KisDoc2P7QWidget+0x4b) [0xb7d409cb]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN7KisDoc218createViewInstanceEP7QWidget+0x3e)
[0xb7cc0abe]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument10createViewEP7QWidget+0x21) [0xb76c1081]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN12KoMainWindow15setRootDocumentEP10KoDocument+0x353)
[0xb76eed53]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument17showStartUpWidgetEP12KoMainWindowb+0x27c)
[0xb76cbc9c]
Mutex #2002 (0x0x8506688) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0x124) [0xb80a42a4]
/usr/lib/libQtCore.so.4 [0xb7eadd63]
/usr/lib/libQtCore.so.4(_ZN6QMutexC1ENS_13RecursionModeE+0x37) [0xb7ea92c7]
/home/boud/kde/inst/lib/libkritaimage.so.6 [0xb7a9693f]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN19KisTiledDataManager4readEP7KoStore+0x15b)
[0xb7a9219b]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisPaintDevice4readEP7KoStore+0x37) [0xb7b19c37]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6902e]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6ab8b]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN13KisPaintLayer6acceptER14KisNodeVisitor+0x18)
[0xb7b20d38]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN14KisNodeVisitor8visitAllEP7KisNodeb+0x57)
[0xb7b18a87]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d68529]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN13KisGroupLayer6acceptER14KisNodeVisitor+0x18)
[0xb7aece68]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7d6d2a2]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN7KisDoc215completeLoadingEP7KoStore+0xcd) [0xb7cc27fd]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument33loadNativeFormatFromStoreInternalEP7KoStore+0x140)
[0xb76cfff0]
Mutex #2583 (0x0x8051c18) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_lock+0x58) [0xb80a4108]
/usr/lib/libQtCore.so.4 [0xb7eadad7]
/usr/lib/libQtCore.so.4(_ZN6QMutex4lockEv+0x165) [0xb7ea91f5]
/usr/lib/libQtCore.so.4(_ZN11QMetaObject7connectEPK7QObjectiS2_iiPi+0x61) [0xb7fb4fc1]
/usr/lib/libQtCore.so.4(_ZN7QObject7connectEPKS_PKcS1_S3_N2Qt14ConnectionTypeE+0x3a2) [0xb7fb5472]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN12KisCmbIDListC1EP7QWidgetPKc+0xbb) [0xb7da557b]
/home/boud/kde/inst/lib/libkritalibpaintop.so.6(_ZN17KisSensorSelectorC1EP7QWidget+0x14b)
[0xb212e72b]
/home/boud/kde/inst/lib/libkritalibpaintop.so.6(_ZN14KisCurveOptionC2ERK7QStringS2_b+0x1a5)
[0xb2121805]
/home/boud/kde/inst/lib/libkritalibpaintop.so.6(_ZN24KisPressureOpacityOptionC1Ev+0x7d)
[0xb212c55d]
/home/boud/kde/inst/lib/kde4/kritacomplexbrush.so [0xb20cd0ce]
/home/boud/kde/inst/lib/kde4/kritacomplexbrush.so [0xb20cd4db]
/home/boud/kde/inst/lib/kde4/kritacomplexbrush.so [0xb20ca1e9]
/home/boud/kde/inst/lib/kde4/kritacomplexbrush.so [0xb20ca70c]
Mutex #176 (0x0x9083570) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0x124) [0xb80a42a4]
/usr/lib/libQtCore.so.4 [0xb7eadd63]
/usr/lib/libQtCore.so.4(_ZN6QMutexC1ENS_13RecursionModeE+0x37) [0xb7ea92c7]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN25KisResourceServerProviderC1Ev+0x317) [0xb7d23147]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN25KisResourceServerProvider8instanceEv+0x4e)
[0xb7d2363e]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7dc53b6]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7cb263d]
/home/boud/kde/inst/lib/libkritaui.so.6 [0xb7cb3067]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN8KisView29createGUIEv+0x1fd) [0xb7d3d07d]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN8KisView2C1EP7KisDoc2P7QWidget+0x4e8) [0xb7d40e68]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN7KisDoc218createViewInstanceEP7QWidget+0x3e)
[0xb7cc0abe]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument10createViewEP7QWidget+0x21) [0xb76c1081]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN12KoMainWindow15setRootDocumentEP10KoDocument+0x353)
[0xb76eed53]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN10KoDocument17showStartUpWidgetEP12KoMainWindowb+0x27c)
[0xb76cbc9c]
/home/boud/kde/inst/lib/libkomain.so.6(_ZN13KoApplication5startEv+0xcc2) [0xb76b4c52]
Mutex #2229 (0x0x804dea8) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_lock+0x58) [0xb80a4108]
/usr/lib/libQtCore.so.4 [0xb7eadad7]
/usr/lib/libQtCore.so.4(_ZN6QMutex4lockEv+0xfd) [0xb7ea918d]
/usr/lib/libQtCore.so.4(_ZN19QAbstractFileEngine6createERK7QString+0x248) [0xb7f245d8]
/usr/lib/libQtCore.so.4 [0xb7f39510]
/usr/lib/libkdecore.so.5 [0xb6742246]
/usr/lib/libkdecore.so.5 [0xb673b7a0]
/usr/lib/libkdecore.so.5(_ZN8KLibraryC1ERK7QStringRK14KComponentDataP7QObject+0x36) [0xb673bb96]
/usr/lib/libkdecore.so.5(_ZN10KLibLoader7libraryERK7QString6QFlagsIN8QLibrary8LoadHintEE+0x68)
[0xb673afc8]
/home/boud/kde/inst/lib/libkoplugin.so.6(_ZN14KoPluginLoader4loadERK7QStringS2_RKNS_13PluginsConfigE+0x1383)
[0xb70c3703]
/home/boud/kde/inst/lib/libkritaimage.so.6(_ZN18KisPaintOpRegistry8instanceEv+0xc6) [0xb7aae8a6]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN11KisFactory213componentDataEv+0x225) [0xb7cc8475]
/home/boud/kde/inst/lib/libkritaui.so.6(_ZN11KisFactory2C1EP7QObject+0x51) [0xb7cc8d61]
mutrace: Showing 10 most contended mutexes:
Mutex # Locked Changed Cont. tot.Time[ms] avg.Time[ms] max.Time[ms] Flag
289 2728870 222349 143464 5590.908 0.002 5.469 x.--
1354 2445278 1009 315 5576.579 0.002 12.141 -.--
1002 4812 464 259 9.827 0.002 0.134 -.--
83 2743 110 46 6.286 0.002 0.022 -.--
1968 817 136 27 1.725 0.002 0.012 -.--
798 249 174 12 1.235 0.005 0.056 -.--
2002 2079 110 10 4.077 0.002 0.007 -.--
2583 341 219 8 1.198 0.004 0.060 -.--
176 41 31 5 0.157 0.004 0.011 -.--
2229 11 8 4 0.034 0.003 0.007 -.--
... ... ... ... ... ... ... ||||
/|||
State: x = dead, ! = inconsistent /||
Use: R = used in realtime thread /|
Type: r = RECURSIVE, e = ERRRORCHECK, a = ADAPTIVE /
Protocol: i = INHERIT, p = PROTECT
mutrace: Note that the flags column R is only valid in --track-rt mode!
mutrace: Total runtime is 61917.355 ms.
mutrace: WARNING: 99 internal hash collisions detected. Results might not be as reliable as they could be.
mutrace: Try to increase --hash-size=, which is currently at 40000.
I think this tool should be able to help us a lot! This is with the old tile engine, and as you can see the contention for the Great Big
Krita Lock is really high and completely kills us. We knew it was bad of course, but now we've been able to measure it! I'm going to retry
with the new tile engine now.
--
Boudewijn Rempt | http://www.valdyas.org
More information about the kimageshop
mailing list