1#@!#!123s

: / usr / local / ssl / share / systemtap / examples / process /
Filename : mutex-contention.stp
back
#!/usr/bin/stap

// NOTE: a popup mutex is one that is seen in contention but the init
// of it was not detected not sure why there are popups - static mutex
// init?

// stack trace where mutex was initialized, if known
global mutex_init_stack
// stack trace where mutex was first referenced, if init stack not known
global mutex_uninit
// stats about the contention on this mutex
global mutex_contention
// usymdata for this mutex
global mutex_names
// stack trace of last contention for this mutex
global mutex_last_cont_stack

// NOTE: the way 389 works is that many common mutexes are initialized
// in the same place.  For example - each connection object has its
// own mutex - there may be thousands of these.  They are all
// initialized in the same place - same with entry objects, where
// there may be millions.  So, if we want to get aggregate contention
// statistics for _all_ connection objects, not just each individual
// one, we have to keep track of each unique call stack.  This is what
// mutex_cont_stack is used for.

// stats about unique stacks
global mutex_cont_stack
// report mutexes that had more than this many contentions
global cont_count_threshold = 1
// usec - report mutexes that had a max time more than this
global cont_max_threshold = 100000
global verbose = 0
global keep_stats = 1

/* ... and a variant of the futexes.stp script: */
global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */
global FUTEX_PRIVATE_FLAG = 128 /* linux 2.6.22+ */
global FUTEX_CLOCK_REALTIME = 256 /* linux 2.6.29+ */

function process_mutex_init(mutex, ppfunc)
{
  if (verbose && (mutex in mutex_init_stack)) {
    printf("error: %s: mutex %p is already initialized at\n%s\n",
	   ppfunc, mutex, mutex_init_stack[mutex])
  }
  if (keep_stats) {
    mutex_init_stack[mutex] = sprint_ubacktrace()
    mutex_names[mutex] = usymdata (mutex)
  }
  else {
    printf("init %p at\n%s\n", mutex, sprint_ubacktrace())
  }
  if (verbose) {
    printf("%s: mutex %p %s\n", ppfunc, mutex, mutex_names[mutex])
  }
}

function show_contention(mutex, stack, type)
{
  count = @count(mutex_contention[mutex])
  max = @max(mutex_contention[mutex])
  if ((count > cont_count_threshold) || (max > cont_max_threshold)) {
    printf("=======================================\nmutex %p (%s) contended %d times, %d avg usec, %d max usec, %d total usec, %s at\n%s\n",
	   mutex, mutex_names[mutex], count, @avg(mutex_contention[mutex]),
	   max, @sum(mutex_contention[mutex]), type, stack)
    if (mutex in mutex_last_cont_stack) {
      printf("\nmutex was last contended at\n%s\n",
	     mutex_last_cont_stack[mutex])
    }
  }
}

// we use @defined($muex) and @defined($rwlock) here because
// on 64 bit systems, the wildcard search takes us through
// both 64 bit and 32 bit libc (which doesn't have debuginfo),
// this means the probe point resolved from the 32 bit library
// has no context info
probe process("/lib*/libc.so*").function("pthread_mutex_init")
{
  if(@defined($mutex))
    process_mutex_init($mutex, ppfunc())
}
probe process("/lib*/libpthread.so*").function("__pthread_mutex_init")
{
  if(@defined($mutex))
    process_mutex_init($mutex, ppfunc())
}
probe process("/lib*/libpthread.so*").function("__pthread_rwlock_init")
{
  if(@defined($rwlock))
    process_mutex_init($rwlock, ppfunc())
}

global entry_times%, uaddrs%

probe syscall.futex {
  if (pid() != target()) next		// skip irrelevant processes
  if ((op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) next
  entry_times[tid()] = gettimeofday_us()
  uaddrs[tid()] = futex_uaddr
}

probe syscall.futex.return
{
  if (!(tid() in entry_times)) next
  entry = entry_times[tid()]
  delete entry_times[tid()]

  uaddr = uaddrs[tid()]
  delete uaddrs[tid()]

  elapsed = gettimeofday_us() - entry
  if (keep_stats) {
    mutex_contention[uaddr] <<< elapsed
    stack = sprint_ubacktrace()
    mutex_last_cont_stack[uaddr] = stack
    mutex_cont_stack[stack] <<< elapsed
    if (uaddr in mutex_init_stack) {
      if (verbose) {
        printf("contention time %d on mutex %p initialized at\n%s\n",
	       elapsed, uaddr, mutex_init_stack[uaddr])
      }
    }
    else if (uaddr in mutex_uninit) {
      if (verbose) {
        printf("contention time %d on popup mutex %p at\n%s\n",
	       elapsed, uaddr, stack)
      }
    }
    else {
      if (verbose) {
        printf("contention time %d on popup mutex %p at\n%s\n",
	       elapsed, uaddr, stack)
      }
      mutex_uninit[uaddr] = stack
      mutex_names[uaddr] = usymdata (uaddr)
    }
  }
  else {
    printf("contention %p elapsed %d at\n%s\n", uaddr, elapsed,
	   sprint_ubacktrace())
  }
}

probe end
{
  if (!keep_stats) {
    printf("======== END\n")
    next
  }
  printf("<<<<<<<< aggregate stats\n")
  foreach (stack in mutex_cont_stack-) {
    count = @count(mutex_cont_stack[stack])
    max = @max(mutex_cont_stack[stack])
    if ((count > cont_count_threshold) || (max > cont_max_threshold)) {
      printf("=======================================\nstack contended %d times, %d avg usec, %d max usec, %d total usec, at\n%s\n",
	     @count(mutex_cont_stack[stack]), @avg(mutex_cont_stack[stack]),
	     @max(mutex_cont_stack[stack]), @sum(mutex_cont_stack[stack]),
	     stack)
    }
  }
  printf(">>>>>>>> aggregate stats\n")
  foreach (mutex in mutex_contention-) {
    if (mutex in mutex_init_stack) {
      stack = mutex_init_stack[mutex]
      type = "init"
    }
    else if (mutex in mutex_uninit) {
      stack = mutex_uninit[mutex]
      type = "popup"
    }
    show_contention(mutex, stack, type)
  }
}