* [RFC PATCH 1/2] Tracepoint: fix documentation of RCU lockdep checks @ 2015-10-06 23:56 Mathieu Desnoyers 2015-10-06 23:56 ` [RFC PATCH 2/2] trace: emit tracepoint in preempt and irqs off tracer Mathieu Desnoyers 0 siblings, 1 reply; 3+ messages in thread From: Mathieu Desnoyers @ 2015-10-06 23:56 UTC (permalink / raw) To: Steven Rostedt; +Cc: linux-kernel, lttng-dev, Mathieu Desnoyers, Dave Hansen The documentation on top of __DECLARE_TRACE() does not match its implementation since the condition check has been added to the RCU lockdep checks. Update the documentation to match its implementation. Fixes: a05d59a56733 "tracing: Add condition check to RCU lockdep checks" Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com> CC: Dave Hansen <dave@sr71.net> CC: Steven Rostedt <rostedt@goodmis.org> --- include/linux/tracepoint.h | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h index a5f7f3e..c8e3030 100644 --- a/include/linux/tracepoint.h +++ b/include/linux/tracepoint.h @@ -167,10 +167,11 @@ extern void syscall_unregfunc(void); * structure. Force alignment to the same alignment as the section start. * * When lockdep is enabled, we make sure to always do the RCU portions of - * the tracepoint code, regardless of whether tracing is on or we match the - * condition. This lets us find RCU issues triggered with tracepoints even - * when this tracepoint is off. This code has no purpose other than poking - * RCU a bit. + * the tracepoint code, regardless of whether tracing is on. However, + * don't check if the condition is false, due to interaction with idle + * instrumentation. This lets us find RCU issues triggered with tracepoints + * even when this tracepoint is off. This code has no purpose other than + * poking RCU a bit. */ #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ extern struct tracepoint __tracepoint_##name; \ -- 2.1.4 ^ permalink raw reply [flat|nested] 3+ messages in thread
* [RFC PATCH 2/2] trace: emit tracepoint in preempt and irqs off tracer 2015-10-06 23:56 [RFC PATCH 1/2] Tracepoint: fix documentation of RCU lockdep checks Mathieu Desnoyers @ 2015-10-06 23:56 ` Mathieu Desnoyers 2015-10-07 2:54 ` Mathieu Desnoyers 0 siblings, 1 reply; 3+ messages in thread From: Mathieu Desnoyers @ 2015-10-06 23:56 UTC (permalink / raw) To: Steven Rostedt Cc: linux-kernel, lttng-dev, Mathieu Desnoyers, Thomas Gleixner, Ingo Molnar, Peter Zijlstra Allow Ftrace, Perf, and LTTng to hook on the irqsoff tracer and trace longest irqsoff and preemptoff critical sections, or those beyond a specified threshold. This requires introducing a __trace_<name>() tracepoint static inline which bypass static jump labels, because calling a breakpoint from the irqsoff tracer triggers machine reboots due to recursive calls into the tracer. How to setup the irqsoff tracer for this use-case (needed for use with Ftrace, Perf, or LTTng): if the tracing_thread value is set, all durations beyond the specified threshold will emit a tracepoint. If unset, then the max duration will be tracked. The current max duration can be reset using the tracing_max_latency file. echo 0 > /sys/kernel/debug/tracing/options/function-trace # don't need function tracing echo preemptirqsoff > /sys/kernel/debug/tracing/current_tracer echo 2 > /sys/kernel/debug/tracing/tracing_thresh # set threshold (e.g. 2 µs) echo 1 > /sys/kernel/debug/tracing/tracing_on The following two commands can also be useful to tweak the irqsoff tracer: echo 0 > /sys/kernel/debug/tracing/tracing_max_latency # reset max latency echo 0 > /sys/kernel/debug/tracing/tracing_thresh # disable threshold *** An example usage of Ftrace hooking on this tracepoint: *** echo 1 > /sys/kernel/debug/tracing/events/core/core_critical_timing_hit/enable cat /sys/kernel/debug/tracing/trace_pipe [...] cat-2422 1d..2 66157455us : core_critical_timing_hit: ip=0xffffffff81101cae parent_ip=0xffffffff818d38e7 delta_ns=5078 flags=6 preempt_cnt=0 *** An example usage of Perf hooking on this tracepoint: *** perf record -g -e core:core_critical_timing_hit -c 1 sleep 30 perf report -g + 100.00% 100.00% sleep [kernel.vmlinux] [k] check_critical_timing + 92.75% 0.00% sleep [kernel.vmlinux] [k] preempt_count_sub + 92.75% 0.00% sleep [kernel.vmlinux] [k] trace_preempt_on + 65.22% 0.00% sleep [kernel.vmlinux] [k] page_fault + 65.22% 0.00% sleep [kernel.vmlinux] [k] do_page_fault + 63.77% 0.00% sleep [kernel.vmlinux] [k] __do_page_fault + 63.77% 0.00% sleep [kernel.vmlinux] [k] handle_mm_fault + 56.52% 0.00% sleep [kernel.vmlinux] [k] _raw_spin_unlock + 30.43% 0.00% sleep ld-2.19.so [.] _dl_sysdep_start [...] *** An example usage of LTTng hooking on this tracepoint: *** (as root) lttng-sessiond -d (then, as root or tracing group) lttng create --live lttng enable-event -k 'core_*' lttng start lttng view [...] [17:34:17.090669588] (+1.569689755) compudjdev core_critical_timing_hit: { cpu_id = 3 }, { ip = 0xFFFFFFFF81102135, parent_ip = 0xFFFFFFFFA0798E13, delta_ns = 252994, irqs_disabled = 0, preempt_disabled = 1, in_softirq = 0, in_irq = 0, in_nmi = 0 } Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com> CC: Thomas Gleixner <tglx@linutronix.de> CC: Steven Rostedt <rostedt@goodmis.org> CC: Ingo Molnar <mingo@redhat.com> CC: Peter Zijlstra <peterz@infradead.org> --- include/linux/tracepoint.h | 41 +++++++++++++++++++++++++++++----- include/trace/events/core.h | 52 ++++++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace_irqsoff.c | 6 +++++ 3 files changed, 94 insertions(+), 5 deletions(-) create mode 100644 include/trace/events/core.h diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h index c8e3030..17f5a47 100644 --- a/include/linux/tracepoint.h +++ b/include/linux/tracepoint.h @@ -95,6 +95,23 @@ extern void syscall_unregfunc(void); #define TRACE_DEFINE_ENUM(x) +#ifdef CONFIG_LOCKDEP +static inline void check_trace_lockdep_rcu(struct tracepoint_func __rcu *funcs, + int condition) +{ + if (!condition) + return; + rcu_read_lock_sched_notrace(); + rcu_dereference_sched(funcs); + rcu_read_unlock_sched_notrace(); +} +#else +static inline void check_trace_lockdep_rcu(struct tracepoint_func __rcu *funcs, + int condition) +{ +} +#endif + #endif /* _LINUX_TRACEPOINT_H */ /* @@ -172,6 +189,11 @@ extern void syscall_unregfunc(void); * instrumentation. This lets us find RCU issues triggered with tracepoints * even when this tracepoint is off. This code has no purpose other than * poking RCU a bit. + * + * trace_<name>() should usually be used for instrumentation. + * + * __trace_<name>() can be used in core instrumentation where recursion into + * the breakpoint handler is unwanted. */ #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ extern struct tracepoint __tracepoint_##name; \ @@ -182,11 +204,18 @@ extern void syscall_unregfunc(void); TP_PROTO(data_proto), \ TP_ARGS(data_args), \ TP_CONDITION(cond),,); \ - if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \ - rcu_read_lock_sched_notrace(); \ - rcu_dereference_sched(__tracepoint_##name.funcs);\ - rcu_read_unlock_sched_notrace(); \ - } \ + check_trace_lockdep_rcu(__tracepoint_##name.funcs, \ + TP_CONDITION(cond)); \ + } \ + static inline void __trace_##name(proto) \ + { \ + if (static_key_enabled(&__tracepoint_##name.key)) \ + __DO_TRACE(&__tracepoint_##name, \ + TP_PROTO(data_proto), \ + TP_ARGS(data_args), \ + TP_CONDITION(cond),,); \ + check_trace_lockdep_rcu(__tracepoint_##name.funcs, \ + TP_CONDITION(cond)); \ } \ __DECLARE_TRACE_RCU(name, PARAMS(proto), PARAMS(args), \ PARAMS(cond), PARAMS(data_proto), PARAMS(data_args)) \ @@ -239,6 +268,8 @@ extern void syscall_unregfunc(void); #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ static inline void trace_##name(proto) \ { } \ + static inline void __trace_##name(proto) \ + { } \ static inline void trace_##name##_rcuidle(proto) \ { } \ static inline int \ diff --git a/include/trace/events/core.h b/include/trace/events/core.h new file mode 100644 index 0000000..b2c130c --- /dev/null +++ b/include/trace/events/core.h @@ -0,0 +1,52 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM core + +#if !defined(_TRACE_CORE_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_CORE_H + +#include <linux/tracepoint.h> + +/* + * Tracepoint for critical timings. + */ +DECLARE_EVENT_CLASS(core_critical_timing, + + TP_PROTO(unsigned long ip, unsigned long parent_ip, + unsigned long flags, int preempt_cnt, + cycles_t delta_ns), + + TP_ARGS(ip, parent_ip, flags, preempt_cnt, delta_ns), + + TP_STRUCT__entry( + __field( unsigned long, ip ) + __field( unsigned long, parent_ip ) + __field( cycles_t, delta_ns ) + __field( unsigned long, flags ) + __field( int, preempt_cnt ) + ), + + TP_fast_assign( + __entry->ip = ip; + __entry->parent_ip = parent_ip; + __entry->delta_ns = delta_ns; + __entry->flags = flags; + __entry->preempt_cnt = preempt_cnt; + ), + + TP_printk("ip=0x%lx parent_ip=0x%lx delta_ns=%llu flags=%lu preempt_cnt=%d", + __entry->ip, __entry->parent_ip, + (unsigned long long) __entry->delta_ns, + __entry->flags, __entry->preempt_cnt) +); + +DEFINE_EVENT(core_critical_timing, core_critical_timing_hit, + TP_PROTO(unsigned long ip, unsigned long parent_ip, + unsigned long flags, int preempt_cnt, + cycles_t delta_ns), + TP_ARGS(ip, parent_ip, flags, preempt_cnt, delta_ns) +); + +#endif /* _TRACE_CORE_H */ + +/* This part must be outside protection */ +#include <trace/define_trace.h> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index 8523ea3..fad8949 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -14,6 +14,9 @@ #include <linux/module.h> #include <linux/ftrace.h> +#define CREATE_TRACE_POINTS +#include <trace/events/core.h> + #include "trace.h" static struct trace_array *irqsoff_trace __read_mostly; @@ -338,6 +341,9 @@ check_critical_timing(struct trace_array *tr, /* Skip 5 functions to get to the irq/preempt enable function */ __trace_stack(tr, flags, 5, pc); + __trace_core_critical_timing_hit(CALLER_ADDR0, parent_ip, flags, pc, + delta); + if (data->critical_sequence != max_sequence) goto out_unlock; -- 2.1.4 ^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [RFC PATCH 2/2] trace: emit tracepoint in preempt and irqs off tracer 2015-10-06 23:56 ` [RFC PATCH 2/2] trace: emit tracepoint in preempt and irqs off tracer Mathieu Desnoyers @ 2015-10-07 2:54 ` Mathieu Desnoyers 0 siblings, 0 replies; 3+ messages in thread From: Mathieu Desnoyers @ 2015-10-07 2:54 UTC (permalink / raw) To: rostedt Cc: linux-kernel, lttng-dev, Thomas Gleixner, Ingo Molnar, Peter Zijlstra ----- On Oct 6, 2015, at 7:56 PM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote: > Allow Ftrace, Perf, and LTTng to hook on the irqsoff tracer and trace > longest irqsoff and preemptoff critical sections, or those beyond a > specified threshold. > > This requires introducing a __trace_<name>() tracepoint static inline > which bypass static jump labels, because calling a breakpoint from the > irqsoff tracer triggers machine reboots due to recursive calls into the > tracer. Actually, the static jump label bypass is not needed here, thanks to data->disabled which skips nested events. I was seeing the machine reboots in earlier attempts to add a tracepoint elsewhere in the irqsoff tracer (before the delta checks). We should be OK with the static jump label after all. I'll simplify that part of the patch before resubmitting. Thanks, Mathieu > > How to setup the irqsoff tracer for this use-case (needed for use with > Ftrace, Perf, or LTTng): if the tracing_thread value is set, all > durations beyond the specified threshold will emit a tracepoint. If > unset, then the max duration will be tracked. The current max duration > can be reset using the tracing_max_latency file. > > echo 0 > /sys/kernel/debug/tracing/options/function-trace # don't need function > tracing > echo preemptirqsoff > /sys/kernel/debug/tracing/current_tracer > echo 2 > /sys/kernel/debug/tracing/tracing_thresh # set threshold (e.g. 2 > µs) > echo 1 > /sys/kernel/debug/tracing/tracing_on > > The following two commands can also be useful to tweak the > irqsoff tracer: > echo 0 > /sys/kernel/debug/tracing/tracing_max_latency # reset max latency > echo 0 > /sys/kernel/debug/tracing/tracing_thresh # disable threshold > > *** An example usage of Ftrace hooking on this tracepoint: *** > > echo 1 > /sys/kernel/debug/tracing/events/core/core_critical_timing_hit/enable > cat /sys/kernel/debug/tracing/trace_pipe > [...] > cat-2422 1d..2 66157455us : core_critical_timing_hit: ip=0xffffffff81101cae > parent_ip=0xffffffff818d38e7 delta_ns=5078 flags=6 preempt_cnt=0 > > *** An example usage of Perf hooking on this tracepoint: *** > > perf record -g -e core:core_critical_timing_hit -c 1 sleep 30 > perf report -g > > + 100.00% 100.00% sleep [kernel.vmlinux] [k] check_critical_timing > + 92.75% 0.00% sleep [kernel.vmlinux] [k] preempt_count_sub > + 92.75% 0.00% sleep [kernel.vmlinux] [k] trace_preempt_on > + 65.22% 0.00% sleep [kernel.vmlinux] [k] page_fault > + 65.22% 0.00% sleep [kernel.vmlinux] [k] do_page_fault > + 63.77% 0.00% sleep [kernel.vmlinux] [k] __do_page_fault > + 63.77% 0.00% sleep [kernel.vmlinux] [k] handle_mm_fault > + 56.52% 0.00% sleep [kernel.vmlinux] [k] _raw_spin_unlock > + 30.43% 0.00% sleep ld-2.19.so [.] _dl_sysdep_start > [...] > > *** An example usage of LTTng hooking on this tracepoint: *** > > (as root) > lttng-sessiond -d > > (then, as root or tracing group) > lttng create --live > lttng enable-event -k 'core_*' > lttng start > lttng view > [...] > [17:34:17.090669588] (+1.569689755) compudjdev core_critical_timing_hit: { > cpu_id = 3 }, { ip = 0xFFFFFFFF81102135, parent_ip = 0xFFFFFFFFA0798E13, > delta_ns = 252994, irqs_disabled = 0, preempt_disabled = 1, in_softirq = 0, > in_irq = 0, in_nmi = 0 } > > Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com> > CC: Thomas Gleixner <tglx@linutronix.de> > CC: Steven Rostedt <rostedt@goodmis.org> > CC: Ingo Molnar <mingo@redhat.com> > CC: Peter Zijlstra <peterz@infradead.org> > --- > include/linux/tracepoint.h | 41 +++++++++++++++++++++++++++++----- > include/trace/events/core.h | 52 ++++++++++++++++++++++++++++++++++++++++++++ > kernel/trace/trace_irqsoff.c | 6 +++++ > 3 files changed, 94 insertions(+), 5 deletions(-) > create mode 100644 include/trace/events/core.h > > diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h > index c8e3030..17f5a47 100644 > --- a/include/linux/tracepoint.h > +++ b/include/linux/tracepoint.h > @@ -95,6 +95,23 @@ extern void syscall_unregfunc(void); > > #define TRACE_DEFINE_ENUM(x) > > +#ifdef CONFIG_LOCKDEP > +static inline void check_trace_lockdep_rcu(struct tracepoint_func __rcu *funcs, > + int condition) > +{ > + if (!condition) > + return; > + rcu_read_lock_sched_notrace(); > + rcu_dereference_sched(funcs); > + rcu_read_unlock_sched_notrace(); > +} > +#else > +static inline void check_trace_lockdep_rcu(struct tracepoint_func __rcu *funcs, > + int condition) > +{ > +} > +#endif > + > #endif /* _LINUX_TRACEPOINT_H */ > > /* > @@ -172,6 +189,11 @@ extern void syscall_unregfunc(void); > * instrumentation. This lets us find RCU issues triggered with tracepoints > * even when this tracepoint is off. This code has no purpose other than > * poking RCU a bit. > + * > + * trace_<name>() should usually be used for instrumentation. > + * > + * __trace_<name>() can be used in core instrumentation where recursion into > + * the breakpoint handler is unwanted. > */ > #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ > extern struct tracepoint __tracepoint_##name; \ > @@ -182,11 +204,18 @@ extern void syscall_unregfunc(void); > TP_PROTO(data_proto), \ > TP_ARGS(data_args), \ > TP_CONDITION(cond),,); \ > - if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \ > - rcu_read_lock_sched_notrace(); \ > - rcu_dereference_sched(__tracepoint_##name.funcs);\ > - rcu_read_unlock_sched_notrace(); \ > - } \ > + check_trace_lockdep_rcu(__tracepoint_##name.funcs, \ > + TP_CONDITION(cond)); \ > + } \ > + static inline void __trace_##name(proto) \ > + { \ > + if (static_key_enabled(&__tracepoint_##name.key)) \ > + __DO_TRACE(&__tracepoint_##name, \ > + TP_PROTO(data_proto), \ > + TP_ARGS(data_args), \ > + TP_CONDITION(cond),,); \ > + check_trace_lockdep_rcu(__tracepoint_##name.funcs, \ > + TP_CONDITION(cond)); \ > } \ > __DECLARE_TRACE_RCU(name, PARAMS(proto), PARAMS(args), \ > PARAMS(cond), PARAMS(data_proto), PARAMS(data_args)) \ > @@ -239,6 +268,8 @@ extern void syscall_unregfunc(void); > #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ > static inline void trace_##name(proto) \ > { } \ > + static inline void __trace_##name(proto) \ > + { } \ > static inline void trace_##name##_rcuidle(proto) \ > { } \ > static inline int \ > diff --git a/include/trace/events/core.h b/include/trace/events/core.h > new file mode 100644 > index 0000000..b2c130c > --- /dev/null > +++ b/include/trace/events/core.h > @@ -0,0 +1,52 @@ > +#undef TRACE_SYSTEM > +#define TRACE_SYSTEM core > + > +#if !defined(_TRACE_CORE_H) || defined(TRACE_HEADER_MULTI_READ) > +#define _TRACE_CORE_H > + > +#include <linux/tracepoint.h> > + > +/* > + * Tracepoint for critical timings. > + */ > +DECLARE_EVENT_CLASS(core_critical_timing, > + > + TP_PROTO(unsigned long ip, unsigned long parent_ip, > + unsigned long flags, int preempt_cnt, > + cycles_t delta_ns), > + > + TP_ARGS(ip, parent_ip, flags, preempt_cnt, delta_ns), > + > + TP_STRUCT__entry( > + __field( unsigned long, ip ) > + __field( unsigned long, parent_ip ) > + __field( cycles_t, delta_ns ) > + __field( unsigned long, flags ) > + __field( int, preempt_cnt ) > + ), > + > + TP_fast_assign( > + __entry->ip = ip; > + __entry->parent_ip = parent_ip; > + __entry->delta_ns = delta_ns; > + __entry->flags = flags; > + __entry->preempt_cnt = preempt_cnt; > + ), > + > + TP_printk("ip=0x%lx parent_ip=0x%lx delta_ns=%llu flags=%lu preempt_cnt=%d", > + __entry->ip, __entry->parent_ip, > + (unsigned long long) __entry->delta_ns, > + __entry->flags, __entry->preempt_cnt) > +); > + > +DEFINE_EVENT(core_critical_timing, core_critical_timing_hit, > + TP_PROTO(unsigned long ip, unsigned long parent_ip, > + unsigned long flags, int preempt_cnt, > + cycles_t delta_ns), > + TP_ARGS(ip, parent_ip, flags, preempt_cnt, delta_ns) > +); > + > +#endif /* _TRACE_CORE_H */ > + > +/* This part must be outside protection */ > +#include <trace/define_trace.h> > diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c > index 8523ea3..fad8949 100644 > --- a/kernel/trace/trace_irqsoff.c > +++ b/kernel/trace/trace_irqsoff.c > @@ -14,6 +14,9 @@ > #include <linux/module.h> > #include <linux/ftrace.h> > > +#define CREATE_TRACE_POINTS > +#include <trace/events/core.h> > + > #include "trace.h" > > static struct trace_array *irqsoff_trace __read_mostly; > @@ -338,6 +341,9 @@ check_critical_timing(struct trace_array *tr, > /* Skip 5 functions to get to the irq/preempt enable function */ > __trace_stack(tr, flags, 5, pc); > > + __trace_core_critical_timing_hit(CALLER_ADDR0, parent_ip, flags, pc, > + delta); > + > if (data->critical_sequence != max_sequence) > goto out_unlock; > > -- > 2.1.4 -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com ^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2015-10-07 2:54 UTC | newest] Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2015-10-06 23:56 [RFC PATCH 1/2] Tracepoint: fix documentation of RCU lockdep checks Mathieu Desnoyers 2015-10-06 23:56 ` [RFC PATCH 2/2] trace: emit tracepoint in preempt and irqs off tracer Mathieu Desnoyers 2015-10-07 2:54 ` Mathieu Desnoyers
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
Powered by JetHome