Tracing/fastboot: Change the printing of boot tracer according to bootgraph.pl
PATCH 1/2 Tracing/fastboot: Change the printing of boot tracer according to bootgraph.pl
Change the boot tracer printing to make it parsable for the scripts/bootgraph.pl script.
We have now to output two lines for each initcall, according to the printk in do_one_initcall() in init/main.c
We need now the call's time and the return's time.
Signed-off-by Frederic Weisbecker <[email protected]>
--- include/linux/ftrace.h | 2 ++ init/main.c | 20 +++++++++----------- kernel/trace/trace_boot.c | 22 +++++++++++++++------- 3 files changed, 26 insertions(+), 18 deletions(-)
include/linux/ftrace.h +2 -0
@@ -216,6 +216,8 @@ struct boot_trace {initcall_t func;int result;unsigned long long duration; +ktime_t calltime; +ktime_t rettime; };#ifdef CONFIG_BOOT_TRACER
init/main.c +9 -11
@@ -721,34 +721,32 @@ __setup("initcall_debug", initcall_debug_setup);int do_one_initcall (initcall_t fn) {int count =preempt_count (); -ktime_t t0, t1, delta; +ktime_t delta;char msgbuf[64 ]; -int result;struct boot_trace it;if (initcall_debug) { it.caller =task_pid_nr (current); it.func = fn;printk ("calling %pF @ %i\n" , fn, it.caller); - t0 =ktime_get (); + it.calltime =ktime_get (); } - result =fn (); + it.result =fn ();if (initcall_debug) { - t1 =ktime_get (); - delta =ktime_sub (t1, t0); - it.result = result; + it.rettime =ktime_get (); + delta =ktime_sub (it.rettime, it.calltime); it.duration = (unsigned long long ) delta.tv64 >>20 ;printk ("initcall %pF returned %d after %Ld msecs\n" , fn, - result, it.duration); + it.result, it.duration);trace_boot (&it); } msgbuf[0 ] =0 ; -if (result && result != -ENODEV && initcall_debug) -sprintf (msgbuf,"error code %d " , result); +if (it.result && it.result != -ENODEV && initcall_debug) +sprintf (msgbuf,"error code %d " , it.result);if (preempt_count () != count) {strlcat (msgbuf,"preemption imbalance " ,sizeof (msgbuf));
@@ -763,7 +761,7 @@ int do_one_initcall(initcall_t fn)printk (" returned with %s\n" , msgbuf); } -return result; +return it.result; }
kernel/trace/trace_boot.c +15 -7
@@ -52,16 +52,24 @@ static enum print_line_t initcall_print_line(struct trace_iterator *iter)struct trace_boot *field = (struct trace_boot *)entry;struct boot_trace *it = &field->initcall;struct trace_seq *s = &iter->seq; +struct timespec calltime =ktime_to_timespec (it->calltime); +struct timespec rettime =ktime_to_timespec (it->rettime);if (entry->type ==TRACE_BOOT ) { - ret =trace_seq_printf (s,"%pF called from %i " -"returned %d after %lld msecs\n" , - it->func, it->caller, it->result, - it->duration); -if (ret) -return TRACE_TYPE_HANDLED ; -else + ret =trace_seq_printf (s,"[%5ld.%06ld] calling %pF @ %i\n" , + calltime.tv_sec, + calltime.tv_nsec, + it->func, it->caller); +if (!ret)return TRACE_TYPE_PARTIAL_LINE ; + ret =trace_seq_printf (s,"[%5ld.%06ld] initcall %pF " +"returned %d after %lld msecs\n" , + rettime.tv_sec, + rettime.tv_nsec, + it->func, it->result, it->duration); +if (!ret) +return TRACE_TYPE_PARTIAL_LINE ; +return TRACE_TYPE_HANDLED ; }return TRACE_TYPE_UNHANDLED ; }
Quoted 7 lines · Frederic Weisbecker
Change the boot tracer printing to make it parsable for the
scripts/bootgraph.plscript.
We have now to output two lines for each initcall, according to the printk indo_one_initcall()ininit/main.c
We need now the call's time and the return's time.Signed-off-by Frederic Weisbecker <[email protected]>
applied to tip/tracing/fastboot, thanks Frederic!
Ingo