Messages in this thread Patch in this message | | | Date | Thu, 16 Oct 2008 17:04:30 -0400 | From | Jason Baron <> | Subject | tracepoints for kernel/mutex.c |
| |
hi,
Below are 3 tracepoints I've been playing with in kernel/mutex.c using a SystemTap script. The idea is to detect and determine the cause of lock contention. Currently I get the following output:
<contended mutex nam> <process name and pid of the contention> <time of contention> <pid that woke me up(caused the contention?)>
for example:
name: &inode->i_mutex, pid name: udevd, pid: 26567, jiffies: 1 cause: 26566
Using SystemTap I can now modify my script to figure out the inode number, the file and pathname, or the backtrace and get to the bottom of the contention.
I think this approach has a number of advantages. It has low overhead in the off case, since its based on tracepoints. It is minimally invasive in the code path (3 tracepoints). It also allows me to explore data structures and parts of the kernel by simply modifying the SystemTap script. I do not need to re-compile the kernel and reboot.
You can run the script via: $stap mutex.stp
thanks,
-Jason
diff --git a/include/trace/mutex.h b/include/trace/mutex.h new file mode 100644 index 0000000..8d365d6 --- /dev/null +++ b/include/trace/mutex.h @@ -0,0 +1,10 @@ +#ifndef _TRACE_MUTEX_H +#define _TRACE_MUTEX_H + +#include <linux/tracepoint.h> + +DEFINE_TRACE(mutex_lock_contention, TPPROTO(int pid, unsigned long time), TPARGS(pid, time)); +DEFINE_TRACE(mutex_lock_contention_length, TPPROTO(char *name, int pid, unsigned long time), TPARGS(name, pid, time)); +DEFINE_TRACE(mutex_wakeup, TPPROTO(int target_pid, int sender_pid), TPARGS(target_pid, sender_pid)); + +#endif diff --git a/kernel/mutex-debug.c b/kernel/mutex-debug.c index 1d94160..847a9fb 100644 --- a/kernel/mutex-debug.c +++ b/kernel/mutex-debug.c @@ -97,6 +97,7 @@ void debug_mutex_init(struct mutex *lock, const char *name, #endif lock->owner = NULL; lock->magic = lock; + lock->name = name; } /*** diff --git a/kernel/mutex.c b/kernel/mutex.c index 12c779d..62c2aab 100644 --- a/kernel/mutex.c +++ b/kernel/mutex.c @@ -18,6 +18,7 @@ #include <linux/spinlock.h> #include <linux/interrupt.h> #include <linux/debug_locks.h> +#include <trace/mutex.h> /* * In the DEBUG case we are using the "NULL fastpath" for mutexes, @@ -147,6 +148,7 @@ __mutex_lock_common(struct mutex *lock, long state, unsigned int subclass, goto done; lock_contended(&lock->dep_map, ip); + trace_mutex_lock_contention((int)task->pid, jiffies); for (;;) { /* @@ -182,7 +184,7 @@ __mutex_lock_common(struct mutex *lock, long state, unsigned int subclass, schedule(); spin_lock_mutex(&lock->wait_lock, flags); } - + trace_mutex_lock_contention_length(lock->name, (int)task->pid, jiffies); done: lock_acquired(&lock->dep_map); /* got the lock - rejoice! */ @@ -256,7 +258,7 @@ __mutex_unlock_common_slowpath(atomic_t *lock_count, int nested) struct mutex_waiter, list); debug_mutex_wake_waiter(lock, waiter); - + trace_mutex_wakeup(waiter->task->pid, current->pid); wake_up_process(waiter->task); } diff --git a/ltt/probes/Makefile b/ltt/probes/Makefile index 2ee8a46..0c54d01 100644 --- a/ltt/probes/Makefile +++ b/ltt/probes/Makefile @@ -10,7 +10,8 @@ CFLAGS_REMOVE_rcu-trace.o = -pg endif obj-$(CONFIG_LTT_TRACEPROBES) += kernel-trace.o mm-trace.o fs-trace.o \ - ipc-trace.o lockdep-trace.o rcu-trace.o + ipc-trace.o lockdep-trace.o rcu-trace.o \ + mutex-trace.o ifeq ($(CONFIG_NET),y) ifdef CONFIG_FTRACE diff --git a/ltt/probes/mutex-trace.c b/ltt/probes/mutex-trace.c new file mode 100644 index 0000000..3b1ebeb --- /dev/null +++ b/ltt/probes/mutex-trace.c @@ -0,0 +1,43 @@ +/* + * ltt/probes/fs-trace.c + * + * Mutex tracepoint probes. + */ + +#include <linux/module.h> +#include <trace/mutex.h> + +static unsigned long mutex_times[PID_MAX_DEFAULT+1]; +static int mutex_wakeup[PID_MAX_DEFAULT+1]; + +void probe_mutex_lock_contention(int pid, unsigned long time) +{ + mutex_times[pid] = (unsigned long)time; + + trace_mark_tp(mutex_lock_contention, mutex_lock_contention, + probe_mutex_lock_contention, "pid %d time %lu", pid, time); +} + +void probe_mutex_lock_contention_length(char *name, int pid, unsigned long time) +{ + unsigned long delay = time - mutex_times[pid]; + int reason = mutex_wakeup[pid]; + + /* FIXME: why is name sometimes null? */ + if (!name) + return; + + trace_mark_tp(mutex_lock_contention_length, mutex_lock_contention_length, + probe_mutex_lock_contention_length, + "name %s pid %d delay %lu cause %d", + name, pid, delay, reason); +} + +void probe_mutex_wakeup(int target_pid, int sender_pid) +{ + mutex_wakeup[target_pid] = sender_pid; + + trace_mark_tp(mutex_wakeup, mutex_wakeup, + probe_mutex_wakeup, "pid %d pid %d", target_pid, sender_pid); +} +
# mutex.stp
probe kernel.mark("mutex_lock_contention") { } probe kernel.mark("mutex_wakeup") { } probe kernel.mark("mutex_lock_contention_length") { name = $arg1 pid = $arg2 delay = $arg3 cause = $arg4 printf("name: %s, pid name: %s, pid: %d, jiffies: %d cause: %d\n", name, execname(), pid, delay, cause); }
| |