tracing: Some fixes and cleanups for 3.19
Steven Rostedt
maintainercover tracing: Some fixes and cleanups for 3.19
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next
Head SHA1: 4526d0676a150dce7a93ad93e03bef7f77e7c906
Byungchul Park (1):
function_graph: Fix micro seconds notations
Daniel Bristot de Oliveira (1):
ftrace-graph: show latency-format on print_graph_irq()
Daniel Thompson (2):
tracing: kdb: Fix kernel panic during ftdump
tracing: kdb: Fix kernel livelock with empty buffers
Luis Claudio R. Goncalves (1):
tracing: Fix traceoff_on_warning handling on boot command line
Rasmus Villemoes (3):
tracing: Replace seq_printf by simpler equivalents
tracing: Merge consecutive seq_puts calls
trace: Replace single-character seq_puts with seq_putc
Steven Rostedt (Red Hat) (1):
ftrace: Have the control_ops get a trampoline
----
kernel/trace/ftrace.c | 32 +++++++------- kernel/trace/trace.c | 83 ++++++++++++++++++------------------ kernel/trace/trace_branch.c | 32 +++++++------- kernel/trace/trace_events.c | 4 +- kernel/trace/trace_events_trigger.c | 6 +-- kernel/trace/trace_functions.c | 2 +- kernel/trace/trace_functions_graph.c | 49 ++++++++++++--------- kernel/trace/trace_kdb.c | 21 +++++---- kernel/trace/trace_kprobe.c | 12 +++--- kernel/trace/trace_printk.c | 2 +- kernel/trace/trace_uprobe.c | 4 +- 11 files changed, 132 insertions(+), 115 deletions(-)
Steven Rostedt
maintainerPATCH 1/9 ftrace: Have the control_ops get a trampoline
From: "Steven Rostedt (Red Hat)" <[email protected]>
With the new logic, if only a single user of ftrace function hooks is used, it will get its own trampoline assigned to it.
The problem is that the control_ops is an indirect ops that perf ops uses. What that means is that when perf registers its ops with register_ftrace_function(), it has the CONTROL flag set and gets added to the control list instead of the global ftrace list. The control_ops gets added to that instead and the mcount trampoline calls the control_ops function. The control_ops function will iterate the control list and call the ops functions that are attached to it.
But currently the trampoline is added to the perf ops and not the control ops, and when ftrace tries to find a trampoline hook for it, it fails to find one and gives the following splat:
------------[ cut here ]------------ WARNING: CPU: 0 PID: 10133 at kernel/trace/ftrace.c:2033 ftrace_get_addr_new+0x6f/0xc0() Modules linked in: [...] CPU: 0 PID: 10133 Comm: perf Tainted: P 3.18.0-rc1-test+ #388 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012 00000000000007f1 ffff8800c2643bc8 ffffffff814fca6e ffff88011ea0ed01 0000000000000000 ffff8800c2643c08 ffffffff81041ffd 0000000000000000 ffffffff810c388c ffffffff81a5a350 ffff880119b00000 ffffffff810001c8 Call Trace: [<ffffffff814fca6e>] dump_stack+0x46/0x58 [<ffffffff81041ffd>] warn_slowpath_common+0x81/0x9b [<ffffffff810c388c>] ? ftrace_get_addr_new+0x6f/0xc0 [<ffffffff810001c8>] ? 0xffffffff810001c8 [<ffffffff81042031>] warn_slowpath_null+0x1a/0x1c [<ffffffff810c388c>] ftrace_get_addr_new+0x6f/0xc0 [<ffffffff8102e938>] ftrace_replace_code+0xd6/0x334 [<ffffffff810c4116>] ftrace_modify_all_code+0x41/0xc5 [<ffffffff8102eba6>] arch_ftrace_update_code+0x10/0x19 [<ffffffff810c293c>] ftrace_run_update_code+0x21/0x42 [<ffffffff810c298f>] ftrace_startup_enable+0x32/0x34 [<ffffffff810c3049>] ftrace_startup+0x14e/0x15a [<ffffffff810c307c>] register_ftrace_function+0x27/0x40 [<ffffffff810dc118>] perf_ftrace_event_register+0x3e/0xee [<ffffffff810dbfbe>] perf_trace_init+0x29d/0x2a9 [<ffffffff810eb422>] perf_tp_event_init+0x27/0x3a [<ffffffff810f18bc>] perf_init_event+0x9e/0xed [<ffffffff810f1ba4>] perf_event_alloc+0x299/0x330 [<ffffffff810f236b>] SYSC_perf_event_open+0x3ee/0x816 [<ffffffff8115a066>] ? mntput+0x2d/0x2f [<ffffffff81142b00>] ? __fput+0xa7/0x1b2 [<ffffffff81091300>] ? do_gettimeofday+0x22/0x3a [<ffffffff810f279c>] SyS_perf_event_open+0x9/0xb [<ffffffff81502a92>] system_call_fastpath+0x12/0x17 ---[ end trace 81a53565150e4982 ]--- Bad trampoline accounting at: ffffffff810001c8 (run_init_process+0x0/0x2d) (10000001)
Update the control_ops trampoline instead of the perf ops one.
--- kernel/trace/ftrace.c | 2 ++ 1 file changed, 2 insertions(+)
kernel/trace/ftrace.c +2 -0
@@ -418,6 +418,8 @@ static int __register_ftrace_function(struct ftrace_ops *ops)if (control_ops_alloc (ops))return -ENOMEM ;add_ftrace_list_ops (&ftrace_control_list, &control_ops, ops); +/* The control_ops needs the trampoline update */ + ops = &control_ops; }else add_ftrace_ops (&ftrace_ops_list, ops);
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 2/9 tracing: Fix traceoff_on_warning handling on boot command line
In reply to Steven RostedtFrom: "Luis Claudio R. Goncalves" <[email protected]>
According to the documentation, adding "traceoff_on_warning" to the boot command line should be enough to enable the feature. But right now it is necessary to specify "traceoff_on_warning=". Along with fixing that, also verify if the value passed, if any, is either "0" or "off".
--- kernel/trace/trace.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-)
kernel/trace/trace.c +3 -2
@@ -155,10 +155,11 @@ __setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);static int __init stop_trace_on_warning (char *str) { - __disable_trace_on_warning =1 ; +if ((strcmp (str,"=0" ) !=0 &&strcmp (str,"=off" ) !=0 )) + __disable_trace_on_warning =1 ;return 1 ; } -__setup ("traceoff_on_warning=" , stop_trace_on_warning); +__setup ("traceoff_on_warning" , stop_trace_on_warning);static int __init boot_alloc_snapshot (char *str) {
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 3/9 tracing: kdb: Fix kernel panic during ftdump
In reply to Steven RostedtFrom: Daniel Thompson <[email protected]>
Currently kdb's ftdump command unconditionally crashes due to a null pointer de-reference whenever the command is run. This in turn causes the kernel to panic.
The abridged stacktrace (gathered with ARCH=arm) is:
--- cut here ---
[<c09535ac>] (panic) from [<c02132dc>] (die+0x264/0x440) [<c02132dc>] (die) from [<c0952eb8>] (__do_kernel_fault.part.11+0x74/0x84)
[<c0952eb8>] (__do_kernel_fault.part.11) from [<c021f954>] (do_page_fault+0x1d0/0x3c4)
[<c021f954>] (do_page_fault) from [<c020846c>] (do_DataAbort+0x48/0xac)
[<c020846c>] (do_DataAbort) from [<c0213c58>] (__dabt_svc+0x38/0x60)
Exception stack(0xc0deba88 to 0xc0debad0)
ba80: e8c29180 00000001 e9854304 e9854300 c0f567d8c0df2580
baa0: 00000000 00000000 00000000 c0f117b8 c0e3a3c0 c0debb0c 00000000 c0debad0
bac0: 0000672e c02f4d60 60000193 ffffffff
[<c0213c58>] (__dabt_svc) from [<c02f4d60>] (kdb_ftdump+0x1e4/0x3d8) [<c02f4d60>] (kdb_ftdump) from [<c02ce328>] (kdb_parse+0x2b8/0x698) [<c02ce328>] (kdb_parse) from [<c02ceef0>] (kdb_main_loop+0x52c/0x784) [<c02ceef0>] (kdb_main_loop) from [<c02d1b0c>] (kdb_stub+0x238/0x490) --- cut here ---
The NULL deref occurs due to the initialized use of struct trace_iter's buffer_iter member.
This is a regression, albeit a fairly elderly one. It was introduced by commit 6d158a813efc ("tracing: Remove NR_CPUS array from trace_iterator").
This patch solves this by providing a collection of ring_buffer_iter(s) and using this to initialize buffer_iter. Note that static allocation is used solely because the trace_iter itself is also static allocated. Static allocation also means that we have to NULL-ify the pointer during cleanup to avoid use-after-free problems.
--- kernel/trace/trace_kdb.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-)
kernel/trace/trace_kdb.c +7 -2
@@ -20,10 +20,12 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file) {/* use static because iter can be a bit big for the stack */ static struct trace_iterator iter; +static struct ring_buffer_iter *buffer_iter[CONFIG_NR_CPUS ];unsigned int old_userobj;int cnt =0 , cpu;trace_init_global_iter (&iter); + iter.buffer_iter = buffer_iter;for_each_tracing_cpu (cpu) {atomic_inc (&per_cpu_ptr (iter.trace_buffer->data, cpu)->disabled);
@@ -86,9 +88,12 @@ out:atomic_dec (&per_cpu_ptr (iter.trace_buffer->data, cpu)->disabled); } -for_each_tracing_cpu (cpu) -if (iter.buffer_iter[cpu]) +for_each_tracing_cpu (cpu) { +if (iter.buffer_iter[cpu]) {ring_buffer_read_finish (iter.buffer_iter[cpu]); + iter.buffer_iter[cpu] =NULL ; + } + } }/*
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 4/9 tracing: kdb: Fix kernel livelock with empty buffers
In reply to Steven RostedtFrom: Daniel Thompson <[email protected]>
Currently kdb's ftdump command will livelock by constantly printk'ing the empty string at KERN_EMERG level if it run when the ftrace system is not in use. This occurs because trace_empty() never returns false when the ring buffers are left at the start of a non-consuming read [launched by ring_buffer_read_start()].
This patch changes the loop exit condition to use the result of trace_find_next_entry_inc(). Effectively this switches the non-consuming kdb dumper to follow the approach of the non-consuming userspace interface [s_next()] rather than the consuming ftrace_dump().
--- kernel/trace/trace_kdb.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-)
kernel/trace/trace_kdb.c +6 -6
@@ -59,19 +59,19 @@ static void ftrace_dump_buf(int skip_lines, long cpu_file)ring_buffer_read_start (iter.buffer_iter[cpu_file]);tracing_iter_reset (&iter, cpu_file); } -if (!trace_empty (&iter)) -trace_find_next_entry_inc (&iter); -while (!trace_empty (&iter)) { + +while (trace_find_next_entry_inc (&iter)) {if (!cnt)kdb_printf ("---------------------------------\n" ); cnt++; -if (trace_find_next_entry_inc (&iter) !=NULL && !skip_lines) +if (!skip_lines) {print_trace_line (&iter); -if (!skip_lines)trace_printk_seq (&iter.seq); -else + }else { skip_lines--; + } +if (KDB_FLAG (CMD_INTERRUPT )) goto out; }
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 5/9 tracing: Replace seq_printf by simpler equivalents
In reply to Steven RostedtFrom: Rasmus Villemoes <[email protected]>
Using seq_printf to print a simple string or a single character is a lot more expensive than it needs to be, since seq_puts and seq_putc exist.
These patches do
seq_printf(m, s) -> seq_puts(m, s)
seq_printf(m, "%s", s) -> seq_puts(m, s)
seq_printf(m, "%c", c) -> seq_putc(m, c)
Subsequent patches will simplify further.
--- kernel/trace/ftrace.c | 30 ++++++++++++------------ kernel/trace/trace.c | 44 ++++++++++++++++++------------------ kernel/trace/trace_branch.c | 26 ++++++++++----------- kernel/trace/trace_events.c | 4 ++-- kernel/trace/trace_events_trigger.c | 2 +- kernel/trace/trace_functions.c | 2 +- kernel/trace/trace_functions_graph.c | 28 +++++++++++------------ kernel/trace/trace_kprobe.c | 4 ++-- kernel/trace/trace_uprobe.c | 2 +- 9 files changed, 71 insertions(+), 71 deletions(-)
kernel/trace/ftrace.c +15 -15
@@ -571,13 +571,13 @@ static int function_stat_cmp(void *p1, void *p2)static int function_stat_headers (struct seq_file *m) {#ifdef CONFIG_FUNCTION_GRAPH_TRACER -seq_printf (m," Function " -"Hit Time Avg s^2\n" -" -------- " -"--- ---- --- ---\n" ); +seq_puts (m," Function " +"Hit Time Avg s^2\n" +" -------- " +"--- ---- --- ---\n" );#else -seq_printf (m," Function Hit\n" -" -------- ---\n" ); +seq_puts (m," Function Hit\n" +" -------- ---\n" );#endif return 0 ; }
@@ -604,7 +604,7 @@ static int function_stat_show(struct seq_file *m, void *v)seq_printf (m," %-30.30s %10lu" , str, rec->counter);#ifdef CONFIG_FUNCTION_GRAPH_TRACER -seq_printf (m," " ); +seq_puts (m," " ); avg = rec->time;do_div (avg, rec->counter);
@@ -3006,9 +3006,9 @@ static int t_show(struct seq_file *m, void *v)if (iter->flags &FTRACE_ITER_PRINTALL ) {if (iter->flags &FTRACE_ITER_NOTRACE ) -seq_printf (m,"#### no functions disabled ####\n" ); +seq_puts (m,"#### no functions disabled ####\n" );else -seq_printf (m,"#### all functions enabled ####\n" ); +seq_puts (m,"#### all functions enabled ####\n" );return 0 ; }
@@ -3030,13 +3030,13 @@ static int t_show(struct seq_file *m, void *v)seq_printf (m,"\ttramp: %pS" , (void *)ops->trampoline); else - seq_printf(m, "\ttramp: ERROR!"); + seq_puts(m, "\ttramp: ERROR!"); }add_trampoline_func (m, ops, rec); } -seq_printf (m,"\n" ); +seq_putc (m,'\n' );return 0 ; }
@@ -4233,9 +4233,9 @@ static int g_show(struct seq_file *m, void *v)struct ftrace_graph_data *fgd = m->private;if (fgd->table == ftrace_graph_funcs) -seq_printf (m,"#### all functions enabled ####\n" ); +seq_puts (m,"#### all functions enabled ####\n" );else -seq_printf (m,"#### no functions disabled ####\n" ); +seq_puts (m,"#### no functions disabled ####\n" );return 0 ; }
@@ -5155,12 +5155,12 @@ static int fpid_show(struct seq_file *m, void *v) const struct ftrace_pid *fpid = list_entry(v, struct ftrace_pid, list);if (v == (void *)1 ) { -seq_printf (m,"no pid\n" ); +seq_puts (m,"no pid\n" );return 0 ; }if (fpid->pid == ftrace_swapper_pid) -seq_printf (m,"swapper tasks\n" ); +seq_puts (m,"swapper tasks\n" );else seq_printf (m,"%u\n" ,pid_vnr (fpid->pid));
kernel/trace/trace.c +22 -22
83 lines not on this page · raw message
kernel/trace/trace_branch.c +13 -13
@@ -233,12 +233,12 @@ extern unsigned long __stop_annotated_branch_profile[];static int annotated_branch_stat_headers (struct seq_file *m) { -seq_printf (m," correct incorrect %% " ); -seq_printf (m," Function " -" File Line\n" -" ------- --------- - " -" -------- " -" ---- ----\n" ); +seq_puts (m," correct incorrect % " ); +seq_puts (m," Function " +" File Line\n" +" ------- --------- - " +" -------- " +" ---- ----\n" );return 0 ; }
@@ -274,7 +274,7 @@ static int branch_stat_show(struct seq_file *m, void *v)seq_printf (m,"%8lu %8lu " , p->correct, p->incorrect);if (percent <0 ) -seq_printf (m," X " ); +seq_puts (m," X " );else seq_printf (m,"%3ld " , percent);seq_printf (m,"%-30.30s %-20.20s %d\n" , p->func, f, p->line);
@@ -362,12 +362,12 @@ extern unsigned long __stop_branch_profile[];static int all_branch_stat_headers (struct seq_file *m) { -seq_printf (m," miss hit %% " ); -seq_printf (m," Function " -" File Line\n" -" ------- --------- - " -" -------- " -" ---- ----\n" ); +seq_puts (m," miss hit % " ); +seq_puts (m," Function " +" File Line\n" +" ------- --------- - " +" -------- " +" ---- ----\n" );return 0 ; }
kernel/trace/trace_events.c +2 -2
@@ -918,7 +918,7 @@ static int f_show(struct seq_file *m, void *v)case FORMAT_HEADER :seq_printf (m,"name: %s\n" ,ftrace_event_name (call));seq_printf (m,"ID: %d\n" , call->event.type); -seq_printf (m,"format:\n" ); +seq_puts (m,"format:\n" );return 0 ;case FORMAT_FIELD_SEPERATOR :
@@ -1988,7 +1988,7 @@ event_enable_print(struct seq_file *m, unsigned long ip, ftrace_event_name(data->file->event_call));if (data->count ==-1 ) -seq_printf (m,":unlimited\n" ); +seq_puts (m,":unlimited\n" );else seq_printf (m,":count=%ld\n" , data->count);
kernel/trace/trace_events_trigger.c +1 -1
@@ -373,7 +373,7 @@ event_trigger_print(const char *name, struct seq_file *m, {long count = (long )data; -seq_printf (m,"%s" , name); +seq_puts (m, name);if (count ==-1 )seq_puts (m,":unlimited" );
kernel/trace/trace_functions.c +1 -1
@@ -361,7 +361,7 @@ ftrace_probe_print(const char *name, struct seq_file *m,seq_printf (m,"%ps:%s" , (void *)ip, name);if (count ==-1 ) -seq_printf (m,":unlimited\n" ); +seq_puts (m,":unlimited\n" );else seq_printf (m,":count=%ld\n" , count);
kernel/trace/trace_functions_graph.c +14 -14
@@ -1407,32 +1407,32 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)print_lat_header (s, flags);/* 1st line */ -seq_printf (s,"#" ); +seq_puts (s,"#" );if (flags &TRACE_GRAPH_PRINT_ABS_TIME ) -seq_printf (s," TIME " ); +seq_puts (s," TIME " );if (flags &TRACE_GRAPH_PRINT_CPU ) -seq_printf (s," CPU" ); +seq_puts (s," CPU" );if (flags &TRACE_GRAPH_PRINT_PROC ) -seq_printf (s," TASK/PID " ); +seq_puts (s," TASK/PID " );if (lat) -seq_printf (s,"||||" ); +seq_puts (s,"||||" );if (flags &TRACE_GRAPH_PRINT_DURATION ) -seq_printf (s," DURATION " ); -seq_printf (s," FUNCTION CALLS\n" ); +seq_puts (s," DURATION " ); +seq_puts (s," FUNCTION CALLS\n" );/* 2nd line */ -seq_printf (s,"#" ); +seq_puts (s,"#" );if (flags &TRACE_GRAPH_PRINT_ABS_TIME ) -seq_printf (s," | " ); +seq_puts (s," | " );if (flags &TRACE_GRAPH_PRINT_CPU ) -seq_printf (s," | " ); +seq_puts (s," | " );if (flags &TRACE_GRAPH_PRINT_PROC ) -seq_printf (s," | | " ); +seq_puts (s," | | " );if (lat) -seq_printf (s,"||||" ); +seq_puts (s,"||||" );if (flags &TRACE_GRAPH_PRINT_DURATION ) -seq_printf (s," | | " ); -seq_printf (s," | | | |\n" ); +seq_puts (s," | | " ); +seq_puts (s," | | | |\n" ); }static void print_graph_headers (struct seq_file *s)
kernel/trace/trace_kprobe.c +2 -2
@@ -826,7 +826,7 @@ static int probes_seq_show(struct seq_file *m, void *v)struct trace_kprobe *tk = v;int i; -seq_printf (m,"%c" ,trace_kprobe_is_return (tk) ?'r' :'p' ); +seq_putc (m,trace_kprobe_is_return (tk) ?'r' :'p' );seq_printf (m,":%s/%s" , tk->tp.call.class->system,ftrace_event_name (&tk->tp.call));
@@ -840,7 +840,7 @@ static int probes_seq_show(struct seq_file *m, void *v)for (i =0 ; i < tk->tp.nr_args; i++)seq_printf (m," %s=%s" , tk->tp.args[i].name, tk->tp.args[i].comm); -seq_printf (m,"\n" ); +seq_putc (m,'\n' );return 0 ; }
kernel/trace/trace_uprobe.c +1 -1
@@ -606,7 +606,7 @@ static int probes_seq_show(struct seq_file *m, void *v)for (i =0 ; i < tu->tp.nr_args; i++)seq_printf (m," %s=%s" , tu->tp.args[i].name, tu->tp.args[i].comm); -seq_printf (m,"\n" ); +seq_putc (m,'\n' );return 0 ; }
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 6/9 tracing: Merge consecutive seq_puts calls
In reply to Steven RostedtFrom: Rasmus Villemoes <[email protected]>
Consecutive seq_puts calls with literal strings can be merged to a single call. This reduces the size of the generated code, and can also lead to slight .rodata reduction (because of fewer nul and padding bytes). It should also shave a off a few clock cycles.
--- kernel/trace/trace.c | 64 ++++++++++++++++++++++----------------------- kernel/trace/trace_branch.c | 14 +++++----- 2 files changed, 39 insertions(+), 39 deletions(-)
kernel/trace/trace.c +32 -32
@@ -2509,14 +2509,14 @@ get_total_entries(struct trace_buffer *buf,static void print_lat_help_header (struct seq_file *m) { -seq_puts (m,"# _------=> CPU# \n" ); -seq_puts (m,"# / _-----=> irqs-off \n" ); -seq_puts (m,"# | / _----=> need-resched \n" ); -seq_puts (m,"# || / _---=> hardirq/softirq \n" ); -seq_puts (m,"# ||| / _--=> preempt-depth \n" ); -seq_puts (m,"# |||| / delay \n" ); -seq_puts (m,"# cmd pid ||||| time | caller \n" ); -seq_puts (m,"# \\ / ||||| \\ | / \n" ); +seq_puts (m,"# _------=> CPU# \n" +"# / _-----=> irqs-off \n" +"# | / _----=> need-resched \n" +"# || / _---=> hardirq/softirq \n" +"# ||| / _--=> preempt-depth \n" +"# |||| / delay \n" +"# cmd pid ||||| time | caller \n" +"# \\ / ||||| \\ | / \n" ); }static void print_event_info (struct trace_buffer *buf,struct seq_file *m)
@@ -2533,20 +2533,20 @@ static void print_event_info(struct trace_buffer *buf, struct seq_file *m)static void print_func_help_header (struct trace_buffer *buf,struct seq_file *m) {print_event_info (buf, m); -seq_puts (m,"# TASK-PID CPU# TIMESTAMP FUNCTION\n" ); -seq_puts (m,"# | | | | |\n" ); +seq_puts (m,"# TASK-PID CPU# TIMESTAMP FUNCTION\n" +"# | | | | |\n" ); }static void print_func_help_header_irq (struct trace_buffer *buf,struct seq_file *m) {print_event_info (buf, m); -seq_puts (m,"# _-----=> irqs-off\n" ); -seq_puts (m,"# / _----=> need-resched\n" ); -seq_puts (m,"# | / _---=> hardirq/softirq\n" ); -seq_puts (m,"# || / _--=> preempt-depth\n" ); -seq_puts (m,"# ||| / delay\n" ); -seq_puts (m,"# TASK-PID CPU# |||| TIMESTAMP FUNCTION\n" ); -seq_puts (m,"# | | | |||| | |\n" ); +seq_puts (m,"# _-----=> irqs-off\n" +"# / _----=> need-resched\n" +"# | / _---=> hardirq/softirq\n" +"# || / _--=> preempt-depth\n" +"# ||| / delay\n" +"# TASK-PID CPU# |||| TIMESTAMP FUNCTION\n" +"# | | | |||| | |\n" ); }void
@@ -2860,34 +2860,34 @@ static void test_ftrace_alive(struct seq_file *m) {if (!ftrace_is_dead ())return ; -seq_puts (m,"# WARNING: FUNCTION TRACING IS CORRUPTED\n" ); -seq_puts (m,"# MAY BE MISSING FUNCTION EVENTS\n" ); +seq_puts (m,"# WARNING: FUNCTION TRACING IS CORRUPTED\n" +"# MAY BE MISSING FUNCTION EVENTS\n" ); }#ifdef CONFIG_TRACER_MAX_TRACE static void show_snapshot_main_help (struct seq_file *m) { -seq_puts (m,"# echo 0 > snapshot : Clears and frees snapshot buffer\n" ); -seq_puts (m,"# echo 1 > snapshot : Allocates snapshot buffer, if not already allocated.\n" ); -seq_puts (m,"# Takes a snapshot of the main buffer.\n" ); -seq_puts (m,"# echo 2 > snapshot : Clears snapshot buffer (but does not allocate or free)\n" ); -seq_puts (m,"# (Doesn't have to be '2' works with any number that\n" ); -seq_puts (m,"# is not a '0' or '1')\n" ); +seq_puts (m,"# echo 0 > snapshot : Clears and frees snapshot buffer\n" +"# echo 1 > snapshot : Allocates snapshot buffer, if not already allocated.\n" +"# Takes a snapshot of the main buffer.\n" +"# echo 2 > snapshot : Clears snapshot buffer (but does not allocate or free)\n" +"# (Doesn't have to be '2' works with any number that\n" +"# is not a '0' or '1')\n" ); }static void show_snapshot_percpu_help (struct seq_file *m) {seq_puts (m,"# echo 0 > snapshot : Invalid for per_cpu snapshot file.\n" );#ifdef CONFIG_RING_BUFFER_ALLOW_SWAP -seq_puts (m,"# echo 1 > snapshot : Allocates snapshot buffer, if not already allocated.\n" ); -seq_puts (m,"# Takes a snapshot of the main buffer for this cpu.\n" ); +seq_puts (m,"# echo 1 > snapshot : Allocates snapshot buffer, if not already allocated.\n" +"# Takes a snapshot of the main buffer for this cpu.\n" );#else -seq_puts (m,"# echo 1 > snapshot : Not supported with this kernel.\n" ); -seq_puts (m,"# Must use main snapshot file to allocate.\n" ); +seq_puts (m,"# echo 1 > snapshot : Not supported with this kernel.\n" +"# Must use main snapshot file to allocate.\n" );#endif -seq_puts (m,"# echo 2 > snapshot : Clears this cpu's snapshot buffer (but does not allocate)\n" ); -seq_puts (m,"# (Doesn't have to be '2' works with any number that\n" ); -seq_puts (m,"# is not a '0' or '1')\n" ); +seq_puts (m,"# echo 2 > snapshot : Clears this cpu's snapshot buffer (but does not allocate)\n" +"# (Doesn't have to be '2' works with any number that\n" +"# is not a '0' or '1')\n" ); }static void print_snapshot_help (struct seq_file *m,struct trace_iterator *iter)
kernel/trace/trace_branch.c +7 -7
@@ -164,9 +164,9 @@ static enum print_line_t trace_branch_print(struct trace_iterator *iter,static void branch_print_header (struct seq_file *s) {seq_puts (s,"# TASK-PID CPU# TIMESTAMP CORRECT" -" FUNC:FILE:LINE\n" ); -seq_puts (s,"# | | | | | " -" |\n" ); +" FUNC:FILE:LINE\n" +"# | | | | | " +" |\n" ); }static struct trace_event_functions trace_branch_funcs = {
@@ -233,8 +233,8 @@ extern unsigned long __stop_annotated_branch_profile[];static int annotated_branch_stat_headers (struct seq_file *m) { -seq_puts (m," correct incorrect % " ); -seq_puts (m," Function " +seq_puts (m," correct incorrect % " +" Function " " File Line\n" " ------- --------- - " " -------- "
@@ -362,8 +362,8 @@ extern unsigned long __stop_branch_profile[];static int all_branch_stat_headers (struct seq_file *m) { -seq_puts (m," miss hit % " ); -seq_puts (m," Function " +seq_puts (m," miss hit % " +" Function " " File Line\n" " ------- --------- - " " -------- "
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 7/9 trace: Replace single-character seq_puts with seq_putc
In reply to Steven RostedtFrom: Rasmus Villemoes <[email protected]>
Printing a single character to a seqfile might as well be done with seq_putc instead of seq_puts; this avoids a strlen() call and a memory access. It also shaves another few bytes off the generated code.
--- kernel/trace/trace_events_trigger.c | 4 ++-- kernel/trace/trace_functions_graph.c | 4 ++-- kernel/trace/trace_kprobe.c | 8 ++++---- kernel/trace/trace_printk.c | 2 +- kernel/trace/trace_uprobe.c | 2 +- 5 files changed, 10 insertions(+), 10 deletions(-)
kernel/trace/trace_events_trigger.c +2 -2
@@ -383,7 +383,7 @@ event_trigger_print(const char *name, struct seq_file *m,if (filter_str)seq_printf (m," if %s\n" , filter_str);else -seq_puts (m,"\n" ); +seq_putc (m,'\n' );return 0 ; }
@@ -1105,7 +1105,7 @@ event_enable_trigger_print(struct seq_file *m, struct event_trigger_ops *ops,if (data->filter_str)seq_printf (m," if %s\n" , data->filter_str);else -seq_puts (m,"\n" ); +seq_putc (m,'\n' );return 0 ; }
kernel/trace/trace_functions_graph.c +2 -2
@@ -1407,7 +1407,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)print_lat_header (s, flags);/* 1st line */ -seq_puts (s,"#" ); +seq_putc (s,'#' );if (flags &TRACE_GRAPH_PRINT_ABS_TIME )seq_puts (s," TIME " );if (flags &TRACE_GRAPH_PRINT_CPU )
@@ -1421,7 +1421,7 @@ static void __print_graph_headers_flags(struct seq_file *s, u32 flags)seq_puts (s," FUNCTION CALLS\n" );/* 2nd line */ -seq_puts (s,"#" ); +seq_putc (s,'#' );if (flags &TRACE_GRAPH_PRINT_ABS_TIME )seq_puts (s," | " );if (flags &TRACE_GRAPH_PRINT_CPU )
kernel/trace/trace_kprobe.c +4 -4
@@ -1030,7 +1030,7 @@ print_kprobe_event(struct trace_iterator *iter, int flags,if (!seq_print_ip_sym (s, field->ip, flags |TRACE_ITER_SYM_OFFSET )) goto partial; -if (!trace_seq_puts (s,")" )) +if (!trace_seq_putc (s,')' )) goto partial; data = (u8 *)&field[1 ];
@@ -1039,7 +1039,7 @@ print_kprobe_event(struct trace_iterator *iter, int flags, data + tp->args[i].offset, field)) goto partial; -if (!trace_seq_puts (s,"\n" )) +if (!trace_seq_putc (s,'\n' )) goto partial;return TRACE_TYPE_HANDLED ;
@@ -1072,7 +1072,7 @@ print_kretprobe_event(struct trace_iterator *iter, int flags,if (!seq_print_ip_sym (s, field->func, flags & ~TRACE_ITER_SYM_OFFSET )) goto partial; -if (!trace_seq_puts (s,")" )) +if (!trace_seq_putc (s,')' )) goto partial; data = (u8 *)&field[1 ];
@@ -1081,7 +1081,7 @@ print_kretprobe_event(struct trace_iterator *iter, int flags, data + tp->args[i].offset, field)) goto partial; -if (!trace_seq_puts (s,"\n" )) +if (!trace_seq_putc (s,'\n' )) goto partial;return TRACE_TYPE_HANDLED ;
kernel/trace/trace_printk.c +1 -1
@@ -305,7 +305,7 @@ static int t_show(struct seq_file *m, void *v)seq_puts (m,"\\t" );break ;case '\\' : -seq_puts (m,"\\" ); +seq_putc (m,'\\' );break ;case '"' :seq_puts (m,"\\\"" );
kernel/trace/trace_uprobe.c +1 -1
@@ -872,7 +872,7 @@ print_uprobe_event(struct trace_iterator *iter, int flags, struct trace_event *e goto partial; } -if (trace_seq_puts (s,"\n" )) +if (trace_seq_putc (s,'\n' ))return TRACE_TYPE_HANDLED ; partial:
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 8/9 ftrace-graph: show latency-format on print_graph_irq()
In reply to Steven RostedtFrom: Daniel Bristot de Oliveira <[email protected]>
On the function_graph tracer, the print_graph_irq() function prints a trace line with the flag ==========> on an irq handler entry, and the flag <========== on an irq handler return.
But when the latency-format is enable, it is not printing the latency-format flags, causing the following error in the trace output:
0) ==========> |
0) d... | smp_apic_timer_interrupt() {
This patch fixes this issue by printing the latency-format flags when it is enable.
--- kernel/trace/trace_functions_graph.c | 9 +++++++++ 1 file changed, 9 insertions(+)
kernel/trace/trace_functions_graph.c +9 -0
@@ -699,6 +699,7 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr, {int ret;struct trace_seq *s = &iter->seq; +struct trace_entry *ent = iter->ent;if (addr < (unsigned long )__irqentry_text_start || addr >= (unsigned long )__irqentry_text_end)
@@ -728,6 +729,14 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,if (!ret)return TRACE_TYPE_PARTIAL_LINE ; } + +/* Latency format */ +if (trace_flags &TRACE_ITER_LATENCY_FMT ) { + ret =print_graph_lat_fmt (s, ent); +if (ret ==TRACE_TYPE_PARTIAL_LINE ) +return TRACE_TYPE_PARTIAL_LINE ; + } + }/* No overhead */
Signature · 1 line
2.1.1
Steven Rostedt
maintainerPATCH 9/9 function_graph: Fix micro seconds notations
In reply to Steven RostedtFrom: Byungchul Park <[email protected]>
Usually, "msecs" notation means milli-seconds, and "usecs" notation means micro-seconds. Since the unit used in the code is micro-seconds, the notation should be replaced from msecs to usecs.
--- kernel/trace/trace_functions_graph.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-)
kernel/trace/trace_functions_graph.c +6 -6
@@ -768,19 +768,19 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s) {unsigned long nsecs_rem =do_div (duration,1000 );/* log10(ULONG_MAX) + '\0' */ -char msecs_str[21 ]; +char usecs_str[21 ];char nsecs_str[5 ];int ret, len;int i; -sprintf (msecs_str,"%lu" , (unsigned long ) duration); +sprintf (usecs_str,"%lu" , (unsigned long ) duration);/* Print msecs */ - ret =trace_seq_printf (s,"%s" , msecs_str); + ret =trace_seq_printf (s,"%s" , usecs_str);if (!ret)return TRACE_TYPE_PARTIAL_LINE ; - len =strlen (msecs_str); + len =strlen (usecs_str);/* Print nsecs (we don't want to exceed 7 numbers) */ if (len <7 ) {
@@ -831,10 +831,10 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,/* Signal a overhead of time execution to the output */ if (flags &TRACE_GRAPH_PRINT_OVERHEAD ) { -/* Duration exceeded 100 msecs */ +/* Duration exceeded 100 usecs */ if (duration >100000ULL ) ret =trace_seq_puts (s,"! " ); -/* Duration exceeded 10 msecs */ +/* Duration exceeded 10 usecs */ else if (duration >10000ULL ) ret =trace_seq_puts (s,"+ " ); }
Signature · 1 line
2.1.1