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 <fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 91954eb6460f9a601fa3a5030286ff6100e377c7..4455490d91bdb62e6be34da1b6074cc0346c1716 100644 (file)
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -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

diff --git a/init/main.c b/init/main.c
index 1e39a1eab1900b7b336323b9ac97d82570e05ec5..61eb661593915cbe9a6e85a1481c3b5b149dcad7 100644 (file)
--- a/init/main.c
+++ b/init/main.c
@@ -706,34 +706,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));
@@ -747,7 +745,7 @@ int do_one_initcall(initcall_t fn)
                printk("initcall %pF returned with %s\n", fn, msgbuf);
        }
 
-       return result;
+       return it.result;
 }
 
 

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index f2dac6f1cf062ae2092f3305295ad87fadee5110..7c15f3e68ba35e25c114e4ed09e017bc27c81d31 100644 (file)
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -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;
 }