[PATCH 3/5] tracing/fastboot: Make the boot tracer use the cpu_clock - Kernel

This is a discussion on [PATCH 3/5] tracing/fastboot: Make the boot tracer use the cpu_clock - Kernel ; 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 ...

+ Reply to Thread
Results 1 to 2 of 2

Thread: [PATCH 3/5] tracing/fastboot: Make the boot tracer use the cpu_clock

  1. [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.

    Signed-off-by: Frederic Weisbecker
    Cc: Arjan van de Ven
    ---
    include/linux/ftrace.h | 5 ++---
    init/main.c | 25 ++++++++++++++++++-------
    kernel/trace/trace_boot.c | 18 ++++++++++--------
    3 files changed, 30 insertions(+), 18 deletions(-)

    diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
    index 135a33f..36b570b 100644
    --- a/include/linux/ftrace.h
    +++ b/include/linux/ftrace.h
    @@ -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
    diff --git a/init/main.c b/init/main.c
    index 98c05aa..bf13013 100644
    --- a/init/main.c
    +++ b/init/main.c
    @@ -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;
    diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
    index bd5046c..20d326b 100644
    --- a/kernel/trace/trace_boot.c
    +++ b/kernel/trace/trace_boot.c
    @@ -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;
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  2. Re: [PATCH 3/5] tracing/fastboot: Make the boot tracer use the cpu_clock

    2008/10/11 Frederic Weisbecker :
    > 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.
    >
    > Signed-off-by: Frederic Weisbecker
    > Cc: Arjan van de Ven
    > ---
    > include/linux/ftrace.h | 5 ++---
    > init/main.c | 25 ++++++++++++++++++-------
    > kernel/trace/trace_boot.c | 18 ++++++++++--------
    > 3 files changed, 30 insertions(+), 18 deletions(-)
    >
    > diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
    > index 135a33f..36b570b 100644
    > --- a/include/linux/ftrace.h
    > +++ b/include/linux/ftrace.h
    > @@ -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
    > diff --git a/init/main.c b/init/main.c
    > index 98c05aa..bf13013 100644
    > --- a/init/main.c
    > +++ b/init/main.c
    > @@ -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;
    > diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
    > index bd5046c..20d326b 100644
    > --- a/kernel/trace/trace_boot.c
    > +++ b/kernel/trace/trace_boot.c
    > @@ -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;
    >


    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.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

+ Reply to Thread