tracing/fastboot: Use the ring-buffer timestamp for initcall entries
PATCH 2/2 tracing/fastboot: Use the ring-buffer timestamp for initcall entries
Impact: Split the boot tracer entries in two parts: call and return
Now that we are using the sched tracer from the boot tracer, we want to use the same timestamp than the ring-buffer to have consistent time captures between sched events and initcall events.
So we get rid of the old time capture by the boot tracer and split the initcall events in two parts: call and return. This way we have the ring buffer timestamp of both.
There is an example of a trace in attachment.
--- include/trace/boot.h | 31 ++++++++--- init/main.c | 32 ++++++------ kernel/trace/trace.h | 17 ++++-- kernel/trace/trace_boot.c | 123 ++++++++++++++++++++++++++++++++++----------- 4 files changed, 144 insertions(+), 59 deletions(-)
include/trace/boot.h +22 -9
@@ -2,22 +2,30 @@#define _LINUX_TRACE_BOOT_H/* -* Structure which defines the trace of an initcall. +* Structure which defines the trace of an initcall +* while it is called. * You don't have to fill the func field since it is * only used internally by the tracer. */ -struct boot_trace { +struct boot_trace_call {pid_t caller;char func[KSYM_NAME_LEN ]; -int result; -unsigned long long duration;/* usecs */ -ktime_t calltime; -ktime_t rettime; +}; + +/* +* Structure which defines the trace of an initcall +* while it returns. +*/ +struct boot_trace_ret { +char func[KSYM_NAME_LEN ]; +int result; +unsigned long long duration; };#ifdef CONFIG_BOOT_TRACER -/* Append the trace on the ring-buffer */ -extern void trace_boot (struct boot_trace *it,initcall_t fn); +/* Append the traces on the ring-buffer */ +extern void trace_boot_call (struct boot_trace_call *bt,initcall_t fn); +extern void trace_boot_ret (struct boot_trace_ret *bt,initcall_t fn);/* Tells the tracer that smp_pre_initcall is finished. * So we can start the tracing
@@ -34,7 +42,12 @@ extern void enable_boot_trace(void);*/ extern void disable_boot_trace (void );#else -static inline void trace_boot (struct boot_trace *it,initcall_t fn) { } +static inline +void trace_boot_call (struct boot_trace_call *bt,initcall_t fn) { } + +static inline +void trace_boot_ret (struct boot_trace_ret *bt,initcall_t fn) { } +static inline void start_boot_trace (void ) { }static inline void enable_boot_trace (void ) { }static inline void disable_boot_trace (void ) { }
init/main.c +17 -15
@@ -712,33 +712,35 @@ core_param(initcall_debug, initcall_debug, bool, 0644);int do_one_initcall (initcall_t fn) {int count =preempt_count (); -ktime_t delta; +ktime_t calltime, delta, rettime;char msgbuf[64 ]; -struct boot_trace it; +struct boot_trace_call call; +struct boot_trace_ret ret;if (initcall_debug) { - it.caller =task_pid_nr (current); -printk ("calling %pF @ %i\n" , fn, it.caller); - it.calltime =ktime_get (); + call.caller =task_pid_nr (current); +printk ("calling %pF @ %i\n" , fn, call.caller); + calltime =ktime_get (); +trace_boot_call (&call, fn);enable_boot_trace (); } - it.result =fn (); + ret.result =fn ();if (initcall_debug) { - it.rettime =ktime_get (); - delta =ktime_sub (it.rettime, it.calltime); - it.duration = (unsigned long long ) delta.tv64 >>10 ; -printk ("initcall %pF returned %d after %Ld usecs\n" , fn, - it.result, it.duration); -trace_boot (&it, fn);disable_boot_trace (); + rettime =ktime_get (); + delta =ktime_sub (rettime, calltime); + ret.duration = (unsigned long long ) delta.tv64 >>10 ; +trace_boot_ret (&ret, fn); +printk ("initcall %pF returned %d after %Ld usecs\n" , fn, + ret.result, ret.duration); } msgbuf[0 ] =0 ; -if (it.result && it.result != -ENODEV && initcall_debug) -sprintf (msgbuf,"error code %d " , it.result); +if (ret.result && ret.result != -ENODEV && initcall_debug) +sprintf (msgbuf,"error code %d " , ret.result);if (preempt_count () != count) {strlcat (msgbuf,"preemption imbalance " ,sizeof (msgbuf));
@@ -752,7 +754,7 @@ int do_one_initcall(initcall_t fn)printk ("initcall %pF returned with %s\n" , fn, msgbuf); } -return it.result; +return ret.result; }
kernel/trace/trace.h +12 -5
@@ -22,7 +22,8 @@ enum trace_type {TRACE_SPECIAL ,TRACE_MMIO_RW ,TRACE_MMIO_MAP , -TRACE_BOOT , +TRACE_BOOT_CALL , +TRACE_BOOT_RET ,TRACE_FN_RET , __TRACE_LAST_TYPE
@@ -123,9 +124,14 @@ struct trace_mmiotrace_map {struct mmiotrace_map map; }; -struct trace_boot { +struct trace_boot_call {struct trace_entry ent; -struct boot_trace initcall; +struct boot_trace_call boot_call; +}; + +struct trace_boot_ret { +struct trace_entry ent; +struct boot_trace_ret boot_ret; };/*
@@ -228,8 +234,9 @@ extern void __ftrace_bad_type(void); TRACE_MMIO_RW); \ IF_ASSIGN(var, ent, struct trace_mmiotrace_map, \TRACE_MMIO_MAP ); \ - IF_ASSIGN(var, ent, struct trace_boot, TRACE_BOOT); \ - IF_ASSIGN(var, ent, struct ftrace_ret_entry, TRACE_FN_RET); \ + IF_ASSIGN(var, ent, struct trace_boot_call, TRACE_BOOT_CALL);\ + IF_ASSIGN(var, ent, struct trace_boot_ret, TRACE_BOOT_RET);\ + IF_ASSIGN(var, ent, struct ftrace_ret_entry, TRACE_FN_RET);\__ftrace_bad_type (); \ }while (0 )
kernel/trace/trace_boot.c +93 -30
156 lines not on this page · raw message
Signature · 1 line
1.5.2.5
Quoted 11 lines · Frederic Weisbecker
Impact: Split the boot tracer entries in two parts: call and return
Now that we are using the sched tracer from the boot tracer, we want to use the same timestamp than the ring-buffer to have consistent time captures between sched events and initcall events. So we get rid of the old time capture by the boot tracer and split the initcall events in two parts: call and return. This way we have the ring buffer timestamp of both.
There is an example of a trace in attachment.
Quoted 7 lines
Signed-off-by Frederic Weisbecker <[email protected]>--- include/trace/boot.h | 31 ++++++++--- init/main.c | 32 ++++++------ kernel/trace/trace.h | 17 ++++-- kernel/trace/trace_boot.c | 123 ++++++++++++++++++++++++++++++++++----------- 4 files changed, 144 insertions(+), 59 deletions(-)
applied to tip/tracing/fastboot, thanks Frederic!
one small detail, do we need these messages in the boot tracer:
##### CPU 1 buffer started ####
they are helpful for latency traces but might be confusing for boot traces. (they lose their attraction after having seen a dozen of them)
Ingo
2008/11/12 Ingo Molnar <[email protected]>:
Quoted 24 lines · Frederic Weisbecker
Quoted 12 lines
Impact: Split the boot tracer entries in two parts: call and return
Now that we are using the sched tracer from the boot tracer, we want to use the same timestamp than the ring-buffer to have consistent time captures between sched events and initcall events. So we get rid of the old time capture by the boot tracer and split the initcall events in two parts: call and return. This way we have the ring buffer timestamp of both.
There is an example of a trace in attachment.
Quoted 7 lines
Signed-off-by Frederic Weisbecker <[email protected]>--- include/trace/boot.h | 31 ++++++++--- init/main.c | 32 ++++++------ kernel/trace/trace.h | 17 ++++-- kernel/trace/trace_boot.c | 123 ++++++++++++++++++++++++++++++++++----------- 4 files changed, 144 insertions(+), 59 deletions(-)applied to tip/tracing/fastboot, thanks Frederic!
Quoted 9 lines
one small detail, do we need these messages in the boot tracer:
##### CPU 1 buffer started ####
they are helpful for latency traces but might be confusing for boot traces. (they lose their attraction after having seen a dozen of them)
Ingo
Yes. I'm using the default formatting output in trace.c so perhaps there is some iter flag I should dynamically remove
from the boot tracer to avoid that or perhaps I may format a custom output for sched entries for the boot tracer.
I will see that....
By the way Arjan, does the actual state of the boot tracer match your needs? You can find an example of its trace here:
http://git.kernel.org/?p=linux/kernel/git/x86/linux-2.6-tip.git;a=commit;h=74239072830ef3f1398edeb1bc1076fc330fd4a2
Steven Rostedt
maintainerQuoted 22 lines · Ingo Molnar
Quoted 11 lines · Frederic Weisbecker
Impact: Split the boot tracer entries in two parts: call and return
Now that we are using the sched tracer from the boot tracer, we want to use the same timestamp than the ring-buffer to have consistent time captures between sched events and initcall events. So we get rid of the old time capture by the boot tracer and split the initcall events in two parts: call and return. This way we have the ring buffer timestamp of both.
There is an example of a trace in attachment.
Quoted 7 lines
Signed-off-by Frederic Weisbecker <[email protected]>--- include/trace/boot.h | 31 ++++++++--- init/main.c | 32 ++++++------ kernel/trace/trace.h | 17 ++++-- kernel/trace/trace_boot.c | 123 ++++++++++++++++++++++++++++++++++----------- 4 files changed, 144 insertions(+), 59 deletions(-)
Quoted 8 lines
applied to tip/tracing/fastboot, thanks Frederic!
one small detail, do we need these messages in the boot tracer:
##### CPU 1 buffer started ####
they are helpful for latency traces but might be confusing for boot traces. (they lose their attraction after having seen a dozen of them)
Yeah, I was thinking of putting in a iter_ctrl to disable them. But then, should they be on or off by default?
The pro for having them off by default, they are not as distracting.
The con for having them off by default, they lose their meaning, and developers get confused when they see CPU 1 starting after 100 prints of CPU0, when they both should have started.
-- Steve
Quoted 34 lines · Steven Rostedt
Quoted 22 lines · Ingo Molnar
Quoted 11 lines · Frederic Weisbecker
Impact: Split the boot tracer entries in two parts: call and return
Now that we are using the sched tracer from the boot tracer, we want to use the same timestamp than the ring-buffer to have consistent time captures between sched events and initcall events. So we get rid of the old time capture by the boot tracer and split the initcall events in two parts: call and return. This way we have the ring buffer timestamp of both.
There is an example of a trace in attachment.
Quoted 7 lines
Signed-off-by Frederic Weisbecker <[email protected]>--- include/trace/boot.h | 31 ++++++++--- init/main.c | 32 ++++++------ kernel/trace/trace.h | 17 ++++-- kernel/trace/trace_boot.c | 123 ++++++++++++++++++++++++++++++++++----------- 4 files changed, 144 insertions(+), 59 deletions(-)Quoted 8 lines
applied to tip/tracing/fastboot, thanks Frederic!
one small detail, do we need these messages in the boot tracer:
##### CPU 1 buffer started ####
they are helpful for latency traces but might be confusing for boot traces. (they lose their attraction after having seen a dozen of them)
Quoted 8 lines
Yeah, I was thinking of putting in a
iter_ctrlto disable them. But then, should they be on or off by default?The pro for having them off by default, they are not as distracting.
The con for having them off by default, they lose their meaning, and developers get confused when they see CPU 1 starting after 100 prints of CPU0, when they both should have started.
i think they are useful to be included for most of the tracers, except the boot tracer (which starts/stop with high frequency). So i'd suggest to keep the default, but also to expose it in an iter_ctl plus dynamically turn it off for the boot tracer.
Ingo