How to profile pthread mutex in linux?
I would like to know how to profile a pthread mutex to see if there are any locking contention points in my code. (who likes contentious code, right? :) I know how to do a more general profiling of the code, as I mention here. But I would like to know if there are any tools or options available to be able to profile mutex locking that would provide metrics/stats about mutex locking contentions to see if I have any problem areas.
Here's some background and context:
Recently I worked on an embedded C++ project using a Cavium Octeon CPU. The Octeon SDK implements mutex style synchronization using spinlocks. Looking through the Octeon documentation, I came across a way to profile the spinlocks to be able to see how many times each spinlock had to spin while waiting for the lock to become available. To use this I had to do a conditional compile and then it would increment a counter each time the spinlock spun, then I could query the spinner wait value. So, what I did was to encapsulate the spinlock and added the ability to dump the spinlock spinner wait value for all of the spinlocks used in the system. The actual value didnt mean much, but there were a few that had really high values compared to the rest, and I focused on reducing the contention for those.
I know this is probably quite easy for spinlocks, since its just a counter per spin, but reading through the related pthread man pages and header files I havent found anything similar, is there something available for pthread mutex?
I would really like to avoid having to do something hacky like taking the time before and after each lock.
PS: What's the plural of mutex? mutexes, muteces, mutexi, muti??? Mutexes never sounded right to me.
Answer
The valgrind tool drd lets you specify a limit on how long a lock should be waited on before reporting an error.
This site mentions drd and also mentions their own tool called mutrace which looks like the kind of tool you're after. It tells you:
- how many times a mutex was locked
- how many times the mutex owning thread changed
- how many times a mutex was contended (already locked when a lock request was made)
- various stats on the duration a mutex was locked for
e.g.
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.