tracing/fastboot: Make the boot tracer use the cpu_clock
PATCH 3/5 tracing/fastboot: Make the boot tracer use the cpu_clock
Make the boot tracer use the cpu_clock() rather than the ktime API. This way we will be able to unify the time capture with the sched_switch tracer.
Also delete the duration attribute which is not needed and can be retrieved at print time.
--- include/linux/ftrace.h | 5 ++--- init/main.c | 25 ++++++++++++++++++------- kernel/trace/trace_boot.c | 18 ++++++++++-------- 3 files changed, 30 insertions(+), 18 deletions(-)
include/linux/ftrace.h +2 -3
@@ -222,9 +222,8 @@ struct boot_trace {pid_t caller;char func[KSYM_NAME_LEN ];int result; -unsigned long long duration; -ktime_t calltime; -ktime_t rettime; +unsigned long long calltime; +unsigned long long rettime; };#ifdef CONFIG_BOOT_TRACER
init/main.c +18 -7
@@ -721,27 +721,38 @@ __setup("initcall_debug", initcall_debug_setup);int do_one_initcall (initcall_t fn) {int count =preempt_count (); -ktime_t delta; +ktime_t delta, t0, t1;char msgbuf[64 ]; +unsigned long long duration;struct boot_trace it;if (initcall_debug) { +long cpu; it.caller =task_pid_nr (current);printk ("calling %pF @ %i\n" , fn, it.caller); - it.calltime =ktime_get (); + t0 =ktime_get (); +preempt_disable (); + cpu =raw_smp_processor_id (); + it.calltime =cpu_clock (cpu); +preempt_enable ();enable_boot_trace (); } it.result =fn ();if (initcall_debug) { - it.rettime =ktime_get (); - delta =ktime_sub (it.rettime, it.calltime); - it.duration = (unsigned long long ) delta.tv64 >>20 ; +long cpu; +disable_boot_trace (); + t1 =ktime_get (); +preempt_disable (); + cpu =raw_smp_processor_id (); + it.rettime =cpu_clock (cpu); +preempt_enable (); + delta =ktime_sub (t1, t0); + duration = (unsigned long long ) delta.tv64 >>20 ;printk ("initcall %pF returned %d after %Ld msecs\n" , fn, - it.result, it.duration); + it.result, duration);trace_boot (&it, fn); -disable_boot_trace (); } msgbuf[0 ] =0 ;
kernel/trace/trace_boot.c +10 -8
@@ -68,22 +68,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); +unsigned long sec, nsec_rem; +unsigned long long duration = it->rettime - it->calltime;if (entry->type ==TRACE_BOOT ) { + nsec_rem =do_div (it->calltime,1000000000 ); + sec = (unsigned long ) it->calltime; ret =trace_seq_printf (s,"[%5ld.%09ld] calling %s @ %i\n" , - calltime.tv_sec, - calltime.tv_nsec, - it->func, it->caller); + sec, nsec_rem, it->func, it->caller);if (!ret)return TRACE_TYPE_PARTIAL_LINE ; + nsec_rem =do_div (it->rettime,1000000000 ); + sec = (unsigned long ) it->rettime; +do_div (duration,1000 ); ret =trace_seq_printf (s,"[%5ld.%09ld] initcall %s " "returned %d after %lld msecs\n" , - rettime.tv_sec, - rettime.tv_nsec, - it->func, it->result, it->duration); + sec, nsec_rem, it->func, it->result, + duration);if (!ret)return TRACE_TYPE_PARTIAL_LINE ;
2008/10/11 Frederic Weisbecker <[email protected]>:
Quoted 108 lines
Make the boot tracer use the
cpu_clock()rather than the ktime API. This way we will be able to unify the time capture with thesched_switchtracer.
Also delete the duration attribute which is not needed and can be retrieved at print time.Signed-off-by Frederic Weisbecker <[email protected]>Cc Arjan van de Ven <[email protected]>--- include/linux/ftrace.h | 5 ++--- init/main.c | 25 ++++++++++++++++++------- kernel/trace/trace_boot.c | 18 ++++++++++-------- 3 files changed, 30 insertions(+), 18 deletions(-)include/linux/ftrace.h +2
-3@@ -222,9 +222,8 @@ struct boot_trace {pid_t caller;char func[KSYM_NAME_LEN ];int result; -unsigned long long duration; -ktime_t calltime; -ktime_t rettime; +unsigned long long calltime; +unsigned long long rettime; };#ifdef CONFIG_BOOT_TRACER init/main.c +18
-7@@ -721,27 +721,38 @@ __setup("initcall_debug", initcall_debug_setup);int do_one_initcall (initcall_t fn) {int count =preempt_count (); -ktime_t delta; +ktime_t delta, t0, t1;char msgbuf[64 ]; +unsigned long long duration;struct boot_trace it;if (initcall_debug) { +long cpu; it.caller =task_pid_nr (current);printk ("calling %pF @ %i\n" , fn, it.caller); - it.calltime =ktime_get (); + t0 =ktime_get (); +preempt_disable (); + cpu =raw_smp_processor_id (); + it.calltime =cpu_clock (cpu); +preempt_enable ();enable_boot_trace (); } it.result =fn ();if (initcall_debug) { - it.rettime =ktime_get (); - delta =ktime_sub (it.rettime, it.calltime); - it.duration = (unsigned long long ) delta.tv64 >>20 ; +long cpu; +disable_boot_trace (); + t1 =ktime_get (); +preempt_disable (); + cpu =raw_smp_processor_id (); + it.rettime =cpu_clock (cpu); +preempt_enable (); + delta =ktime_sub (t1, t0); + duration = (unsigned long long ) delta.tv64 >>20 ;printk ("initcall %pF returned %d after %Ld msecs\n" , fn, - it.result, it.duration); + it.result, duration);trace_boot (&it, fn); -disable_boot_trace (); } msgbuf[0 ] =0 ;kernel/trace/trace_boot.c +8
-5@@ -68,22 +68,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); +unsigned long sec, nsec_rem; +unsigned long long duration = it->rettime - it->calltime;if (entry->type ==TRACE_BOOT ) { + nsec_rem =do_div (it->calltime,1000000000 ); + sec = (unsigned long ) it->calltime; ret =trace_seq_printf (s,"[%5ld.%09ld] calling %s @ %i\n" , - calltime.tv_sec, - calltime.tv_nsec, - it->func, it->caller); + sec, nsec_rem, it->func, it->caller);if (!ret)return TRACE_TYPE_PARTIAL_LINE ; + nsec_rem =do_div (it->rettime,1000000000 ); + sec = (unsigned long ) it->rettime; +do_div (duration,1000 );
kernel/trace/trace_boot.c static enum print_line_t initcall_print_line(struct trace_iterator *iter) · line 91
Quoted 10 lines
kernel/trace/trace_boot.c +2
-3ret =trace_seq_printf (s,"[%5ld.%09ld] initcall %s " "returned %d after %lld msecs\n" , - rettime.tv_sec, - rettime.tv_nsec, - it->func, it->result, it->duration); + sec, nsec_rem, it->func, it->result, + duration);if (!ret)return TRACE_TYPE_PARTIAL_LINE ;
Please just ignore this patch. I think I will change a bit the design of the boot tracer by sending
two types of entries: the call and the return. With this new approach, I will be able to use the internal
timestamp of the ring buffer and stay consistent with the same used for sched switch entries.
Thanks.