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>
This commit is contained in:
Frederic Weisbecker 2008-10-02 12:59:20 +02:00 committed by Ingo Molnar
parent 77ae11f63b
commit cb5ab74204
3 changed files with 26 additions and 18 deletions

View File

@ -216,6 +216,8 @@ struct boot_trace {
initcall_t func; initcall_t func;
int result; int result;
unsigned long long duration; unsigned long long duration;
ktime_t calltime;
ktime_t rettime;
}; };
#ifdef CONFIG_BOOT_TRACER #ifdef CONFIG_BOOT_TRACER

View File

@ -706,34 +706,32 @@ __setup("initcall_debug", initcall_debug_setup);
int do_one_initcall(initcall_t fn) int do_one_initcall(initcall_t fn)
{ {
int count = preempt_count(); int count = preempt_count();
ktime_t t0, t1, delta; ktime_t delta;
char msgbuf[64]; char msgbuf[64];
int result;
struct boot_trace it; struct boot_trace it;
if (initcall_debug) { if (initcall_debug) {
it.caller = task_pid_nr(current); it.caller = task_pid_nr(current);
it.func = fn; it.func = fn;
printk("calling %pF @ %i\n", fn, it.caller); printk("calling %pF @ %i\n", fn, it.caller);
t0 = ktime_get(); it.calltime = ktime_get();
} }
result = fn(); it.result = fn();
if (initcall_debug) { if (initcall_debug) {
t1 = ktime_get(); it.rettime = ktime_get();
delta = ktime_sub(t1, t0); delta = ktime_sub(it.rettime, it.calltime);
it.result = result;
it.duration = (unsigned long long) delta.tv64 >> 20; it.duration = (unsigned long long) delta.tv64 >> 20;
printk("initcall %pF returned %d after %Ld msecs\n", fn, printk("initcall %pF returned %d after %Ld msecs\n", fn,
result, it.duration); it.result, it.duration);
trace_boot(&it); trace_boot(&it);
} }
msgbuf[0] = 0; msgbuf[0] = 0;
if (result && result != -ENODEV && initcall_debug) if (it.result && it.result != -ENODEV && initcall_debug)
sprintf(msgbuf, "error code %d ", result); sprintf(msgbuf, "error code %d ", it.result);
if (preempt_count() != count) { if (preempt_count() != count) {
strlcat(msgbuf, "preemption imbalance ", sizeof(msgbuf)); 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); printk("initcall %pF returned with %s\n", fn, msgbuf);
} }
return result; return it.result;
} }

View File

@ -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 trace_boot *field = (struct trace_boot *)entry;
struct boot_trace *it = &field->initcall; struct boot_trace *it = &field->initcall;
struct trace_seq *s = &iter->seq; 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) { if (entry->type == TRACE_BOOT) {
ret = trace_seq_printf(s, "%pF called from %i " ret = trace_seq_printf(s, "[%5ld.%06ld] calling %pF @ %i\n",
"returned %d after %lld msecs\n", calltime.tv_sec,
it->func, it->caller, it->result, calltime.tv_nsec,
it->duration); it->func, it->caller);
if (ret) if (!ret)
return TRACE_TYPE_HANDLED;
else
return TRACE_TYPE_PARTIAL_LINE; 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; return TRACE_TYPE_UNHANDLED;
} }