Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756143AbZCDLdW (ORCPT ); Wed, 4 Mar 2009 06:33:22 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751903AbZCDLdO (ORCPT ); Wed, 4 Mar 2009 06:33:14 -0500 Received: from bombadil.infradead.org ([18.85.46.34]:42768 "EHLO bombadil.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751719AbZCDLdN (ORCPT ); Wed, 4 Mar 2009 06:33:13 -0500 Subject: [PATCH -v2] tracing: lockdep tracepoints From: Peter Zijlstra To: Frederic Weisbecker Cc: Steven Rostedt , Ingo Molnar , =?ISO-8859-1?Q?T=F6r=F6k?= Edwin , Jason Baron , lkml In-Reply-To: <20090304112345.GB6032@nowhere> References: <1236164586.5330.7142.camel@laptop> <20090304112345.GB6032@nowhere> Content-Type: text/plain Date: Wed, 04 Mar 2009 12:32:55 +0100 Message-Id: <1236166375.5330.7209.camel@laptop> Mime-Version: 1.0 X-Mailer: Evolution 2.25.91 Content-Transfer-Encoding: 7bit X-Bad-Reply: References and In-Reply-To but no 'Re:' in Subject. Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 10315 Lines: 330 On Wed, 2009-03-04 at 12:23 +0100, Frederic Weisbecker wrote: > > --- > > Subject: tracing: lockdep tracepoints > > From: Peter Zijlstra > > 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 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 --- 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 +#include + +#include + +#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 #include +#include 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 #include #include +#include #include @@ -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_(proto) * { - * event_trace_printk(_RET_IP_, "() " ); + * event_trace_printk(_RET_IP_, ": " ); * } * * static int ftrace_reg_event_(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 #include +#include -- 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/