Script to identify contended mutex locks with a stack trace.

Script to identify contended mutex locks with a stack trace.

[Alan Conway]

[-- Attachment #1: Type: text/plain, Size: 1311 bytes --]

I'm trying to write a systemtap script that will identify contended mutex locks 
and print a user stack trace to identify them. Two unsuccessful attempts are 
attached, I'd appreciate any tips on how to make them work.

futexes.stp is a modified version of the futexes example provided with stap. I 
added a pthread_mutex_lock.return trace point and I attempt to print the user 
stack trace there. However the stack trace is just a hex address. Also for my 
contention_test.c (attached) test it claims that there are 9 locks contended 1 
times each rather than 1 lock contended 9 times.

mutexes.stp sets probes on pthread_muted_lock and .return. This almost works but 
the stack trace for contention_test.c doesn't show functions main and foo as I 
expect, I get:
  0x0000003073408ca0 : __pthread_mutex_lock+0x0/0x135 [/lib64/libpthread-2.5.so]
  0x000000000040065e : _end+0x15de06/0x1e97a8 
[/home/remote/aconway/install/lib/libqpidbroker.so.2.0.0]

If I run mutexes.stp on anything non-trivial it prints a bunch of very promising 
looking stack traces but then falls over with:

ERROR: Skipped too many probes, check MAXSKIPPED or try again with stap -t for 
more details.
WARNING: Skipped due to global 'thread_blocktime' lock timeout: 101

Any tips on how to make these work would be greatly appreciated!


[-- Attachment #2: contention_test.c --]
[-- Type: text/x-csrc, Size: 558 bytes --]

#include <pthread.h>
#include <stdlib.h>
#include <unistd.h>

pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;

void* sleeper(void* p) {
  pthread_mutex_lock(&lock);	/* Contended */
  usleep(1000);
  pthread_mutex_unlock(&lock);
}

void foo() {
  const int n=10;
  pthread_mutex_lock(&lock);
  pthread_t thread[n];
  int i;
  for (i = 0; i < n; ++i) 
    pthread_create(&thread[i], NULL, sleeper, NULL);
  usleep(5000);
  pthread_mutex_unlock(&lock);
  for (i = 0; i < n; ++i) 
    pthread_join(thread[i], 0);
}

int main(int argc,char** argv) {
  foo();
}

[-- Attachment #3: futexes.stp --]
[-- Type: text/plain, Size: 1402 bytes --]

#!/usr/bin/stap

# This script tries to identify contended user-space locks by hooking
# into the futex system call.

global thread_thislock # short
global thread_blocktime # 
global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */

global lock_waits # long-lived stats on (tid,lock) blockage elapsed time
global process_names # long-lived pid-to-execname mapping
     
probe syscall.futex {  
  if (op != FUTEX_WAIT) next; # don't care about WAKE event originator
  t = tid ()
  process_names[pid()] = execname()
  thread_thislock[t] = $uaddr
  thread_blocktime[t] = gettimeofday_us()
}

probe syscall.futex.return {  
  t = tid()
  ts = thread_blocktime[t]
  if (ts) {
    elapsed = gettimeofday_us() - ts
    lock_waits[pid(), thread_thislock[t]] <<< elapsed
  }
}

probe process("/lib64/libpthread.so.0").function("pthread_mutex_lock").return {
  t = tid();
  l = thread_thislock[t]
  if (thread_blocktime[t]) {
    # Print a stack trace the first time we see a lock.
    if (@count(lock_waits[pid(), l]) == 1) {
      printf("Trace for lock %s:%p\n", process_names[pid()], l);
      print_ubacktrace();
    }
    delete thread_blocktime[t];
    delete thread_thislock[t]
  }
}

probe end {
  foreach ([pid+, lock] in lock_waits) 
    printf ("%s[%d] lock %p contended %d times, %d avg us\n",
            process_names[pid], pid, lock, @count(lock_waits[pid,lock]),
            @avg(lock_waits[pid, lock]));
}

[-- Attachment #4: Makefile --]
[-- Type: text/plain, Size: 139 bytes --]

LDLIBS=-lpthread
CFLAGS=-g -O0
all: contention_test
	stap -d ./contention_test -c ./contention_test mutexes.stp
clean:
	rm contention_test

[-- Attachment #5: mutexes.stp --]
[-- Type: text/plain, Size: 1398 bytes --]

#!/usr/bin/stap

# This script tries to identify contended mutex locks.

global thread_blocktime		  # time of latest lock call by thread
global lock_waits # long-lived stats on (pid,lock) blockage elapsed time
global process_names		  # long-lived pid-to-execname mapping

global mutex_locks;		  # number of locks in progress
global mutex_stack;		  # flag if we already printed a stack

probe process("/lib64/libpthread.so.0").function("pthread_mutex_lock") {
  if (mutex_locks[$mutex]++ > 0) {	  # Contended
      process_names[pid()] = execname();
      thread_blocktime[tid()] = gettimeofday_us();
      if (!mutex_stack[pid(), $mutex]) {
	mutex_stack[pid(), $mutex] = 1;
	printf("%s[%d] mutex %p stack trace:\n", process_names[pid()], pid(), $mutex)
	print_ubacktrace();
      }
  }
}

probe process("/lib64/libpthread.so.0").function("pthread_mutex_lock").return {
  --mutex_locks[$mutex];
  t = tid();
  ts = thread_blocktime[t];
  if (ts) {
    elapsed = gettimeofday_us() - ts;
    lock_waits[pid(), $mutex] <<< elapsed;
    delete thread_blocktime[tid()]
  }
}

probe end {
  // TODO: sort output by sum of wait times, rather than count.
  foreach ([pid, m] in lock_waits-) {
    printf ("%s[%d] mutex %p contended %d times, %dus total, %dus avg\n",
            process_names[pid], pid, m, 
	    @count(lock_waits[pid,m]),
	    @sum(lock_waits[pid,m]),
	    @avg(lock_waits[pid,m]));
  }
}

Re: Script to identify contended mutex locks with a stack trace.

[William Cohen]

On 09/07/2010 05:21 PM, Alan Conway wrote:
> I'm trying to write a systemtap script that will identify contended mutex locks and print a user stack trace to identify them. Two unsuccessful attempts are attached, I'd appreciate any tips on how to make them work.
> 
> futexes.stp is a modified version of the futexes example provided with stap. I added a pthread_mutex_lock.return trace point and I attempt to print the user stack trace there. However the stack trace is just a hex address. Also for my contention_test.c (attached) test it claims that there are 9 locks contended 1 times each rather than 1 lock contended 9 times.
> 
> mutexes.stp sets probes on pthread_muted_lock and .return. This almost works but the stack trace for contention_test.c doesn't show functions main and foo as I expect, I get:
>  0x0000003073408ca0 : __pthread_mutex_lock+0x0/0x135 [/lib64/libpthread-2.5.so]
>  0x000000000040065e : _end+0x15de06/0x1e97a8 [/home/remote/aconway/install/lib/libqpidbroker.so.2.0.0]
> 
> If I run mutexes.stp on anything non-trivial it prints a bunch of very promising looking stack traces but then falls over with:
> 
> ERROR: Skipped too many probes, check MAXSKIPPED or try again with stap -t for more details.
> WARNING: Skipped due to global 'thread_blocktime' lock timeout: 101
> 
> Any tips on how to make these work would be greatly appreciated!
> 

Hi Alan,

What Linux distribution and version of systemtap are you using? RHEL-5 and Systemtap-1.2?

This is maybe a side effect of print_ubacktrace() taking too long. 

http://sources.redhat.com/bugzilla/show_bug.cgi?id=10665

You might try and see if this problem goes away with systemtap-1.3.

-Will