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