tracing: updates for 2.6.39
Subsystems (6)
Steven Rostedt
maintainerIngo,
Please pull the latest tip/perf/core tree, which can be found at:
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/perf/core
David Sharp (8):
tracing: Add an 'overwrite' trace_option.
ring-buffer: Remove unused #include <linux/trace_irq.h>
tracing: Fix event alignment: ftrace:context_switch and ftrace:wakeup
tracing: Fix event alignment: module:module_request
tracing: Fix event alignment: kvm:kvm_hv_hypercall
tracing: Fix event alignment: mce:mce_record
tracing: Fix event alignment: skb:kfree_skb
tracing: Adjust conditional expression latency formatting.
Jiri Olsa (1):
tracing: Explain about unstable clock on resume with ring buffer warning
Steven Rostedt (5):
tracing: Remove lock_depth from event entry
ftrace: Add .ref.text as one of the safe areas to trace ftrace/graph: Trace function entry before updating index
tracing: Align 4 byte ints together in struct tracer
tracing: Fix irqoff selftest expanding max buffer
Yuanhan Liu (1):
tracing: Export trace_set_clr_event()
----
Documentation/trace/ftrace.txt | 5 +++++ arch/x86/kernel/ftrace.c | 15 ++++++++------- arch/x86/kvm/trace.h | 8 ++++---- include/linux/ftrace_event.h | 1 - include/linux/ring_buffer.h | 2 ++ include/trace/events/mce.h | 8 ++++---- include/trace/events/module.h | 5 ++--- include/trace/events/skb.h | 4 ++-- kernel/trace/ring_buffer.c | 24 +++++++++++++++++++++--- kernel/trace/trace.c | 34 +++++++++++++++++++++++----------- kernel/trace/trace.h | 3 ++- kernel/trace/trace_entries.h | 6 +++--- kernel/trace/trace_events.c | 2 +- kernel/trace/trace_output.c | 36 ++++++++++++++++++++---------------- scripts/recordmcount.c | 3 ++- scripts/recordmcount.pl | 1 + 16 files changed, 100 insertions(+), 57 deletions(-)
Steven Rostedt
maintainerPATCH 1/15 tracing: Add an overwrite trace_option.
From: David Sharp <[email protected]>
Add an "overwrite" trace_option for ftrace to control whether the buffer should be overwritten on overflow or not. The default remains to overwrite old events when the buffer is full. This patch adds the option to instead discard newest events when the buffer is full. This is useful to get a snapshot of traces just after enabling traces. Dropping the current event is also a simpler code path.
LKML-Reference: <[email protected]>
--- Documentation/trace/ftrace.txt | 5 +++++ include/linux/ring_buffer.h | 2 ++ kernel/trace/ring_buffer.c | 11 +++++++++++ kernel/trace/trace.c | 17 +++++++++++------ kernel/trace/trace.h | 1 + 5 files changed, 30 insertions(+), 6 deletions(-)
Documentation/trace/ftrace.txt +5 -0
@@ -454,6 +454,11 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] latencies, as described in "Latency trace format". + overwrite - This controls what happens when the trace buffer is + full. If "1" (default), the oldest events are + discarded and overwritten. If "0", then the newest + events are discarded. + ftrace_enabled --------------
include/linux/ring_buffer.h +2 -0
@@ -100,6 +100,8 @@ void ring_buffer_free(struct ring_buffer *buffer);int ring_buffer_resize (struct ring_buffer *buffer,unsigned long size); +void ring_buffer_change_overwrite (struct ring_buffer *buffer,int val); +struct ring_buffer_event *ring_buffer_lock_reserve (struct ring_buffer *buffer,unsigned long length); int ring_buffer_unlock_commit(struct ring_buffer *buffer,
kernel/trace/ring_buffer.c +11 -0
@@ -1429,6 +1429,17 @@ int ring_buffer_resize(struct ring_buffer *buffer, unsigned long size) }EXPORT_SYMBOL_GPL (ring_buffer_resize); +void ring_buffer_change_overwrite (struct ring_buffer *buffer,int val) +{ +mutex_lock (&buffer->mutex); +if (val) + buffer->flags |=RB_FL_OVERWRITE ; +else + buffer->flags &= ~RB_FL_OVERWRITE ; +mutex_unlock (&buffer->mutex); +} +EXPORT_SYMBOL_GPL (ring_buffer_change_overwrite); +static inline void *__rb_data_page_index (struct buffer_data_page *bpage,unsigned index) {
kernel/trace/trace.c +11 -6
@@ -41,8 +41,6 @@#include "trace.h" #include "trace_output.h" -#define TRACE_BUFFER_FLAGS (RB_FL_OVERWRITE) -/* * On boot up, the ring buffer is set to the minimum size, so that * we do not waste memory on systems that are not using tracing.
@@ -340,7 +338,7 @@ static DECLARE_WAIT_QUEUE_HEAD(trace_wait);/* trace_flags holds trace_options default values */ unsigned long trace_flags =TRACE_ITER_PRINT_PARENT |TRACE_ITER_PRINTK |TRACE_ITER_ANNOTATE |TRACE_ITER_CONTEXT_INFO |TRACE_ITER_SLEEP_TIME | -TRACE_ITER_GRAPH_TIME |TRACE_ITER_RECORD_CMD ; +TRACE_ITER_GRAPH_TIME |TRACE_ITER_RECORD_CMD |TRACE_ITER_OVERWRITE ;static int trace_stop_count;static DEFINE_SPINLOCK (tracing_start_lock);
@@ -425,6 +423,7 @@ static const char *trace_options[] = {"sleep-time" ,"graph-time" ,"record-cmd" , +"overwrite" , NULL };
@@ -2529,6 +2528,9 @@ static void set_tracer_flags(unsigned int mask, int enabled)if (mask ==TRACE_ITER_RECORD_CMD )trace_event_enable_cmd_record (enabled); + +if (mask ==TRACE_ITER_OVERWRITE ) +ring_buffer_change_overwrite (global_trace.buffer, enabled); } static ssize_t
@@ -4555,9 +4557,11 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)__init static int tracer_alloc_buffers (void ) {int ring_buf_size; +enum ring_buffer_flags rb_flags;int i;int ret = -ENOMEM ; +if (!alloc_cpumask_var (&tracing_buffer_mask,GFP_KERNEL )) goto out;
@@ -4570,12 +4574,13 @@ __init static int tracer_alloc_buffers(void)else ring_buf_size =1 ; + rb_flags = trace_flags &TRACE_ITER_OVERWRITE ?RB_FL_OVERWRITE :0 ; +cpumask_copy (tracing_buffer_mask, cpu_possible_mask);cpumask_copy (tracing_cpumask, cpu_all_mask);/* TODO: make the number of buffers hot pluggable with CPUS */ - global_trace.buffer =ring_buffer_alloc (ring_buf_size, -TRACE_BUFFER_FLAGS ); + global_trace.buffer =ring_buffer_alloc (ring_buf_size, rb_flags);if (!global_trace.buffer) {printk (KERN_ERR "tracer: failed to allocate ring buffer!\n" );WARN_ON (1 );
@@ -4585,7 +4590,7 @@ __init static int tracer_alloc_buffers(void)#ifdef CONFIG_TRACER_MAX_TRACE - max_tr.buffer =ring_buffer_alloc (1 ,TRACE_BUFFER_FLAGS ); + max_tr.buffer =ring_buffer_alloc (1 , rb_flags);if (!max_tr.buffer) {printk (KERN_ERR "tracer: failed to allocate max ring buffer!\n" );WARN_ON (1 );
kernel/trace/trace.h +1 -0
@@ -606,6 +606,7 @@ enum trace_iterator_flags {TRACE_ITER_SLEEP_TIME =0x40000 ,TRACE_ITER_GRAPH_TIME =0x80000 ,TRACE_ITER_RECORD_CMD =0x100000 , + TRACE_ITER_OVERWRITE = 0x200000, };/*
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 2/15 ring-buffer: Remove unused #include <linux/trace_irq.h>
In reply to Steven RostedtFrom: David Sharp <[email protected]>
LKML-Reference: <[email protected]>
--- kernel/trace/ring_buffer.c | 1 - 1 files changed, 0 insertions(+), 1 deletions(-)
kernel/trace/ring_buffer.c +0 -1
@@ -5,7 +5,6 @@*/ #include <linux/ring_buffer.h> #include <linux/trace_clock.h> -#include <linux/ftrace_irq.h> #include <linux/spinlock.h> #include <linux/debugfs.h> #include <linux/uaccess.h>
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 3/15 tracing: Remove lock_depth from event entry
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
The lock_depth field in the event headers was added as a temporary data point for help in removing the BKL. Now that the BKL is pretty much been removed, we can remove this field.
This in turn changes the header from 12 bytes to 8 bytes, removing the 4 byte buffer that gcc would insert if the first field in the data load was 8 bytes in size.
--- include/linux/ftrace_event.h | 1 - kernel/trace/trace.c | 8 +++----- kernel/trace/trace_events.c | 1 - kernel/trace/trace_output.c | 10 ++-------- 4 files changed, 5 insertions(+), 15 deletions(-)
include/linux/ftrace_event.h +0 -1
@@ -37,7 +37,6 @@ struct trace_entry {unsigned char flags;unsigned char preempt_count;int pid; -int lock_depth; };#define FTRACE_MAX_EVENT \
kernel/trace/trace.c +3 -5
@@ -1101,7 +1101,6 @@ tracing_generic_entry_update(struct trace_entry *entry, unsigned long flags, entry->preempt_count = pc &0xff ; entry->pid = (tsk) ? tsk->pid :0 ; - entry->lock_depth = (tsk) ? tsk->lock_depth :0 ; entry->flags = #ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT (irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_OFF : 0) |
@@ -1748,10 +1747,9 @@ static void print_lat_help_header(struct seq_file *m)seq_puts (m,"# | / _----=> need-resched \n" );seq_puts (m,"# || / _---=> hardirq/softirq \n" );seq_puts (m,"# ||| / _--=> preempt-depth \n" ); -seq_puts (m,"# |||| /_--=> lock-depth \n" ); -seq_puts (m,"# |||||/ delay \n" ); -seq_puts (m,"# cmd pid |||||| time | caller \n" ); -seq_puts (m,"# \\ / |||||| \\ | / \n" ); +seq_puts (m,"# |||| / delay \n" ); +seq_puts (m,"# cmd pid ||||| time | caller \n" ); +seq_puts (m,"# \\ / ||||| \\ | / \n" ); }static void print_func_help_header (struct seq_file *m)
kernel/trace/trace_events.c +0 -1
@@ -116,7 +116,6 @@ static int trace_define_common_fields(void) __common_field(unsigned char, flags); __common_field(unsigned char, preempt_count);__common_field (int, pid); -__common_field (int, lock_depth);return ret; }
kernel/trace/trace_output.c +2 -8
@@ -529,7 +529,7 @@ seq_print_ip_sym(struct trace_seq *s, unsigned long ip, unsigned long sym_flags)* @entry: The trace entry field from the ring buffer * * Prints the generic fields of irqs off, in hard or softirq, preempt -* count and lock depth. +* count. */ int trace_print_lat_fmt (struct trace_seq *s,struct trace_entry *entry) {
@@ -554,13 +554,7 @@ int trace_print_lat_fmt(struct trace_seq *s, struct trace_entry *entry)else ret =trace_seq_putc (s,'.' ); -if (!ret) -return 0 ; - -if (entry->lock_depth <0 ) -return trace_seq_putc (s,'.' ); - -return trace_seq_printf (s,"%d" , entry->lock_depth); +return ret; } static int
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 4/15 tracing: Fix event alignment: ftrace:context_switch and ftrace:wakeup
In reply to Steven RostedtFrom: David Sharp <[email protected]>
LKML-Reference: <[email protected]>
--- kernel/trace/trace_entries.h | 6 +++--- 1 files changed, 3 insertions(+), 3 deletions(-)
kernel/trace/trace_entries.h +3 -3
@@ -109,12 +109,12 @@ FTRACE_ENTRY(funcgraph_exit, ftrace_graph_ret_entry,*/ #define FTRACE_CTX_FIELDS \ __field( unsigned int, prev_pid ) \ + __field( unsigned int, next_pid ) \ + __field( unsigned int, next_cpu ) \ __field( unsigned char, prev_prio ) \ __field( unsigned char, prev_state ) \ - __field( unsigned int, next_pid ) \ __field( unsigned char, next_prio ) \ - __field( unsigned char, next_state ) \ - __field( unsigned int, next_cpu ) + __field( unsigned char, next_state ) FTRACE_ENTRY(context_switch, ctx_switch_entry,
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 5/15 tracing: Fix event alignment: module:module_request
In reply to Steven RostedtFrom: David Sharp <[email protected]>
LKML-Reference: <[email protected]>
--- include/trace/events/module.h | 5 ++--- 1 files changed, 2 insertions(+), 3 deletions(-)
include/trace/events/module.h +2 -3
@@ -108,14 +108,14 @@ TRACE_EVENT(module_request, TP_ARGS(name, wait, ip),TP_STRUCT__entry ( - __field( bool, wait )__field (unsigned long ,ip ) +__field ( bool, wait )__string ( name, name ) ),TP_fast_assign ( - __entry->wait = wait; __entry->ip = ip; + __entry->wait = wait;__assign_str (name, name); ),
@@ -129,4 +129,3 @@ TRACE_EVENT(module_request,/* This part must be outside protection */ #include <trace/define_trace.h> -
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 6/15 tracing: Fix event alignment: kvm:kvm_hv_hypercall
In reply to Steven RostedtFrom: David Sharp <[email protected]>
LKML-Reference: <[email protected]>
--- arch/x86/kvm/trace.h | 8 ++++---- 1 files changed, 4 insertions(+), 4 deletions(-)
arch/x86/kvm/trace.h +4 -4
@@ -62,21 +62,21 @@ TRACE_EVENT(kvm_hv_hypercall, TP_ARGS(code, fast, rep_cnt, rep_idx, ingpa, outgpa),TP_STRUCT__entry ( -__field (__u16 ,code ) -__field ( bool, fast )__field (__u16 ,rep_cnt )__field ( __u16, rep_idx )__field ( __u64, ingpa )__field ( __u64, outgpa ) +__field ( __u16, code ) +__field ( bool, fast ) ),TP_fast_assign ( - __entry->code = code; - __entry->fast = fast; __entry->rep_cnt = rep_cnt; __entry->rep_idx = rep_idx; __entry->ingpa = ingpa; __entry->outgpa = outgpa; + __entry->code = code; + __entry->fast = fast; ), TP_printk("code 0x%x %s cnt 0x%x idx 0x%x in 0x%llx out 0x%llx",
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 7/15 tracing: Fix event alignment: mce:mce_record
In reply to Steven RostedtFrom: David Sharp <[email protected]>
LKML-Reference: <[email protected]>
--- include/trace/events/mce.h | 8 ++++---- 1 files changed, 4 insertions(+), 4 deletions(-)
include/trace/events/mce.h +4 -4
@@ -17,36 +17,36 @@ TRACE_EVENT(mce_record,TP_STRUCT__entry (__field (u64 ,mcgcap )__field ( u64, mcgstatus ) -__field ( u8, bank )__field ( u64, status )__field ( u64, addr )__field ( u64, misc )__field ( u64, ip ) -__field ( u8, cs )__field ( u64, tsc )__field ( u64, walltime )__field ( u32, cpu )__field ( u32, cpuid )__field ( u32, apicid )__field ( u32, socketid ) +__field ( u8, cs ) +__field ( u8, bank )__field ( u8, cpuvendor ) ),TP_fast_assign ( __entry->mcgcap = m->mcgcap; __entry->mcgstatus = m->mcgstatus; - __entry->bank = m->bank; __entry->status = m->status; __entry->addr = m->addr; __entry->misc = m->misc; __entry->ip = m->ip; - __entry->cs = m->cs; __entry->tsc = m->tsc; __entry->walltime = m->time; __entry->cpu = m->extcpu; __entry->cpuid = m->cpuid; __entry->apicid = m->apicid; __entry->socketid = m->socketid; + __entry->cs = m->cs; + __entry->bank = m->bank; __entry->cpuvendor = m->cpuvendor; ),
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 8/15 tracing: Fix event alignment: skb:kfree_skb
In reply to Steven RostedtFrom: David Sharp <[email protected]>
LKML-Reference: <[email protected]>
--- include/trace/events/skb.h | 4 ++-- 1 files changed, 2 insertions(+), 2 deletions(-)
include/trace/events/skb.h +2 -2
@@ -19,14 +19,14 @@ TRACE_EVENT(kfree_skb,TP_STRUCT__entry (__field (void *,skbaddr ) - __field( unsigned short, protocol ) __field( void *, location ) + __field( unsigned short, protocol ) ),TP_fast_assign ( __entry->skbaddr = skb; - __entry->protocol =ntohs (skb->protocol); __entry->location = location; + __entry->protocol =ntohs (skb->protocol); ), TP_printk("skbaddr=%p protocol=%u location=%p",
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 9/15 tracing: Adjust conditional expression latency formatting.
In reply to Steven RostedtFrom: David Sharp <[email protected]>
Formatting change only to improve code readability. No code changes except to introduce intermediate variables.
LKML-Reference: <[email protected]>
[ Keep variable declarations and assignment separate ]
--- kernel/trace/trace_output.c | 26 ++++++++++++++++++-------- 1 files changed, 18 insertions(+), 8 deletions(-)
kernel/trace/trace_output.c +18 -8
@@ -533,20 +533,30 @@ seq_print_ip_sym(struct trace_seq *s, unsigned long ip, unsigned long sym_flags)*/ int trace_print_lat_fmt (struct trace_seq *s,struct trace_entry *entry) { -int hardirq, softirq; +char hardsoft_irq; +char need_resched; +char irqs_off; +int hardirq; +int softirq;int ret; hardirq = entry->flags &TRACE_FLAG_HARDIRQ ; softirq = entry->flags &TRACE_FLAG_SOFTIRQ ; + irqs_off = + (entry->flags &TRACE_FLAG_IRQS_OFF ) ?'d' : + (entry->flags &TRACE_FLAG_IRQS_NOSUPPORT ) ?'X' : +'.' ; + need_resched = + (entry->flags &TRACE_FLAG_NEED_RESCHED ) ?'N' :'.' ; + hardsoft_irq = + (hardirq && softirq) ?'H' : + hardirq ?'h' : + softirq ?'s' : +'.' ; +if (!trace_seq_printf (s,"%c%c%c" , - (entry->flags &TRACE_FLAG_IRQS_OFF ) ?'d' : - (entry->flags &TRACE_FLAG_IRQS_NOSUPPORT ) ? -'X' :'.' , - (entry->flags &TRACE_FLAG_NEED_RESCHED ) ? -'N' :'.' , - (hardirq && softirq) ?'H' : - hardirq ?'h' : softirq ?'s' :'.' )) + irqs_off, need_resched, hardsoft_irq))return 0 ;if (entry->preempt_count)
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 10/15 ftrace: Add .ref.text as one of the safe areas to trace
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
The section .ref.text will not go away unexpectedly and is safe to trace. Add it to the safe list of sections to allow tracing.
--- scripts/recordmcount.c | 3 ++- scripts/recordmcount.pl | 1 + 2 files changed, 3 insertions(+), 1 deletions(-)
scripts/recordmcount.c +2 -1
@@ -206,7 +206,8 @@ static uint32_t (*w2)(uint16_t);static int is_mcounted_section_name (char const *const txtname) { -return 0 ==strcmp (".text" , txtname) || +return 0 ==strcmp (".text" , txtname) || +0 ==strcmp (".ref.text" , txtname) ||0 ==strcmp (".sched.text" , txtname) ||0 ==strcmp (".spinlock.text" , txtname) || 0 == strcmp(".irqentry.text", txtname) ||
scripts/recordmcount.pl +1 -0
@@ -130,6 +130,7 @@ if ($inputfile =~ m,kernel/trace/ftrace\.o$,) { # Acceptable sections to record. my %text_sections = ( ".text" => 1, + ".ref.text" => 1, ".sched.text" => 1, ".spinlock.text" => 1, ".irqentry.text" => 1,
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 11/15 ftrace/graph: Trace function entry before updating index
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
Currently the index to the ret_stack is updated and the real return address is saved in the ret_stack. Then we call the trace function. The trace function could decide that it doesn't want to trace this function (ex. set_graph_function does not match) and it will return 0 which means not to trace this call.
The normal function graph tracer has this code:
if (!(trace->depth || ftrace_graph_addr(trace->func)) || ftrace_graph_ignore_irqs()) return 0;
What this states is, if the trace depth (which is curr_ret_stack) is zero (top of nested functions) then test if we want to trace this function. If this function is not to be traced, then return 0 and the rest of the function graph tracer logic will not trace this function.
The problem arises when an interrupt comes in after we updated the curr_ret_stack. The next function that gets called will have a trace->depth of 1. Which fools this trace code into thinking that we are in a nested function, and that we should trace. This causes interrupts to be traced when they should not be.
The solution is to trace the function first and then update the ret_stack.
--- arch/x86/kernel/ftrace.c | 15 ++++++++------- 1 files changed, 8 insertions(+), 7 deletions(-)
arch/x86/kernel/ftrace.c +8 -7
@@ -437,18 +437,19 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr, return; } -if (ftrace_push_return_trace (old, self_addr, &trace.depth, - frame_pointer) == -EBUSY ) { - *parent = old; -return ; - } - trace.func = self_addr; + trace.depth = current->curr_ret_stack +1 ;/* Only trace if the calling function expects to */ if (!ftrace_graph_entry (&trace)) { - current->curr_ret_stack--; *parent = old; +return ; + } + +if (ftrace_push_return_trace (old, self_addr, &trace.depth, + frame_pointer) == -EBUSY ) { + *parent = old; +return ; } }#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 12/15 tracing: Explain about unstable clock on resume with ring buffer warning
In reply to Steven RostedtFrom: Jiri Olsa <[email protected]>
The "Delta way too big" warning might appear on a system with a unstable shed clock right after the system is resumed and tracing was enabled at time of suspend.
Since it's not realy a bug, and the unstable sched clock is working fast and reliable otherwise, Steven suggested to keep using the sched clock in any case and just to make note in the warning itself.
v2 changes:
- added #ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
LKML-Reference: <[email protected]>
--- kernel/trace/ring_buffer.c | 12 ++++++++++-- 1 files changed, 10 insertions(+), 2 deletions(-)
kernel/trace/ring_buffer.c +10 -2
@@ -2172,11 +2172,19 @@ rb_reserve_next_event(struct ring_buffer *buffer,if (likely (ts >= cpu_buffer->write_stamp)) { delta = diff;if (unlikely (test_time_stamp (delta))) { +int local_clock_stable =1 ; +#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK + local_clock_stable = sched_clock_stable; +#endif WARN_ONCE (delta > (1ULL <<59 ), -KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n" , +KERN_WARNING "Delta way too big! %llu ts=%llu write stamp = %llu\n%s" , (unsigned long long )delta, (unsigned long long )ts, - (unsigned long long )cpu_buffer->write_stamp); + (unsigned long long )cpu_buffer->write_stamp, + local_clock_stable ?"" : +"If you just came from a suspend/resume,\n" +"please switch to the trace global clock:\n" +" echo global > /sys/kernel/debug/tracing/trace_clock\n" ); add_timestamp =1 ; } }
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 13/15 tracing: Export trace_set_clr_event()
In reply to Steven RostedtFrom: Yuanhan Liu <[email protected]>
Trace events belonging to a module only exists when the module is loaded. Well, we can use trace_set_clr_event funtion to enable some trace event at the module init routine, so that we will not miss something while loading then module.
So, Export the trace_set_clr_event function so that module can use it.
LKML-Reference: <[email protected]>
--- kernel/trace/trace_events.c | 1 + 1 files changed, 1 insertions(+), 0 deletions(-)
kernel/trace/trace_events.c +1 -0
@@ -325,6 +325,7 @@ int trace_set_clr_event(const char *system, const char *event, int set) {return __ftrace_set_clr_event (NULL , system, event, set); } +EXPORT_SYMBOL_GPL (trace_set_clr_event);/* 128 should be much more than enough */ #define EVENT_BUF_SIZE 127
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 14/15 tracing: Align 4 byte ints together in struct tracer
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
Move elements in struct tracer for better alignment.
--- kernel/trace/trace.h | 2 +- 1 files changed, 1 insertions(+), 1 deletions(-)
kernel/trace/trace.h +1 -1
@@ -272,8 +272,8 @@ struct tracer {/* If you handled the flag setting, return 0 */ int (*set_flag)(u32 old_flags,u32 bit,int set);struct tracer *next; -int print_max;struct tracer_flags *flags; +int print_max;int use_max_tr; };
Signature · 1 line
1.7.2.3
Steven Rostedt
maintainerPATCH 15/15 tracing: Fix irqoff selftest expanding max buffer
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
If the kernel command line declares a tracer "ftrace=sometracer" and that tracer is either not defined or is enabled after irqsoff, then the irqs off selftest will fail with the following error:
Testing tracer irqsoff:
------------[ cut here ]------------ WARNING: at /home/rostedt/work/autotest/nobackup/linux-test.git/kernel/trace/tra ce.c:713 update_max_tr_single+0xfa/0x11b() Hardware name: Modules linked in: Pid: 1, comm: swapper Not tainted 2.6.38-rc8-test #1 Call Trace: [<c0441d9d>] ? warn_slowpath_common+0x65/0x7a [<c049adb2>] ? update_max_tr_single+0xfa/0x11b [<c0441dc1>] ? warn_slowpath_null+0xf/0x13 [<c049adb2>] ? update_max_tr_single+0xfa/0x11b [<c049e454>] ? stop_critical_timing+0x154/0x204 [<c049b54b>] ? trace_selftest_startup_irqsoff+0x5b/0xc1 [<c049b54b>] ? trace_selftest_startup_irqsoff+0x5b/0xc1 [<c049b54b>] ? trace_selftest_startup_irqsoff+0x5b/0xc1 [<c049e529>] ? time_hardirqs_on+0x25/0x28 [<c0468bca>] ? trace_hardirqs_on_caller+0x18/0x12f [<c0468cec>] ? trace_hardirqs_on+0xb/0xd [<c049b54b>] ? trace_selftest_startup_irqsoff+0x5b/0xc1 [<c049b6b8>] ? register_tracer+0xf8/0x1a3 [<c14e93fe>] ? init_irqsoff_tracer+0xd/0x11 [<c040115e>] ? do_one_initcall+0x71/0x121 [<c14e93f1>] ? init_irqsoff_tracer+0x0/0x11 [<c14ce3a9>] ? kernel_init+0x13a/0x1b6 [<c14ce26f>] ? kernel_init+0x0/0x1b6 [<c0403842>] ? kernel_thread_helper+0x6/0x10 ---[ end trace e93713a9d40cd06c ]---
.. no entries found ..FAILED!
What happens is the "ftrace=..." will expand the ring buffer to its default size (from its minimum size) but it will not expand the max ring buffer (the ring buffer to store maximum latencies). When the irqsoff test runs, it will call the ring buffer swap routine that checks if the max ring buffer is the same size as the normal ring buffer, and will fail if it is not. This causes the test to fail.
The solution is to expand the max ring buffer before running the self test if the max ring buffer is used by that tracer and the normal ring buffer is expanded. The max ring buffer should be shrunk again after the test is done to save space.
--- kernel/trace/trace.c | 9 +++++++++ 1 files changed, 9 insertions(+), 0 deletions(-)
kernel/trace/trace.c +9 -0
@@ -779,6 +779,11 @@ __acquires(kernel_lock)tracing_reset_online_cpus (tr); current_trace = type; + +/* If we expanded the buffers, make sure the max is expanded too */ +if (ring_buffer_expanded && type->use_max_tr) +ring_buffer_resize (max_tr.buffer, trace_buf_size); +/* the test is responsible for initializing and enabling */ pr_info ("Testing tracer %s: " , type->name); ret = type->selftest (type, tr);
@@ -791,6 +796,10 @@ __acquires(kernel_lock)/* Only reset on passing, to avoid touching corrupted buffers */ tracing_reset_online_cpus (tr); +/* Shrink the max buffer again */ +if (ring_buffer_expanded && type->use_max_tr) +ring_buffer_resize (max_tr.buffer,1 ); + printk(KERN_CONT "PASSED\n"); }#endif
Signature · 1 line
1.7.2.3
Quoted 41 lines · Steven Rostedt
Ingo,
Please pull the latest tip/perf/core tree, which can be found at:
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/perf/coreDavid Sharp (8):
tracing: Add an 'overwrite'trace_option.
ring-buffer: Remove unused #include <linux/trace_irq.h>
tracing: Fix event alignment: ftrace:context_switch and ftrace:wakeup
tracing: Fix event alignment: module:module_request
tracing: Fix event alignment: kvm:kvm_hv_hypercall
tracing: Fix event alignment: mce:mce_record
tracing: Fix event alignment: skb:kfree_skb
tracing: Adjust conditional expression latency formatting.Jiri Olsa (1):
tracing: Explain about unstable clock on resume with ring buffer warningSteven Rostedt (5):
tracing: Removelock_depthfrom event entry
ftrace: Add .ref.text as one of the safe areas to trace ftrace/graph: Trace function entry before updating index
tracing: Align 4 byte ints together in struct tracer
tracing: Fix irqoff selftest expanding max bufferYuanhan Liu (1):
tracing: Exporttrace_set_clr_event()----
Documentation/trace/ftrace.txt | 5 +++++ arch/x86/kernel/ftrace.c | 15 ++++++++------- arch/x86/kvm/trace.h | 8 ++++---- include/linux/ftrace_event.h | 1 - include/linux/ring_buffer.h | 2 ++ include/trace/events/mce.h | 8 ++++---- include/trace/events/module.h | 5 ++--- include/trace/events/skb.h | 4 ++-- kernel/trace/ring_buffer.c | 24 +++++++++++++++++++++---
Quoted 8 lines
kernel/trace/trace.c | 34 +++++++++++++++++++++++----------- kernel/trace/trace.h | 3 ++- kernel/trace/trace_entries.h | 6 +++--- kernel/trace/trace_events.c | 2 +- kernel/trace/trace_output.c | 36 ++++++++++++++++++++---------------- scripts/recordmcount.c | 3 ++- scripts/recordmcount.pl | 1 + 16 files changed, 100 insertions(+), 57 deletions(-)
Pulled, thanks a lot Steve!
Ingo