futexes.stp report negative values

futexes.stp report negative values

[Mingfan Lu]

I am using the futexes.stp(http://sourceware.org/systemtap/examples/process/futexes.stp)
from to analyze the mutex contention. But I got negative values of
average contention time.
e.g.
memcached[5395] lock 0x22f9eb0 contended 26847 times, -143 avg us
memcached[5395] lock 0x22ee9e8 contended 467469 times, -110 avg us
memcached[5395] lock 0x612600 contended 13215 times, -53 avg us
memcached[5395] lock 0x230ea88 contended 3 times, 16 avg us
memcached[5395] lock 0x22f5660 contended 35136 times, -118 avg us
memcached[5395] lock 0x7f4b8c97be40 contended 31 times, -69 avg us
memcached[5395] lock 0x2300b28 contended 23907 times, -117 avg us
memcached[5395] lock 0x2319ec8 contended 4 times, 5 avg us
memcached[5395] lock 0x22ec5c0 contended 32502 times, -89 avg us
memcached[5395] lock 0x22f0e10 contended 28022 times, -93 avg us
memcached[5395] lock 0x22fc2d8 contended 22641 times, -98 avg us
memcached[5395] lock 0x6152c0 contended 6869 times, -45 avg us
memcached[5395] lock 0x22fe700 contended 21250 times, -133 avg us
memcached[5395] lock 0x230bd78 contended 4 times, 8 avg us
memcached[5395] lock 0x22f3238 contended 25635 times, -117 avg us
memcached[5395] lock 0x22f7a88 contended 24542 times, -137 avg us
memcached[5395] lock 0x7f4b74000020 contended 3 times, 5 avg us
memcached[5395] lock 0x7f4b78000020 contended 1 times, 3 avg us
memcached[5395] lock 0x2311798 contended 4 times, 7 avg us
memcached[5395] lock 0x2309068 contended 1 times, 2 avg us

Is possible to get such confused result or a bug?
I could not understand the new @entry operator.
----------------------------------------------------------------------------------------
#! /usr/bin/env stap

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

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+ */

global lock_waits # long-lived stats on (tid,lock) blockage elapsed time
global process_names # long-lived pid-to-execname mapping

probe syscall.futex.return {
  if (($op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) next
  process_names[pid()] = execname()
  elapsed = gettimeofday_us() - @entry(gettimeofday_us())
  lock_waits[pid(), $uaddr] <<< elapsed
}

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]))
}