When naively profiling multi-threaded applications the time spent waiting for mutexes is not necessarily visible in the generated output. However lock contention can have a big impact on the runtime behaviour of applications. On Linux valgrind's drd can be used to track down mutex contention. Unfortunately running applications under valgrind/drd slows them down massively, often having the effect of itself generating many of the contentions one is trying to track down. Also due to its slowness it is very time consuming work.
To improve the situation if have now written a mutex profiler called mutrace. In contrast to valgrind/drd it does not virtualize the CPU instruction set, making it a lot faster. In fact, the hooks mutrace relies on to profile mutex operations should only minimally influence application runtime. mutrace is not useful for finding synchronizations bugs, it is solely useful for profiling locks.
Now, enough of this introductionary blabla. Let's have a look on the data mutrace can generate for you. As an example we'll look at gedit as a bit of a prototypical Gnome application. Gtk+ and the other Gnome libraries are not really known for their heavy use of multi-threading, and the APIs are generally not thread-safe (for a good reason). However, internally subsytems such as gio do use threading quite extensibly. And as it turns out there are a few hotspots that can be discovered with mutrace:
$ LD_PRELOAD=/home/lennart/projects/mutrace/libmutrace.so gedit mutrace: 0.1 sucessfully initialized.
gedit is now running and its mutex use is being profiled. For this example I have now opened a file with it, typed a few letters and then quit the program again without saving. As soon as gedit exits mutrace will print the profiling data it gathered to stderr. The full output you can see here. The most interesting part is at the end of the generated output, a breakdown of the most contended mutexes:
mutrace: 10 most contended mutexes:
Mutex # Locked Changed Cont. tot.Time[ms] avg.Time[ms] max.Time[ms] Type
35 368268 407 275 120,822 0,000 0,894 normal
5 234645 100 21 86,855 0,000 0,494 normal
26 177324 47 4 98,610 0,001 0,150 normal
19 55758 53 2 23,931 0,000 0,092 normal
53 106 73 1 0,769 0,007 0,160 normal
25 15156 70 1 6,633 0,000 0,019 normal
4 973 10 1 4,376 0,004 0,174 normal
75 68 62 0 0,038 0,001 0,004 normal
9 1663 52 0 1,068 0,001 0,412 normal
3 136553 41 0 61,408 0,000 0,281 normal
... ... ... ... ... ... ... ...
mutrace: Total runtime 9678,142 ms.
(Sorry, LC_NUMERIC was set to de_DE.UTF-8, so if you can't make sense of all the commas, think s/,/./g!)
For each mutex a line is printed. The 'Locked' column tells how often the mutex was locked during the entire runtime of about 10s. The 'Changed' column tells us how often the owning thread of the mutex changed. The 'Cont.' column tells us how often the lock was already taken when we tried to take it and we had to wait. The fifth column tell us for how long during the entire runtime the lock was locked, the sixth tells us the average lock time, and the seventh column tells us the longest time the lock was held. Finally, the last column tells us what kind of mutex this is (recursive, normal or otherwise).
The most contended lock in the example above is #35. 275 times during the runtime a thread had to wait until another thread released this mutex. All in all more then 120ms of the entire runtime (about 10s) were spent with this lock taken!
In the full output we can now look up which mutex #35 actually is:
Mutex #35 (0x0x7f48c7057d28) first referenced by: /home/lennart/projects/mutrace/libmutrace.so(pthread_mutex_lock+0x70) [0x7f48c97dc900] /lib64/libglib-2.0.so.0(g_static_rw_lock_writer_lock+0x6a) [0x7f48c674a03a] /lib64/libgobject-2.0.so.0(g_type_init_with_debug_flags+0x4b) [0x7f48c6e38ddb] /usr/lib64/libgdk-x11-2.0.so.0(gdk_pre_parse_libgtk_only+0x8c) [0x7f48c853171c] /usr/lib64/libgtk-x11-2.0.so.0(+0x14b31f) [0x7f48c891831f] /lib64/libglib-2.0.so.0(g_option_context_parse+0x90) [0x7f48c67308e0] /usr/lib64/libgtk-x11-2.0.so.0(gtk_parse_args+0xa1) [0x7f48c8918021] /usr/lib64/libgtk-x11-2.0.so.0(gtk_init_check+0x9) [0x7f48c8918079] /usr/lib64/libgtk-x11-2.0.so.0(gtk_init+0x9) [0x7f48c89180a9] /usr/bin/gedit(main+0x166) [0x427fc6] /lib64/libc.so.6(__libc_start_main+0xfd) [0x7f48c5b42b4d] /usr/bin/gedit() [0x4276c9]
As it appears in this Gtk+ program the rwlock type_rw_lock (defined in glib's gobject/gtype.c) is a hotspot. GLib's rwlocks are implemented on top of mutexes, so an obvious attempt in improving this could be to actually make them use the operating system's rwlock primitives.
If a mutex is used often but only ever by the same thread it cannot starve other threads. The 'Changed.' column lists how often a specific mutex changed the owning thread. If the number is high this means the risk of contention is also high. The 'Cont.' column tells you about contention that actually took place.
Due to the way mutrace works we cannot profile mutexes that are used internally in glibc, such as those used for synchronizing stdio and suchlike.
mutrace is implemented entirely in userspace. It uses all kinds of exotic GCC, glibc and kernel features, so you might have a hard time compiling and running it on anything but a very recent Linux distribution. I have tested it on Rawhide but it should work on slightly older distributions, too.
Make sure to build your application with -rdynamic to make the backtraces mutrace generates useful.
As of now, mutrace only profiles mutexes. Adding support for rwlocks should be easy to add though. Patches welcome.
The output mutrace generates can be influenced by various MUTRACE_xxx environment variables. See the sources for more information.
And now, please take mutrace and profile and speed up your application!