Overview

The mutrace utility allows profile mutex locking overhead. valgrind includesa similar tool, DRD, but its overhead is usually too big for lock measuring. Included is also a even more specialized tool, matrace, which traces memory allocations on real-time threads. I didn't find use for that tool yet.

Project Information

Installation Instructions

Available by default at the Linaro developer image, and also at the Overlay PPA. To install it at any Linaro image, just run:

sudo apt-get install mutrace

Using mutrace

Statistics:

$ mutrace dolphin
mutrace: Application appears to be compiled without -rdynamic. It might be a
mutrace: good idea to recompile with -rdynamic enabled since this produces more
mutrace: useful stack traces.
mutrace: 0.2 sucessfully initialized for process dolphin (pid 3851).

mutrace: Showing statistics for process dolphin (pid 3853).
mutrace: 525 mutexes used.

Mutex #409 (0x0x860ed8) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_lock+0x49) [0x7f7f005f36e9]
        /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_acquire+0x59) [0x7f7ef815c669]

Mutex #523 (0x0x719208) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_lock+0x49) [0x7f7f005f36e9]
        /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_acquire+0x59) [0x7f7ef815c669]

Mutex #407 (0x0x7f7ef8408be8) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_lock+0x49) [0x7f7f005f36e9]
        /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_default+0x34) [0x7f7ef815a9d4]

Mutex #140 (0x0x71ade0) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_init+0xee) [0x7f7f005f351e]
        /usr/lib/x86_64-linux-gnu/libgthread-2.0.so.0(+0x25cc) [0x7f7ef6fb35cc]

Mutex #137 (0x0x71adb0) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_init+0xee) [0x7f7f005f351e]
        /usr/lib/x86_64-linux-gnu/libgthread-2.0.so.0(+0x25cc) [0x7f7ef6fb35cc]

Mutex #423 (0x0x7f7ef8408ec8) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_lock+0x49) [0x7f7f005f36e9]
        /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_static_private_set+0x82) [0x7f7ef8186812]

Mutex #404 (0x0x7f7ef8408b88) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_lock+0x49) [0x7f7f005f36e9]
        /lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_new+0xe0) [0x7f7ef815a8c0]

Mutex #147 (0x0x707380) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_init+0xee) [0x7f7f005f351e]
        /lib/x86_64-linux-gnu/libdbus-1.so.3(+0x2d94c) [0x7f7ef6d9a94c]

Mutex #197 (0x0x707f50) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_init+0xee) [0x7f7f005f351e]
        /lib/x86_64-linux-gnu/libdbus-1.so.3(+0x2d94c) [0x7f7ef6d9a94c]

Mutex #37 (0x0x70c6d0) first referenced by:
        /usr/lib/mutrace/libmutrace.so(pthread_mutex_init+0xee) [0x7f7f005f351e]
        /lib/x86_64-linux-gnu/libdbus-1.so.3(+0x2d94c) [0x7f7ef6d9a94c]

mutrace: Showing 10 most contended mutexes:

 Mutex #   Locked  Changed    Cont. tot.Time[ms] avg.Time[ms] max.Time[ms]  Flags
     409       53        2        1        0.127        0.002        0.042 M-.--.
     523     2769       10        0        4.659        0.002        0.012 M-.--.
     407        9        5        0        2.324        0.258        2.310 M-.--.
     140      255        4        0        0.434        0.002        0.024 M-.--.
     137       15        4        0        0.029        0.002        0.003 M-.--.
     423       10        4        0        0.019        0.002        0.003 M-.--.
     404        6        4        0        0.053        0.009        0.018 M-.--.
     147    23066        2        0       33.102        0.001        0.776 M-.--.
     197     4546        2        0        6.520        0.001        0.009 M-.--.
      37     1739        2        0       68.644        0.039       12.225 Mx.--.
     ...      ...      ...      ...          ...          ...          ... ||||||
                                                                           /|||||
          Object:                                     M = Mutex, W = RWLock /||||
           State:                                 x = dead, ! = inconsistent /|||
             Use:                                 R = used in realtime thread /||
      Mutex Type:                 r = RECURSIVE, e = ERRRORCHECK, a = ADAPTIVE /|
  Mutex Protocol:                                      i = INHERIT, p = PROTECT /
     RWLock Kind: r = PREFER_READER, w = PREFER_WRITER, W = PREFER_WRITER_NONREC 

mutrace: Note that the flags column R is only valid in --track-rt mode!

mutrace: Total runtime is 5231.667 ms.

mutrace: Results for SMP with 2 processors.

mutrace: WARNING: 42 internal hash collisions detected. Results might not be as reliable as they could be.
mutrace:          Try to increase --hash-size=, which is currently at 3371.

Future Areas

The tool is still very much "expert tool", you need to know what you are looking for to be able to get useful results. Find a way to get debug symbol packages (ddeb) easily for end user usage.

Limitations

Typically binaries are not compiled with -rdynamic, so the results are limited unless software is recompiled.


CategoryHowTo

Platform/DevPlatform/Tools/Mutrace (last modified 2011-09-01 04:14:10)