[PATCH] tracing: lockdep tracepoints

[PATCH] tracing: lockdep tracepoints

[Peter Zijlstra]

Lets add LKML this time :-)

---
Subject: tracing: lockdep tracepoints
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Tue Mar 03 22:03:08 CET 2009

Augment the traces with lock names when lockdep is available:

 1)               |  down_read_trylock() {
 1)               |    _spin_lock_irqsave() {
 1)               |      /* lock_acquire: name: &sem->wait_lock */
 1)   4.201 us    |    }
 1)               |    _spin_unlock_irqrestore() {
 1)               |      /* lock_release: name: &sem->wait_lock */
 1)   3.523 us    |    }
 1)               |  /* lock_acquire: try read name: &mm->mmap_sem */
 1) + 13.386 us   |  }
 1)   1.635 us    |  find_vma();
 1)               |  handle_mm_fault() {
 1)               |    __do_fault() {
 1)               |      filemap_fault() {
 1)               |        find_lock_page() {
 1)               |          find_get_page() {
 1)               |            /* lock_acquire: read name: rcu_read_lock */
 1)               |            /* lock_release: name: rcu_read_lock */
 1)   5.697 us    |          }
 1)   8.158 us    |        }
 1) + 11.079 us   |      }
 1)               |      _spin_lock() {
 1)               |        /* lock_acquire: name: __pte_lockptr(page) */
 1)   3.949 us    |      }
 1)   1.460 us    |      page_add_file_rmap();
 1)               |      _spin_unlock() {
 1)               |        /* lock_release: name: __pte_lockptr(page) */
 1)   3.115 us    |      }
 1)               |      unlock_page() {
 1)   1.421 us    |        page_waitqueue();
 1)   1.220 us    |        __wake_up_bit();
 1)   6.519 us    |      }
 1) + 34.328 us   |    }
 1) + 37.452 us   |  }
 1)               |  up_read() {
 1)               |  /* lock_release: name: &mm->mmap_sem */
 1)               |    _spin_lock_irqsave() {
 1)               |      /* lock_acquire: name: &sem->wait_lock */
 1)   3.865 us    |    }
 1)               |    _spin_unlock_irqrestore() {
 1)               |      /* lock_release: name: &sem->wait_lock */
 1)   8.562 us    |    }
 1) + 17.370 us   |  }

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 include/trace/lockdep.h             |    9 +++++++
 include/trace/lockdep_event_types.h |   44 ++++++++++++++++++++++++++++++++++++
 include/trace/trace_event_types.h   |    1 
 include/trace/trace_events.h        |    1 
 kernel/lockdep.c                    |   17 +++++++++++++
 kernel/trace/trace.c                |   14 ++++++-----
 kernel/trace/trace_events_stage_3.h |    4 +--
 7 files changed, 82 insertions(+), 8 deletions(-)

Index: linux-2.6/include/trace/lockdep.h
===================================================================
--- /dev/null
+++ linux-2.6/include/trace/lockdep.h
@@ -0,0 +1,9 @@
+#ifndef _TRACE_LOCKDEP_H
+#define _TRACE_LOCKDEP_H
+
+#include <linux/lockdep.h>
+#include <linux/tracepoint.h>
+
+#include <trace/lockdep_event_types.h>
+
+#endif
Index: linux-2.6/include/trace/lockdep_event_types.h
===================================================================
--- /dev/null
+++ linux-2.6/include/trace/lockdep_event_types.h
@@ -0,0 +1,44 @@
+
+#ifndef TRACE_EVENT_FORMAT
+# error Do not include this file directly.
+# error Unless you know what you are doing.
+#endif
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM lock
+
+#ifdef CONFIG_LOCKDEP
+
+TRACE_FORMAT(lock_acquire,
+	TPPROTO(struct lockdep_map *lock, unsigned int subclass,
+		int trylock, int read, int check,
+		struct lockdep_map *next_lock, unsigned long ip),
+	TPARGS(lock, subclass, trylock, read, check, next_lock, ip),
+	TPFMT("%s%sname: %s", trylock ? "try " : "",
+		read ? "read " : "", lock->name)
+	);
+
+TRACE_FORMAT(lock_release,
+	TPPROTO(struct lockdep_map *lock, int nested, unsigned long ip),
+	TPARGS(lock, nested, ip),
+	TPFMT("name: %s", lock->name)
+	);
+
+#ifdef CONFIG_LOCK_STAT
+
+TRACE_FORMAT(lock_contended,
+	TPPROTO(struct lockdep_map *lock, unsigned long ip),
+	TPARGS(lock, ip),
+	TPFMT("name: %s", lock->name)
+	);
+
+TRACE_FORMAT(lock_acquired,
+	TPPROTO(struct lockdep_map *lock, unsigned long ip),
+	TPARGS(lock, ip),
+	TPFMT("name: %s", lock->name)
+	);
+
+#endif
+#endif
+
+#undef TRACE_SYSTEM
Index: linux-2.6/include/trace/trace_events.h
===================================================================
--- linux-2.6.orig/include/trace/trace_events.h
+++ linux-2.6/include/trace/trace_events.h
@@ -2,3 +2,4 @@
 
 #include <trace/sched.h>
 #include <trace/irq.h>
+#include <trace/lockdep.h>
Index: linux-2.6/kernel/lockdep.c
===================================================================
--- linux-2.6.orig/kernel/lockdep.c
+++ linux-2.6/kernel/lockdep.c
@@ -42,6 +42,7 @@
 #include <linux/hash.h>
 #include <linux/ftrace.h>
 #include <linux/stringify.h>
+#include <trace/lockdep.h>
 
 #include <asm/sections.h>
 
@@ -2912,6 +2913,8 @@ void lock_set_class(struct lockdep_map *
 }
 EXPORT_SYMBOL_GPL(lock_set_class);
 
+DEFINE_TRACE(lock_acquire);
+
 /*
  * We are not always called with irqs disabled - do that here,
  * and also avoid lockdep recursion:
@@ -2922,6 +2925,8 @@ void lock_acquire(struct lockdep_map *lo
 {
 	unsigned long flags;
 
+	trace_lock_acquire(lock, subclass, trylock, read, check, nest_lock, ip);
+
 	if (unlikely(current->lockdep_recursion))
 		return;
 
@@ -2936,11 +2941,15 @@ void lock_acquire(struct lockdep_map *lo
 }
 EXPORT_SYMBOL_GPL(lock_acquire);
 
+DEFINE_TRACE(lock_release);
+
 void lock_release(struct lockdep_map *lock, int nested,
 			  unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_release(lock, nested, ip);
+
 	if (unlikely(current->lockdep_recursion))
 		return;
 
@@ -3089,10 +3098,14 @@ found_it:
 	lock->ip = ip;
 }
 
+DEFINE_TRACE(lock_contended);
+
 void lock_contended(struct lockdep_map *lock, unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_contended(lock, ip);
+
 	if (unlikely(!lock_stat))
 		return;
 
@@ -3108,10 +3121,14 @@ void lock_contended(struct lockdep_map *
 }
 EXPORT_SYMBOL_GPL(lock_contended);
 
+DEFINE_TRACE(lock_acquired);
+
 void lock_acquired(struct lockdep_map *lock, unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_acquired(lock, ip);
+
 	if (unlikely(!lock_stat))
 		return;
 
Index: linux-2.6/kernel/trace/trace.c
===================================================================
--- linux-2.6.orig/kernel/trace/trace.c
+++ linux-2.6/kernel/trace/trace.c
@@ -624,7 +624,7 @@ static unsigned map_pid_to_cmdline[PID_M
 static unsigned map_cmdline_to_pid[SAVED_CMDLINES];
 static char saved_cmdlines[SAVED_CMDLINES][TASK_COMM_LEN];
 static int cmdline_idx;
-static DEFINE_SPINLOCK(trace_cmdline_lock);
+static raw_spinlock_t trace_cmdline_lock = __RAW_SPIN_LOCK_UNLOCKED;
 
 /* temporary disable recording */
 static atomic_t trace_record_cmdline_disabled __read_mostly;
@@ -736,7 +736,7 @@ static void trace_save_cmdline(struct ta
 	 * nor do we want to disable interrupts,
 	 * so if we miss here, then better luck next time.
 	 */
-	if (!spin_trylock(&trace_cmdline_lock))
+	if (!__raw_spin_trylock(&trace_cmdline_lock))
 		return;
 
 	idx = map_pid_to_cmdline[tsk->pid];
@@ -754,7 +754,7 @@ static void trace_save_cmdline(struct ta
 
 	memcpy(&saved_cmdlines[idx], tsk->comm, TASK_COMM_LEN);
 
-	spin_unlock(&trace_cmdline_lock);
+	__raw_spin_unlock(&trace_cmdline_lock);
 }
 
 char *trace_find_cmdline(int pid)
@@ -3491,7 +3491,7 @@ static __init int tracer_init_debugfs(vo
 
 int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 {
-	static DEFINE_SPINLOCK(trace_buf_lock);
+	static raw_spinlock_t trace_buf_lock = __RAW_SPIN_LOCK_UNLOCKED;
 	static char trace_buf[TRACE_BUF_SIZE];
 
 	struct ring_buffer_event *event;
@@ -3513,7 +3513,8 @@ int trace_vprintk(unsigned long ip, int 
 		goto out;
 
 	pause_graph_tracing();
-	spin_lock_irqsave(&trace_buf_lock, irq_flags);
+	raw_local_irq_save(irq_flags);
+	__raw_spin_lock(&trace_buf_lock);
 	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
 
 	len = min(len, TRACE_BUF_SIZE-1);
@@ -3532,7 +3533,8 @@ int trace_vprintk(unsigned long ip, int 
 	ring_buffer_unlock_commit(tr->buffer, event);
 
  out_unlock:
-	spin_unlock_irqrestore(&trace_buf_lock, irq_flags);
+	__raw_spin_unlock(&trace_buf_lock);
+	raw_local_irq_restore(irq_flags);
 	unpause_graph_tracing();
  out:
 	preempt_enable_notrace();
Index: linux-2.6/kernel/trace/trace_events_stage_3.h
===================================================================
--- linux-2.6.orig/kernel/trace/trace_events_stage_3.h
+++ linux-2.6/kernel/trace/trace_events_stage_3.h
@@ -5,7 +5,7 @@
  *
  * static void ftrace_event_<call>(proto)
  * {
- * 	event_trace_printk(_RET_IP_, "(<call>) " <fmt>);
+ * 	event_trace_printk(_RET_IP_, "<call>: " <fmt>);
  * }
  *
  * static int ftrace_reg_event_<call>(void)
@@ -112,7 +112,7 @@
 #define _TRACE_FORMAT(call, proto, args, fmt)				\
 static void ftrace_event_##call(proto)					\
 {									\
-	event_trace_printk(_RET_IP_, "(" #call ") " fmt);		\
+	event_trace_printk(_RET_IP_, #call ": " fmt);			\
 }									\
 									\
 static int ftrace_reg_event_##call(void)				\
Index: linux-2.6/include/trace/trace_event_types.h
===================================================================
--- linux-2.6.orig/include/trace/trace_event_types.h
+++ linux-2.6/include/trace/trace_event_types.h
@@ -2,3 +2,4 @@
 
 #include <trace/sched_event_types.h>
 #include <trace/irq_event_types.h>
+#include <trace/lockdep_event_types.h>

Re: [PATCH] tracing: lockdep tracepoints

[Frederic Weisbecker]

On Wed, Mar 04, 2009 at 12:03:06PM +0100, Peter Zijlstra wrote:
> Lets add LKML this time :-)
> 
> ---
> Subject: tracing: lockdep tracepoints
> From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Date: Tue Mar 03 22:03:08 CET 2009
> 
> Augment the traces with lock names when lockdep is available:
> 
>  1)               |  down_read_trylock() {
>  1)               |    _spin_lock_irqsave() {
>  1)               |      /* lock_acquire: name: &sem->wait_lock */
>  1)   4.201 us    |    }
>  1)               |    _spin_unlock_irqrestore() {
>  1)               |      /* lock_release: name: &sem->wait_lock */

Nice idea.
I would just suggest to drop the "name:" since the comment is intuitive enough
to figure out what we have after lock_{release,acquire}: 

Frederic.


>  1)   3.523 us    |    }
>  1)               |  /* lock_acquire: try read name: &mm->mmap_sem */
>  1) + 13.386 us   |  }
>  1)   1.635 us    |  find_vma();
>  1)               |  handle_mm_fault() {
>  1)               |    __do_fault() {
>  1)               |      filemap_fault() {
>  1)               |        find_lock_page() {
>  1)               |          find_get_page() {
>  1)               |            /* lock_acquire: read name: rcu_read_lock */
>  1)               |            /* lock_release: name: rcu_read_lock */
>  1)   5.697 us    |          }
>  1)   8.158 us    |        }
>  1) + 11.079 us   |      }
>  1)               |      _spin_lock() {
>  1)               |        /* lock_acquire: name: __pte_lockptr(page) */
>  1)   3.949 us    |      }
>  1)   1.460 us    |      page_add_file_rmap();
>  1)               |      _spin_unlock() {
>  1)               |        /* lock_release: name: __pte_lockptr(page) */
>  1)   3.115 us    |      }
>  1)               |      unlock_page() {
>  1)   1.421 us    |        page_waitqueue();
>  1)   1.220 us    |        __wake_up_bit();
>  1)   6.519 us    |      }
>  1) + 34.328 us   |    }
>  1) + 37.452 us   |  }
>  1)               |  up_read() {
>  1)               |  /* lock_release: name: &mm->mmap_sem */
>  1)               |    _spin_lock_irqsave() {
>  1)               |      /* lock_acquire: name: &sem->wait_lock */
>  1)   3.865 us    |    }
>  1)               |    _spin_unlock_irqrestore() {
>  1)               |      /* lock_release: name: &sem->wait_lock */
>  1)   8.562 us    |    }
>  1) + 17.370 us   |  }
> 
> Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
> ---
>  include/trace/lockdep.h             |    9 +++++++
>  include/trace/lockdep_event_types.h |   44 ++++++++++++++++++++++++++++++++++++
>  include/trace/trace_event_types.h   |    1 
>  include/trace/trace_events.h        |    1 
>  kernel/lockdep.c                    |   17 +++++++++++++
>  kernel/trace/trace.c                |   14 ++++++-----
>  kernel/trace/trace_events_stage_3.h |    4 +--
>  7 files changed, 82 insertions(+), 8 deletions(-)
> 
> Index: linux-2.6/include/trace/lockdep.h
> ===================================================================
> --- /dev/null
> +++ linux-2.6/include/trace/lockdep.h
> @@ -0,0 +1,9 @@
> +#ifndef _TRACE_LOCKDEP_H
> +#define _TRACE_LOCKDEP_H
> +
> +#include <linux/lockdep.h>
> +#include <linux/tracepoint.h>
> +
> +#include <trace/lockdep_event_types.h>
> +
> +#endif
> Index: linux-2.6/include/trace/lockdep_event_types.h
> ===================================================================
> --- /dev/null
> +++ linux-2.6/include/trace/lockdep_event_types.h
> @@ -0,0 +1,44 @@
> +
> +#ifndef TRACE_EVENT_FORMAT
> +# error Do not include this file directly.
> +# error Unless you know what you are doing.
> +#endif
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM lock
> +
> +#ifdef CONFIG_LOCKDEP
> +
> +TRACE_FORMAT(lock_acquire,
> +	TPPROTO(struct lockdep_map *lock, unsigned int subclass,
> +		int trylock, int read, int check,
> +		struct lockdep_map *next_lock, unsigned long ip),
> +	TPARGS(lock, subclass, trylock, read, check, next_lock, ip),
> +	TPFMT("%s%sname: %s", trylock ? "try " : "",
> +		read ? "read " : "", lock->name)
> +	);
> +
> +TRACE_FORMAT(lock_release,
> +	TPPROTO(struct lockdep_map *lock, int nested, unsigned long ip),
> +	TPARGS(lock, nested, ip),
> +	TPFMT("name: %s", lock->name)
> +	);
> +
> +#ifdef CONFIG_LOCK_STAT
> +
> +TRACE_FORMAT(lock_contended,
> +	TPPROTO(struct lockdep_map *lock, unsigned long ip),
> +	TPARGS(lock, ip),
> +	TPFMT("name: %s", lock->name)
> +	);
> +
> +TRACE_FORMAT(lock_acquired,
> +	TPPROTO(struct lockdep_map *lock, unsigned long ip),
> +	TPARGS(lock, ip),
> +	TPFMT("name: %s", lock->name)
> +	);
> +
> +#endif
> +#endif
> +
> +#undef TRACE_SYSTEM
> Index: linux-2.6/include/trace/trace_events.h
> ===================================================================
> --- linux-2.6.orig/include/trace/trace_events.h
> +++ linux-2.6/include/trace/trace_events.h
> @@ -2,3 +2,4 @@
>  
>  #include <trace/sched.h>
>  #include <trace/irq.h>
> +#include <trace/lockdep.h>
> Index: linux-2.6/kernel/lockdep.c
> ===================================================================
> --- linux-2.6.orig/kernel/lockdep.c
> +++ linux-2.6/kernel/lockdep.c
> @@ -42,6 +42,7 @@
>  #include <linux/hash.h>
>  #include <linux/ftrace.h>
>  #include <linux/stringify.h>
> +#include <trace/lockdep.h>
>  
>  #include <asm/sections.h>
>  
> @@ -2912,6 +2913,8 @@ void lock_set_class(struct lockdep_map *
>  }
>  EXPORT_SYMBOL_GPL(lock_set_class);
>  
> +DEFINE_TRACE(lock_acquire);
> +
>  /*
>   * We are not always called with irqs disabled - do that here,
>   * and also avoid lockdep recursion:
> @@ -2922,6 +2925,8 @@ void lock_acquire(struct lockdep_map *lo
>  {
>  	unsigned long flags;
>  
> +	trace_lock_acquire(lock, subclass, trylock, read, check, nest_lock, ip);
> +
>  	if (unlikely(current->lockdep_recursion))
>  		return;
>  
> @@ -2936,11 +2941,15 @@ void lock_acquire(struct lockdep_map *lo
>  }
>  EXPORT_SYMBOL_GPL(lock_acquire);
>  
> +DEFINE_TRACE(lock_release);
> +
>  void lock_release(struct lockdep_map *lock, int nested,
>  			  unsigned long ip)
>  {
>  	unsigned long flags;
>  
> +	trace_lock_release(lock, nested, ip);
> +
>  	if (unlikely(current->lockdep_recursion))
>  		return;
>  
> @@ -3089,10 +3098,14 @@ found_it:
>  	lock->ip = ip;
>  }
>  
> +DEFINE_TRACE(lock_contended);
> +
>  void lock_contended(struct lockdep_map *lock, unsigned long ip)
>  {
>  	unsigned long flags;
>  
> +	trace_lock_contended(lock, ip);
> +
>  	if (unlikely(!lock_stat))
>  		return;
>  
> @@ -3108,10 +3121,14 @@ void lock_contended(struct lockdep_map *
>  }
>  EXPORT_SYMBOL_GPL(lock_contended);
>  
> +DEFINE_TRACE(lock_acquired);
> +
>  void lock_acquired(struct lockdep_map *lock, unsigned long ip)
>  {
>  	unsigned long flags;
>  
> +	trace_lock_acquired(lock, ip);
> +
>  	if (unlikely(!lock_stat))
>  		return;
>  
> Index: linux-2.6/kernel/trace/trace.c
> ===================================================================
> --- linux-2.6.orig/kernel/trace/trace.c
> +++ linux-2.6/kernel/trace/trace.c
> @@ -624,7 +624,7 @@ static unsigned map_pid_to_cmdline[PID_M
>  static unsigned map_cmdline_to_pid[SAVED_CMDLINES];
>  static char saved_cmdlines[SAVED_CMDLINES][TASK_COMM_LEN];
>  static int cmdline_idx;
> -static DEFINE_SPINLOCK(trace_cmdline_lock);
> +static raw_spinlock_t trace_cmdline_lock = __RAW_SPIN_LOCK_UNLOCKED;
>  
>  /* temporary disable recording */
>  static atomic_t trace_record_cmdline_disabled __read_mostly;
> @@ -736,7 +736,7 @@ static void trace_save_cmdline(struct ta
>  	 * nor do we want to disable interrupts,
>  	 * so if we miss here, then better luck next time.
>  	 */
> -	if (!spin_trylock(&trace_cmdline_lock))
> +	if (!__raw_spin_trylock(&trace_cmdline_lock))
>  		return;
>  
>  	idx = map_pid_to_cmdline[tsk->pid];
> @@ -754,7 +754,7 @@ static void trace_save_cmdline(struct ta
>  
>  	memcpy(&saved_cmdlines[idx], tsk->comm, TASK_COMM_LEN);
>  
> -	spin_unlock(&trace_cmdline_lock);
> +	__raw_spin_unlock(&trace_cmdline_lock);
>  }
>  
>  char *trace_find_cmdline(int pid)
> @@ -3491,7 +3491,7 @@ static __init int tracer_init_debugfs(vo
>  
>  int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
>  {
> -	static DEFINE_SPINLOCK(trace_buf_lock);
> +	static raw_spinlock_t trace_buf_lock = __RAW_SPIN_LOCK_UNLOCKED;
>  	static char trace_buf[TRACE_BUF_SIZE];
>  
>  	struct ring_buffer_event *event;
> @@ -3513,7 +3513,8 @@ int trace_vprintk(unsigned long ip, int 
>  		goto out;
>  
>  	pause_graph_tracing();
> -	spin_lock_irqsave(&trace_buf_lock, irq_flags);
> +	raw_local_irq_save(irq_flags);
> +	__raw_spin_lock(&trace_buf_lock);
>  	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
>  
>  	len = min(len, TRACE_BUF_SIZE-1);
> @@ -3532,7 +3533,8 @@ int trace_vprintk(unsigned long ip, int 
>  	ring_buffer_unlock_commit(tr->buffer, event);
>  
>   out_unlock:
> -	spin_unlock_irqrestore(&trace_buf_lock, irq_flags);
> +	__raw_spin_unlock(&trace_buf_lock);
> +	raw_local_irq_restore(irq_flags);
>  	unpause_graph_tracing();
>   out:
>  	preempt_enable_notrace();
> Index: linux-2.6/kernel/trace/trace_events_stage_3.h
> ===================================================================
> --- linux-2.6.orig/kernel/trace/trace_events_stage_3.h
> +++ linux-2.6/kernel/trace/trace_events_stage_3.h
> @@ -5,7 +5,7 @@
>   *
>   * static void ftrace_event_<call>(proto)
>   * {
> - * 	event_trace_printk(_RET_IP_, "(<call>) " <fmt>);
> + * 	event_trace_printk(_RET_IP_, "<call>: " <fmt>);
>   * }
>   *
>   * static int ftrace_reg_event_<call>(void)
> @@ -112,7 +112,7 @@
>  #define _TRACE_FORMAT(call, proto, args, fmt)				\
>  static void ftrace_event_##call(proto)					\
>  {									\
> -	event_trace_printk(_RET_IP_, "(" #call ") " fmt);		\
> +	event_trace_printk(_RET_IP_, #call ": " fmt);			\
>  }									\
>  									\
>  static int ftrace_reg_event_##call(void)				\
> Index: linux-2.6/include/trace/trace_event_types.h
> ===================================================================
> --- linux-2.6.orig/include/trace/trace_event_types.h
> +++ linux-2.6/include/trace/trace_event_types.h
> @@ -2,3 +2,4 @@
>  
>  #include <trace/sched_event_types.h>
>  #include <trace/irq_event_types.h>
> +#include <trace/lockdep_event_types.h>
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

[PATCH -v2] tracing: lockdep tracepoints

[Peter Zijlstra]

On Wed, 2009-03-04 at 12:23 +0100, Frederic Weisbecker wrote:
> > ---
> > Subject: tracing: lockdep tracepoints
> > From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > Date: Tue Mar 03 22:03:08 CET 2009
> > 
> > Augment the traces with lock names when lockdep is available:
> > 
> >  1)               |  down_read_trylock() {
> >  1)               |    _spin_lock_irqsave() {
> >  1)               |      /* lock_acquire: name: &sem->wait_lock */
> >  1)   4.201 us    |    }
> >  1)               |    _spin_unlock_irqrestore() {
> >  1)               |      /* lock_release: name: &sem->wait_lock */
> 
> Nice idea.
> I would just suggest to drop the "name:" since the comment is intuitive enough
> to figure out what we have after lock_{release,acquire}: 

Makes sense I guess..

Here goes.. one s/name: //g later

---
Subject: tracing: lockdep tracepoints
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Tue Mar 03 22:03:08 CET 2009

Augment the traces with lock names when lockdep is available:

 1)               |  down_read_trylock() {
 1)               |    _spin_lock_irqsave() {
 1)               |      /* lock_acquire: &sem->wait_lock */
 1)   4.201 us    |    }
 1)               |    _spin_unlock_irqrestore() {
 1)               |      /* lock_release: &sem->wait_lock */
 1)   3.523 us    |    }
 1)               |  /* lock_acquire: try read &mm->mmap_sem */
 1) + 13.386 us   |  }
 1)   1.635 us    |  find_vma();
 1)               |  handle_mm_fault() {
 1)               |    __do_fault() {
 1)               |      filemap_fault() {
 1)               |        find_lock_page() {
 1)               |          find_get_page() {
 1)               |            /* lock_acquire: read rcu_read_lock */
 1)               |            /* lock_release: rcu_read_lock */
 1)   5.697 us    |          }
 1)   8.158 us    |        }
 1) + 11.079 us   |      }
 1)               |      _spin_lock() {
 1)               |        /* lock_acquire: __pte_lockptr(page) */
 1)   3.949 us    |      }
 1)   1.460 us    |      page_add_file_rmap();
 1)               |      _spin_unlock() {
 1)               |        /* lock_release: __pte_lockptr(page) */
 1)   3.115 us    |      }
 1)               |      unlock_page() {
 1)   1.421 us    |        page_waitqueue();
 1)   1.220 us    |        __wake_up_bit();
 1)   6.519 us    |      }
 1) + 34.328 us   |    }
 1) + 37.452 us   |  }
 1)               |  up_read() {
 1)               |  /* lock_release: &mm->mmap_sem */
 1)               |    _spin_lock_irqsave() {
 1)               |      /* lock_acquire: &sem->wait_lock */
 1)   3.865 us    |    }
 1)               |    _spin_unlock_irqrestore() {
 1)               |      /* lock_release: &sem->wait_lock */
 1)   8.562 us    |    }
 1) + 17.370 us   |  }

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 include/trace/lockdep.h             |    9 +++++++
 include/trace/lockdep_event_types.h |   44 ++++++++++++++++++++++++++++++++++++
 include/trace/trace_event_types.h   |    1 
 include/trace/trace_events.h        |    1 
 kernel/lockdep.c                    |   17 +++++++++++++
 kernel/trace/trace.c                |   14 ++++++-----
 kernel/trace/trace_events_stage_3.h |    4 +--
 7 files changed, 82 insertions(+), 8 deletions(-)

Index: linux-2.6/include/trace/lockdep.h
===================================================================
--- /dev/null
+++ linux-2.6/include/trace/lockdep.h
@@ -0,0 +1,9 @@
+#ifndef _TRACE_LOCKDEP_H
+#define _TRACE_LOCKDEP_H
+
+#include <linux/lockdep.h>
+#include <linux/tracepoint.h>
+
+#include <trace/lockdep_event_types.h>
+
+#endif
Index: linux-2.6/include/trace/lockdep_event_types.h
===================================================================
--- /dev/null
+++ linux-2.6/include/trace/lockdep_event_types.h
@@ -0,0 +1,44 @@
+
+#ifndef TRACE_EVENT_FORMAT
+# error Do not include this file directly.
+# error Unless you know what you are doing.
+#endif
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM lock
+
+#ifdef CONFIG_LOCKDEP
+
+TRACE_FORMAT(lock_acquire,
+	TPPROTO(struct lockdep_map *lock, unsigned int subclass,
+		int trylock, int read, int check,
+		struct lockdep_map *next_lock, unsigned long ip),
+	TPARGS(lock, subclass, trylock, read, check, next_lock, ip),
+	TPFMT("%s%s%s", trylock ? "try " : "",
+		read ? "read " : "", lock->name)
+	);
+
+TRACE_FORMAT(lock_release,
+	TPPROTO(struct lockdep_map *lock, int nested, unsigned long ip),
+	TPARGS(lock, nested, ip),
+	TPFMT("%s", lock->name)
+	);
+
+#ifdef CONFIG_LOCK_STAT
+
+TRACE_FORMAT(lock_contended,
+	TPPROTO(struct lockdep_map *lock, unsigned long ip),
+	TPARGS(lock, ip),
+	TPFMT("%s", lock->name)
+	);
+
+TRACE_FORMAT(lock_acquired,
+	TPPROTO(struct lockdep_map *lock, unsigned long ip),
+	TPARGS(lock, ip),
+	TPFMT("%s", lock->name)
+	);
+
+#endif
+#endif
+
+#undef TRACE_SYSTEM
Index: linux-2.6/include/trace/trace_events.h
===================================================================
--- linux-2.6.orig/include/trace/trace_events.h
+++ linux-2.6/include/trace/trace_events.h
@@ -2,3 +2,4 @@
 
 #include <trace/sched.h>
 #include <trace/irq.h>
+#include <trace/lockdep.h>
Index: linux-2.6/kernel/lockdep.c
===================================================================
--- linux-2.6.orig/kernel/lockdep.c
+++ linux-2.6/kernel/lockdep.c
@@ -42,6 +42,7 @@
 #include <linux/hash.h>
 #include <linux/ftrace.h>
 #include <linux/stringify.h>
+#include <trace/lockdep.h>
 
 #include <asm/sections.h>
 
@@ -2912,6 +2913,8 @@ void lock_set_class(struct lockdep_map *
 }
 EXPORT_SYMBOL_GPL(lock_set_class);
 
+DEFINE_TRACE(lock_acquire);
+
 /*
  * We are not always called with irqs disabled - do that here,
  * and also avoid lockdep recursion:
@@ -2922,6 +2925,8 @@ void lock_acquire(struct lockdep_map *lo
 {
 	unsigned long flags;
 
+	trace_lock_acquire(lock, subclass, trylock, read, check, nest_lock, ip);
+
 	if (unlikely(current->lockdep_recursion))
 		return;
 
@@ -2936,11 +2941,15 @@ void lock_acquire(struct lockdep_map *lo
 }
 EXPORT_SYMBOL_GPL(lock_acquire);
 
+DEFINE_TRACE(lock_release);
+
 void lock_release(struct lockdep_map *lock, int nested,
 			  unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_release(lock, nested, ip);
+
 	if (unlikely(current->lockdep_recursion))
 		return;
 
@@ -3089,10 +3098,14 @@ found_it:
 	lock->ip = ip;
 }
 
+DEFINE_TRACE(lock_contended);
+
 void lock_contended(struct lockdep_map *lock, unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_contended(lock, ip);
+
 	if (unlikely(!lock_stat))
 		return;
 
@@ -3108,10 +3121,14 @@ void lock_contended(struct lockdep_map *
 }
 EXPORT_SYMBOL_GPL(lock_contended);
 
+DEFINE_TRACE(lock_acquired);
+
 void lock_acquired(struct lockdep_map *lock, unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_acquired(lock, ip);
+
 	if (unlikely(!lock_stat))
 		return;
 
Index: linux-2.6/kernel/trace/trace.c
===================================================================
--- linux-2.6.orig/kernel/trace/trace.c
+++ linux-2.6/kernel/trace/trace.c
@@ -624,7 +624,7 @@ static unsigned map_pid_to_cmdline[PID_M
 static unsigned map_cmdline_to_pid[SAVED_CMDLINES];
 static char saved_cmdlines[SAVED_CMDLINES][TASK_COMM_LEN];
 static int cmdline_idx;
-static DEFINE_SPINLOCK(trace_cmdline_lock);
+static raw_spinlock_t trace_cmdline_lock = __RAW_SPIN_LOCK_UNLOCKED;
 
 /* temporary disable recording */
 static atomic_t trace_record_cmdline_disabled __read_mostly;
@@ -736,7 +736,7 @@ static void trace_save_cmdline(struct ta
 	 * nor do we want to disable interrupts,
 	 * so if we miss here, then better luck next time.
 	 */
-	if (!spin_trylock(&trace_cmdline_lock))
+	if (!__raw_spin_trylock(&trace_cmdline_lock))
 		return;
 
 	idx = map_pid_to_cmdline[tsk->pid];
@@ -754,7 +754,7 @@ static void trace_save_cmdline(struct ta
 
 	memcpy(&saved_cmdlines[idx], tsk->comm, TASK_COMM_LEN);
 
-	spin_unlock(&trace_cmdline_lock);
+	__raw_spin_unlock(&trace_cmdline_lock);
 }
 
 char *trace_find_cmdline(int pid)
@@ -3491,7 +3491,7 @@ static __init int tracer_init_debugfs(vo
 
 int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 {
-	static DEFINE_SPINLOCK(trace_buf_lock);
+	static raw_spinlock_t trace_buf_lock = __RAW_SPIN_LOCK_UNLOCKED;
 	static char trace_buf[TRACE_BUF_SIZE];
 
 	struct ring_buffer_event *event;
@@ -3513,7 +3513,8 @@ int trace_vprintk(unsigned long ip, int 
 		goto out;
 
 	pause_graph_tracing();
-	spin_lock_irqsave(&trace_buf_lock, irq_flags);
+	raw_local_irq_save(irq_flags);
+	__raw_spin_lock(&trace_buf_lock);
 	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
 
 	len = min(len, TRACE_BUF_SIZE-1);
@@ -3532,7 +3533,8 @@ int trace_vprintk(unsigned long ip, int 
 	ring_buffer_unlock_commit(tr->buffer, event);
 
  out_unlock:
-	spin_unlock_irqrestore(&trace_buf_lock, irq_flags);
+	__raw_spin_unlock(&trace_buf_lock);
+	raw_local_irq_restore(irq_flags);
 	unpause_graph_tracing();
  out:
 	preempt_enable_notrace();
Index: linux-2.6/kernel/trace/trace_events_stage_3.h
===================================================================
--- linux-2.6.orig/kernel/trace/trace_events_stage_3.h
+++ linux-2.6/kernel/trace/trace_events_stage_3.h
@@ -5,7 +5,7 @@
  *
  * static void ftrace_event_<call>(proto)
  * {
- * 	event_trace_printk(_RET_IP_, "(<call>) " <fmt>);
+ * 	event_trace_printk(_RET_IP_, "<call>: " <fmt>);
  * }
  *
  * static int ftrace_reg_event_<call>(void)
@@ -112,7 +112,7 @@
 #define _TRACE_FORMAT(call, proto, args, fmt)				\
 static void ftrace_event_##call(proto)					\
 {									\
-	event_trace_printk(_RET_IP_, "(" #call ") " fmt);		\
+	event_trace_printk(_RET_IP_, #call ": " fmt);			\
 }									\
 									\
 static int ftrace_reg_event_##call(void)				\
Index: linux-2.6/include/trace/trace_event_types.h
===================================================================
--- linux-2.6.orig/include/trace/trace_event_types.h
+++ linux-2.6/include/trace/trace_event_types.h
@@ -2,3 +2,4 @@
 
 #include <trace/sched_event_types.h>
 #include <trace/irq_event_types.h>
+#include <trace/lockdep_event_types.h>

Re: [PATCH -v2] tracing: lockdep tracepoints

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> On Wed, 2009-03-04 at 12:23 +0100, Frederic Weisbecker wrote:
> > > ---
> > > Subject: tracing: lockdep tracepoints
> > > From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > > Date: Tue Mar 03 22:03:08 CET 2009
> > > 
> > > Augment the traces with lock names when lockdep is available:
> > > 
> > >  1)               |  down_read_trylock() {
> > >  1)               |    _spin_lock_irqsave() {
> > >  1)               |      /* lock_acquire: name: &sem->wait_lock */
> > >  1)   4.201 us    |    }
> > >  1)               |    _spin_unlock_irqrestore() {
> > >  1)               |      /* lock_release: name: &sem->wait_lock */
> > 
> > Nice idea.
> > I would just suggest to drop the "name:" since the comment is intuitive enough
> > to figure out what we have after lock_{release,acquire}: 
> 
> Makes sense I guess..
> 
> Here goes.. one s/name: //g later
> 
> ---
> Subject: tracing: lockdep tracepoints
> From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Date: Tue Mar 03 22:03:08 CET 2009
> 
> Augment the traces with lock names when lockdep is available:
> 
>  1)               |  down_read_trylock() {
>  1)               |    _spin_lock_irqsave() {
>  1)               |      /* lock_acquire: &sem->wait_lock */
>  1)   4.201 us    |    }
>  1)               |    _spin_unlock_irqrestore() {
>  1)               |      /* lock_release: &sem->wait_lock */
>  1)   3.523 us    |    }
>  1)               |  /* lock_acquire: try read &mm->mmap_sem */
>  1) + 13.386 us   |  }

very nice! :-)

>  1)   1.460 us    |      page_add_file_rmap();
>  1)               |      _spin_unlock() {
>  1)               |        /* lock_release: __pte_lockptr(page) */
>  1)   3.115 us    |      }
>  1)               |      unlock_page() {
>  1)   1.421 us    |        page_waitqueue();
>  1)   1.220 us    |        __wake_up_bit();
>  1)   6.519 us    |      }

btw., we might want to add tracepoints for 
pagelock-acquire/release events too?

> +TRACE_FORMAT(lock_contended,
> +	TPPROTO(struct lockdep_map *lock, unsigned long ip),
> +	TPARGS(lock, ip),
> +	TPFMT("%s", lock->name)
> +	);

Would it be possible to use the C syntax tracepoints perhaps? 
They are bigger:

     TRACE_EVENT_FORMAT(sched_switch,
        TPPROTO(struct rq *rq, struct task_struct *prev,
                struct task_struct *next),
        TPARGS(rq, prev, next),
        TPFMT("task %s:%d ==> %s:%d",
              prev->comm, prev->pid, next->comm, next->pid),
        TRACE_STRUCT(
                TRACE_FIELD(pid_t, prev_pid, prev->pid)
                TRACE_FIELD(int, prev_prio, prev->prio)
                TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
                                    next_comm,
                                    TPCMD(memcpy(TRACE_ENTRY->next_comm,
                                                 next->comm,
                                                 TASK_COMM_LEN)))
                TRACE_FIELD(pid_t, next_pid, next->pid)
                TRACE_FIELD(int, next_prio, next->prio)
        ),
        TPRAWFMT("prev %d:%d ==> next %s:%d:%d")
        );

but a lot faster.

	Ingo

Re: [PATCH -v2] tracing: lockdep tracepoints

[Peter Zijlstra]

On Wed, 2009-03-04 at 12:43 +0100, Ingo Molnar wrote:
> 
> > +TRACE_FORMAT(lock_contended,
> > +     TPPROTO(struct lockdep_map *lock, unsigned long ip),
> > +     TPARGS(lock, ip),
> > +     TPFMT("%s", lock->name)
> > +     );
> 
> Would it be possible to use the C syntax tracepoints perhaps? 
> They are bigger:
> 
>      TRACE_EVENT_FORMAT(sched_switch,
>         TPPROTO(struct rq *rq, struct task_struct *prev,
>                 struct task_struct *next),
>         TPARGS(rq, prev, next),
>         TPFMT("task %s:%d ==> %s:%d",
>               prev->comm, prev->pid, next->comm, next->pid),
>         TRACE_STRUCT(
>                 TRACE_FIELD(pid_t, prev_pid, prev->pid)
>                 TRACE_FIELD(int, prev_prio, prev->prio)
>                 TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
>                                     next_comm,
>                                     TPCMD(memcpy(TRACE_ENTRY->next_comm,
>                                                  next->comm,
>                                                  TASK_COMM_LEN)))
>                 TRACE_FIELD(pid_t, next_pid, next->pid)
>                 TRACE_FIELD(int, next_prio, next->prio)
>         ),
>         TPRAWFMT("prev %d:%d ==> next %s:%d:%d")
>         );

I'm not quite sure how to do strings with those. The IRQ tracepoints
cheat and omit the string, and the sched tracepoints cheat and use this
static sized comm array.

Re: [PATCH -v2] tracing: lockdep tracepoints

[Török Edwin]

On 2009-03-04 13:32, Peter Zijlstra wrote:
> On Wed, 2009-03-04 at 12:23 +0100, Frederic Weisbecker wrote:
>   
>>> ---
>>> Subject: tracing: lockdep tracepoints
>>> From: Peter Zijlstra <a.p.zijlstra@chello.nl>
>>> Date: Tue Mar 03 22:03:08 CET 2009
>>>
>>> Augment the traces with lock names when lockdep is available:
>>>
>>>  1)               |  down_read_trylock() {
>>>  1)               |    _spin_lock_irqsave() {
>>>  1)               |      /* lock_acquire: name: &sem->wait_lock */
>>>  1)   4.201 us    |    }
>>>  1)               |    _spin_unlock_irqrestore() {
>>>  1)               |      /* lock_release: name: &sem->wait_lock */
>>>       
>> Nice idea.
>> I would just suggest to drop the "name:" since the comment is intuitive enough
>> to figure out what we have after lock_{release,acquire}: 
>>     
>
> Makes sense I guess..
>
> Here goes.. one s/name: //g later

Thanks for working on this.
I just booted a kernel with your patch, and it worked.

When I find some time, I will try to write a locklatency tracer that
uses these tracepoints.

Best regards,
--Edwin

Re: [PATCH -v2] tracing: lockdep tracepoints

[Frederic Weisbecker]

On Wed, Mar 04, 2009 at 12:58:03PM +0100, Peter Zijlstra wrote:
> On Wed, 2009-03-04 at 12:43 +0100, Ingo Molnar wrote:
> > 
> > > +TRACE_FORMAT(lock_contended,
> > > +     TPPROTO(struct lockdep_map *lock, unsigned long ip),
> > > +     TPARGS(lock, ip),
> > > +     TPFMT("%s", lock->name)
> > > +     );
> > 
> > Would it be possible to use the C syntax tracepoints perhaps? 
> > They are bigger:
> > 
> >      TRACE_EVENT_FORMAT(sched_switch,
> >         TPPROTO(struct rq *rq, struct task_struct *prev,
> >                 struct task_struct *next),
> >         TPARGS(rq, prev, next),
> >         TPFMT("task %s:%d ==> %s:%d",
> >               prev->comm, prev->pid, next->comm, next->pid),
> >         TRACE_STRUCT(
> >                 TRACE_FIELD(pid_t, prev_pid, prev->pid)
> >                 TRACE_FIELD(int, prev_prio, prev->prio)
> >                 TRACE_FIELD_SPECIAL(char next_comm[TASK_COMM_LEN],
> >                                     next_comm,
> >                                     TPCMD(memcpy(TRACE_ENTRY->next_comm,
> >                                                  next->comm,
> >                                                  TASK_COMM_LEN)))
> >                 TRACE_FIELD(pid_t, next_pid, next->pid)
> >                 TRACE_FIELD(int, next_prio, next->prio)
> >         ),
> >         TPRAWFMT("prev %d:%d ==> next %s:%d:%d")
> >         );
> 
> I'm not quite sure how to do strings with those. The IRQ tracepoints
> cheat and omit the string, and the sched tracepoints cheat and use this
> static sized comm array.
> 


The TRACE_FIELD_SPECIAL is only used in case of complex assignment,
those that can't be done in a simple "=" expression.

All you need is simply:

TRACE_FORMAT(lock_contended,
     TPPROTO(struct lockdep_map *lock, unsigned long ip),
     TPARGS(lock, ip),
     TPFMT("%s", lock->name)
     TRACE_STRUCT(
	TRACE_FIELD(char *, name, lock->name)
     )
     TPRAWFMT("%s");
);

Re: [PATCH -v2] tracing: lockdep tracepoints

[Peter Zijlstra]

On Wed, 2009-03-04 at 13:12 +0100, Frederic Weisbecker wrote:

> The TRACE_FIELD_SPECIAL is only used in case of complex assignment,
> those that can't be done in a simple "=" expression.
> 
> All you need is simply:
> 
> TRACE_FORMAT(lock_contended,
>      TPPROTO(struct lockdep_map *lock, unsigned long ip),
>      TPARGS(lock, ip),
>      TPFMT("%s", lock->name)
>      TRACE_STRUCT(
> 	TRACE_FIELD(char *, name, lock->name)
>      )
>      TPRAWFMT("%s");
> );

As discussed on IRC, that won't actually work. In generic, you cannot
assume the string is stable, in my particular case it would work, since
lock->name is a compile time constant, except for modules, who will
still ruin that.

So I think something like TRACE_FIELD_STRING() is called for. Not sure
how to integrate a variable length field like that with the static
format description though. Maybe use offsets from the start of the
object as string pointers, so you can place the variable sized bits
after the static bits.

Re: [PATCH -v2] tracing: lockdep tracepoints

[Steven Rostedt]

On Wed, 4 Mar 2009, Frederic Weisbecker wrote:
> > 
> 
> 
> The TRACE_FIELD_SPECIAL is only used in case of complex assignment,
> those that can't be done in a simple "=" expression.
> 
> All you need is simply:
> 
> TRACE_FORMAT(lock_contended,
>      TPPROTO(struct lockdep_map *lock, unsigned long ip),
>      TPARGS(lock, ip),
>      TPFMT("%s", lock->name)
>      TRACE_STRUCT(
> 	TRACE_FIELD(char *, name, lock->name)
>      )
>      TPRAWFMT("%s");
> );


Nope, that wont work :-(  If this is saved to userspace, all the user 
would have is some hex value. If they have a copy of the vmlinux image, 
then they could probably translate that value, unless it was a module.

Perhaps something like:

 TRACE_EVENT_FORMAT(lock_contended,
	TPPROTO(struct lockdep_map *lock, unsigned long ip),
	TPARGS(lock, ip),
	TPFMT("%s", lock->name);
	TRACE_STRUCT(
		TRACE_FIELD_SPECIAL(char name[16], name,
			strncpy(name, lock->name, 16));
	),
	TPRAWFMT("%s")
 );

This would require those 16 bytes to be copied with the raw format, but 
then we would always have the name (first 16 bytes anyway) for later use.

-- Steve

[tip:tracing/ftrace] tracing: add lockdep tracepoints for lock acquire/release

[Peter Zijlstra]

Commit-ID:  efed792d6738964f399a508ef9e831cd60fa4657
Gitweb:     http://git.kernel.org/tip/efed792d6738964f399a508ef9e831cd60fa4657
Author:     "Peter Zijlstra" <peterz@infradead.org>
AuthorDate: Wed, 4 Mar 2009 12:32:55 +0100
Commit:     Ingo Molnar <mingo@elte.hu>
CommitDate: Wed, 4 Mar 2009 18:49:58 +0100

tracing: add lockdep tracepoints for lock acquire/release

Augment the traces with lock names when lockdep is available:

 1)               |  down_read_trylock() {
 1)               |    _spin_lock_irqsave() {
 1)               |      /* lock_acquire: &sem->wait_lock */
 1)   4.201 us    |    }
 1)               |    _spin_unlock_irqrestore() {
 1)               |      /* lock_release: &sem->wait_lock */
 1)   3.523 us    |    }
 1)               |  /* lock_acquire: try read &mm->mmap_sem */
 1) + 13.386 us   |  }
 1)   1.635 us    |  find_vma();
 1)               |  handle_mm_fault() {
 1)               |    __do_fault() {
 1)               |      filemap_fault() {
 1)               |        find_lock_page() {
 1)               |          find_get_page() {
 1)               |            /* lock_acquire: read rcu_read_lock */
 1)               |            /* lock_release: rcu_read_lock */
 1)   5.697 us    |          }
 1)   8.158 us    |        }
 1) + 11.079 us   |      }
 1)               |      _spin_lock() {
 1)               |        /* lock_acquire: __pte_lockptr(page) */
 1)   3.949 us    |      }
 1)   1.460 us    |      page_add_file_rmap();
 1)               |      _spin_unlock() {
 1)               |        /* lock_release: __pte_lockptr(page) */
 1)   3.115 us    |      }
 1)               |      unlock_page() {
 1)   1.421 us    |        page_waitqueue();
 1)   1.220 us    |        __wake_up_bit();
 1)   6.519 us    |      }
 1) + 34.328 us   |    }
 1) + 37.452 us   |  }
 1)               |  up_read() {
 1)               |  /* lock_release: &mm->mmap_sem */
 1)               |    _spin_lock_irqsave() {
 1)               |      /* lock_acquire: &sem->wait_lock */
 1)   3.865 us    |    }
 1)               |    _spin_unlock_irqrestore() {
 1)               |      /* lock_release: &sem->wait_lock */
 1)   8.562 us    |    }
 1) + 17.370 us   |  }

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: =?ISO-8859-1?Q?T=F6r=F6k?= Edwin <edwintorok@gmail.com>
Cc: Jason Baron <jbaron@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
LKML-Reference: <1236166375.5330.7209.camel@laptop>
Signed-off-by: Ingo Molnar <mingo@elte.hu>


---
 include/trace/lockdep.h             |    9 +++++++
 include/trace/lockdep_event_types.h |   44 +++++++++++++++++++++++++++++++++++
 include/trace/trace_event_types.h   |    1 +
 include/trace/trace_events.h        |    1 +
 kernel/lockdep.c                    |   17 +++++++++++++
 kernel/trace/trace.c                |   14 ++++++----
 kernel/trace/trace_events_stage_3.h |    4 +-
 7 files changed, 82 insertions(+), 8 deletions(-)

diff --git a/include/trace/lockdep.h b/include/trace/lockdep.h
new file mode 100644
index 0000000..5ca67df
--- /dev/null
+++ b/include/trace/lockdep.h
@@ -0,0 +1,9 @@
+#ifndef _TRACE_LOCKDEP_H
+#define _TRACE_LOCKDEP_H
+
+#include <linux/lockdep.h>
+#include <linux/tracepoint.h>
+
+#include <trace/lockdep_event_types.h>
+
+#endif
diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
new file mode 100644
index 0000000..f713d74
--- /dev/null
+++ b/include/trace/lockdep_event_types.h
@@ -0,0 +1,44 @@
+
+#ifndef TRACE_EVENT_FORMAT
+# error Do not include this file directly.
+# error Unless you know what you are doing.
+#endif
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM lock
+
+#ifdef CONFIG_LOCKDEP
+
+TRACE_FORMAT(lock_acquire,
+	TPPROTO(struct lockdep_map *lock, unsigned int subclass,
+		int trylock, int read, int check,
+		struct lockdep_map *next_lock, unsigned long ip),
+	TPARGS(lock, subclass, trylock, read, check, next_lock, ip),
+	TPFMT("%s%s%s", trylock ? "try " : "",
+		read ? "read " : "", lock->name)
+	);
+
+TRACE_FORMAT(lock_release,
+	TPPROTO(struct lockdep_map *lock, int nested, unsigned long ip),
+	TPARGS(lock, nested, ip),
+	TPFMT("%s", lock->name)
+	);
+
+#ifdef CONFIG_LOCK_STAT
+
+TRACE_FORMAT(lock_contended,
+	TPPROTO(struct lockdep_map *lock, unsigned long ip),
+	TPARGS(lock, ip),
+	TPFMT("%s", lock->name)
+	);
+
+TRACE_FORMAT(lock_acquired,
+	TPPROTO(struct lockdep_map *lock, unsigned long ip),
+	TPARGS(lock, ip),
+	TPFMT("%s", lock->name)
+	);
+
+#endif
+#endif
+
+#undef TRACE_SYSTEM
diff --git a/include/trace/trace_event_types.h b/include/trace/trace_event_types.h
index 33c8ed5..df56f56 100644
--- a/include/trace/trace_event_types.h
+++ b/include/trace/trace_event_types.h
@@ -2,3 +2,4 @@
 
 #include <trace/sched_event_types.h>
 #include <trace/irq_event_types.h>
+#include <trace/lockdep_event_types.h>
diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index ea2ef20..fd13750 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -2,3 +2,4 @@
 
 #include <trace/sched.h>
 #include <trace/irq.h>
+#include <trace/lockdep.h>
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 02014f7..cb70c1d 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -42,6 +42,7 @@
 #include <linux/hash.h>
 #include <linux/ftrace.h>
 #include <linux/stringify.h>
+#include <trace/lockdep.h>
 
 #include <asm/sections.h>
 
@@ -2913,6 +2914,8 @@ void lock_set_class(struct lockdep_map *lock, const char *name,
 }
 EXPORT_SYMBOL_GPL(lock_set_class);
 
+DEFINE_TRACE(lock_acquire);
+
 /*
  * We are not always called with irqs disabled - do that here,
  * and also avoid lockdep recursion:
@@ -2923,6 +2926,8 @@ void lock_acquire(struct lockdep_map *lock, unsigned int subclass,
 {
 	unsigned long flags;
 
+	trace_lock_acquire(lock, subclass, trylock, read, check, nest_lock, ip);
+
 	if (unlikely(current->lockdep_recursion))
 		return;
 
@@ -2937,11 +2942,15 @@ void lock_acquire(struct lockdep_map *lock, unsigned int subclass,
 }
 EXPORT_SYMBOL_GPL(lock_acquire);
 
+DEFINE_TRACE(lock_release);
+
 void lock_release(struct lockdep_map *lock, int nested,
 			  unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_release(lock, nested, ip);
+
 	if (unlikely(current->lockdep_recursion))
 		return;
 
@@ -3090,10 +3099,14 @@ found_it:
 	lock->ip = ip;
 }
 
+DEFINE_TRACE(lock_contended);
+
 void lock_contended(struct lockdep_map *lock, unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_contended(lock, ip);
+
 	if (unlikely(!lock_stat))
 		return;
 
@@ -3109,10 +3122,14 @@ void lock_contended(struct lockdep_map *lock, unsigned long ip)
 }
 EXPORT_SYMBOL_GPL(lock_contended);
 
+DEFINE_TRACE(lock_acquired);
+
 void lock_acquired(struct lockdep_map *lock, unsigned long ip)
 {
 	unsigned long flags;
 
+	trace_lock_acquired(lock, ip);
+
 	if (unlikely(!lock_stat))
 		return;
 
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 12539f7..c8abbb0 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -623,7 +623,7 @@ static unsigned map_pid_to_cmdline[PID_MAX_DEFAULT+1];
 static unsigned map_cmdline_to_pid[SAVED_CMDLINES];
 static char saved_cmdlines[SAVED_CMDLINES][TASK_COMM_LEN];
 static int cmdline_idx;
-static DEFINE_SPINLOCK(trace_cmdline_lock);
+static raw_spinlock_t trace_cmdline_lock = __RAW_SPIN_LOCK_UNLOCKED;
 
 /* temporary disable recording */
 static atomic_t trace_record_cmdline_disabled __read_mostly;
@@ -735,7 +735,7 @@ static void trace_save_cmdline(struct task_struct *tsk)
 	 * nor do we want to disable interrupts,
 	 * so if we miss here, then better luck next time.
 	 */
-	if (!spin_trylock(&trace_cmdline_lock))
+	if (!__raw_spin_trylock(&trace_cmdline_lock))
 		return;
 
 	idx = map_pid_to_cmdline[tsk->pid];
@@ -753,7 +753,7 @@ static void trace_save_cmdline(struct task_struct *tsk)
 
 	memcpy(&saved_cmdlines[idx], tsk->comm, TASK_COMM_LEN);
 
-	spin_unlock(&trace_cmdline_lock);
+	__raw_spin_unlock(&trace_cmdline_lock);
 }
 
 char *trace_find_cmdline(int pid)
@@ -3751,7 +3751,7 @@ static __init int tracer_init_debugfs(void)
 
 int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 {
-	static DEFINE_SPINLOCK(trace_buf_lock);
+	static raw_spinlock_t trace_buf_lock = __RAW_SPIN_LOCK_UNLOCKED;
 	static char trace_buf[TRACE_BUF_SIZE];
 
 	struct ring_buffer_event *event;
@@ -3773,7 +3773,8 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 		goto out;
 
 	pause_graph_tracing();
-	spin_lock_irqsave(&trace_buf_lock, irq_flags);
+	raw_local_irq_save(irq_flags);
+	__raw_spin_lock(&trace_buf_lock);
 	len = vsnprintf(trace_buf, TRACE_BUF_SIZE, fmt, args);
 
 	len = min(len, TRACE_BUF_SIZE-1);
@@ -3792,7 +3793,8 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 	ring_buffer_unlock_commit(tr->buffer, event);
 
  out_unlock:
-	spin_unlock_irqrestore(&trace_buf_lock, irq_flags);
+	__raw_spin_unlock(&trace_buf_lock);
+	raw_local_irq_restore(irq_flags);
 	unpause_graph_tracing();
  out:
 	preempt_enable_notrace();
diff --git a/kernel/trace/trace_events_stage_3.h b/kernel/trace/trace_events_stage_3.h
index 041789f..2c8d76c 100644
--- a/kernel/trace/trace_events_stage_3.h
+++ b/kernel/trace/trace_events_stage_3.h
@@ -5,7 +5,7 @@
  *
  * static void ftrace_event_<call>(proto)
  * {
- * 	event_trace_printk(_RET_IP_, "(<call>) " <fmt>);
+ * 	event_trace_printk(_RET_IP_, "<call>: " <fmt>);
  * }
  *
  * static int ftrace_reg_event_<call>(void)
@@ -112,7 +112,7 @@
 #define _TRACE_FORMAT(call, proto, args, fmt)				\
 static void ftrace_event_##call(proto)					\
 {									\
-	event_trace_printk(_RET_IP_, "(" #call ") " fmt);		\
+	event_trace_printk(_RET_IP_, #call ": " fmt);			\
 }									\
 									\
 static int ftrace_reg_event_##call(void)				\