Anyone tried using "mutrace" on beam.smp?

[Scott Lystig Fritchie]

Hi, all.  What does a person do when attacked by insomnia?
Mutex profiling of the Erlang virtual machine, of course.

After taking the advice of mutrace's author and compiling
everything(*) with the "-rdynamic" linker flag(**), I tried
it out ... but the stack trace info didn't get much better
than with a 100% untouched-by-me R13B01 + Fedora Core 10
Linux build.

After running a sometime CPU-, sometimes disk-I/O-limited
workload for a few minutes, I've attached the report that
I got at the end of this message. (Running on R13B01 on a
dual core i386 laptop.)  Of the top 10 contended mutexes,
77.5 sec / 456.2 sec wallclock runtime shows says 17% time
spent in contention.  Actual wallclock time spent waiting
was probably less than that, but how much less I dunno.

I assume that the OTP team has been using some other tool
for its profiling & optimization of the VM's SMP innards.
If "mutrace" isn't used but could be helpful, wonderful.
Otherwise, it may be of interest to other gentle readers?

http://0pointer.de/blog/projects/mutrace.html

-Scott

(*) beam.smp and then three shared libraries: trace_ip_drv.so,
trace_file_drv.so, and crypto_drv.so.

(**) I cheated.  I took the "make" output, hunted for where
each of the four above were linked, then cut-and-pasted a small
shell script to re-do the linking step with "-rdynamic" added
to each.

mutrace: Showing statistics for process beam.smp (pid 2954).
mutrace: 197412 mutexes used.

Mutex #191163 (0x0xb7ae0b08) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]

Mutex #191120 (0x0xb7ae0988) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]

Mutex #135006 (0x0x820fdc0) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]
        /lib/libc.so.6(__libc_start_main+0xe5) [0x3b06e5]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp [0x806e801]

Mutex #135005 (0x0x820fd80) first referenced by:
        /tmp/libmutrace.so(pthread_rwlock_init+0xfb) [0xb7e2406b]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_rwmutex_init+0x17) [0x81b79c7]
        /lib/libc.so.6(__libc_start_main+0xe5) [0x3b06e5]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp [0x806e801]

Mutex #197409 (0x0x883d85c) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]

Mutex #197408 (0x0x883d25c) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]

Mutex #184333 (0x0xb7b2c9e8) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_gate_init+0x3b) [0x81b856b]
        /lib/libc.so.6(clone+0x5e) [0x47e04e]

Mutex #135004 (0x0x820fca0) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]

Mutex #135026 (0x0xb7b9bd28) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_gate_init+0x3b) [0x81b856b]
        /lib/libc.so.6(clone+0x5e) [0x47e04e]

Mutex #135000 (0x0x820f7c0) first referenced by:
        /tmp/libmutrace.so(pthread_mutex_init+0x124) [0xb7e24274]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp(ethr_mutex_init+0x2c) [0x81b7e1c]
        /lib/libc.so.6(__libc_start_main+0xe5) [0x3b06e5]
        /tmp/R13B01/lib/erlang/erts-5.7.2/bin/beam.smp [0x806e801]

mutrace: Showing 10 most contended mutexes:

 Mutex #   Locked  Changed    Cont. tot.Time[ms] avg.Time[ms] max.Time[ms]  Flags
  191163  4244283   306763    89886    11937.279        0.003       15.324 M-.--.
  191120  8810450   308827    57879    20226.626        0.002       11.541 M-.--.
  135006  5279274   330673    26464    20335.058        0.004        7.666 M-.--.
  135005  3544998   267925     3208     6814.369        0.002        3.729 W-...r
  197409  1360828    36825      523     3135.264        0.002        7.318 M-.--.
  197408  3003752    36382      490     6441.524        0.002        7.694 M-.--.
  184333   279995   140004      275      799.137        0.003        6.036 M-.--.
  135004   668695    15303      264     5276.240        0.008        9.349 M-.--.
  135026   155037    77522      260      455.899        0.003        4.352 M-.--.
  135000  1061733    15905      222     2081.179        0.002        6.419 M-.--.
     ...      ...      ...      ...          ...          ...          ... ||||||
                                                                           /|||||
          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 456184.437 ms.

mutrace: Results for SMP with 2 processors.

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

mutrace: WARNING: 532 internal mutex contention detected. Results might not be reliable as they could be.
mutrace:          Try to increase --hash-size=, which is currently at 39997.