tracing/fastboot: Use the ring-buffer timestamp for initcall entries
Impact: Split the boot tracer entries in two parts: call and return
Now that we are using the sched tracer from the boot tracer, we want
to use the same timestamp than the ring-buffer to have consistent time
captures between sched events and initcall events.
So we get rid of the old time capture by the boot tracer and split the
initcall events in two parts: call and return. This way we have the
ring buffer timestamp of both.
An example trace:
[ 27.904149584] calling net_ns_init+0x0/0x1c0 @ 1
[ 27.904429624] initcall net_ns_init+0x0/0x1c0 returned 0 after 0 msecs
[ 27.904575926] calling reboot_init+0x0/0x20 @ 1
[ 27.904655399] initcall reboot_init+0x0/0x20 returned 0 after 0 msecs
[ 27.904800228] calling sysctl_init+0x0/0x30 @ 1
[ 27.905142914] initcall sysctl_init+0x0/0x30 returned 0 after 0 msecs
[ 27.905287211] calling ksysfs_init+0x0/0xb0 @ 1
##### CPU 0 buffer started ####
init-1 [000] 27.905395: 1:120:R + [001] 11:115:S
##### CPU 1 buffer started ####
<idle>-0 [001] 27.905425: 0:140:R ==> [001] 11:115:R
init-1 [000] 27.905426: 1:120:D ==> [000] 0:140:R
<idle>-0 [000] 27.905431: 0:140:R + [000] 4:115:S
<idle>-0 [000] 27.905451: 0:140:R ==> [000] 4:115:R
ksoftirqd/0-4 [000] 27.905456: 4:115:S ==> [000] 0:140:R
udevd-11 [001] 27.905458: 11:115:R + [001] 14:115:R
<idle>-0 [000] 27.905459: 0:140:R + [000] 4:115:S
<idle>-0 [000] 27.905462: 0:140:R ==> [000] 4:115:R
udevd-11 [001] 27.905462: 11:115:R ==> [001] 14:115:R
ksoftirqd/0-4 [000] 27.905467: 4:115:S ==> [000] 0:140:R
<idle>-0 [000] 27.905470: 0:140:R + [000] 4:115:S
<idle>-0 [000] 27.905473: 0:140:R ==> [000] 4:115:R
ksoftirqd/0-4 [000] 27.905476: 4:115:S ==> [000] 0:140:R
<idle>-0 [000] 27.905479: 0:140:R + [000] 4:115:S
<idle>-0 [000] 27.905482: 0:140:R ==> [000] 4:115:R
ksoftirqd/0-4 [000] 27.905486: 4:115:S ==> [000] 0:140:R
udevd-14 [001] 27.905499: 14:120:X ==> [001] 11:115:R
udevd-11 [001] 27.905506: 11:115:R + [000] 1:120:D
<idle>-0 [000] 27.905515: 0:140:R ==> [000] 1:120:R
udevd-11 [001] 27.905517: 11:115:S ==> [001] 0:140:R
[ 27.905557107] initcall ksysfs_init+0x0/0xb0 returned 0 after 3906 msecs
[ 27.905705736] calling init_jiffies_clocksource+0x0/0x10 @ 1
[ 27.905779239] initcall init_jiffies_clocksource+0x0/0x10 returned 0 after 0 msecs
[ 27.906769814] calling pm_init+0x0/0x30 @ 1
[ 27.906853627] initcall pm_init+0x0/0x30 returned 0 after 0 msecs
[ 27.906997803] calling pm_disk_init+0x0/0x20 @ 1
[ 27.907076946] initcall pm_disk_init+0x0/0x20 returned 0 after 0 msecs
[ 27.907222556] calling swsusp_header_init+0x0/0x30 @ 1
[ 27.907294325] initcall swsusp_header_init+0x0/0x30 returned 0 after 0 msecs
[ 27.907439620] calling stop_machine_init+0x0/0x50 @ 1
init-1 [000] 27.907485: 1:120:R + [000] 2:115:S
init-1 [000] 27.907490: 1:120:D ==> [000] 2:115:R
kthreadd-2 [000] 27.907507: 2:115:R + [001] 15:115:R
<idle>-0 [001] 27.907517: 0:140:R ==> [001] 15:115:R
kthreadd-2 [000] 27.907517: 2:115:D ==> [000] 0:140:R
<idle>-0 [000] 27.907521: 0:140:R + [000] 4:115:S
<idle>-0 [000] 27.907524: 0:140:R ==> [000] 4:115:R
udevd-15 [001] 27.907527: 15:115:D + [000] 2:115:D
ksoftirqd/0-4 [000] 27.907537: 4:115:S ==> [000] 2:115:R
udevd-15 [001] 27.907537: 15:115:D ==> [001] 0:140:R
kthreadd-2 [000] 27.907546: 2:115:R + [000] 1:120:D
kthreadd-2 [000] 27.907550: 2:115:S ==> [000] 1:120:R
init-1 [000] 27.907584: 1:120:R + [000] 15: 0:D
init-1 [000] 27.907589: 1:120:R + [000] 2:115:S
init-1 [000] 27.907593: 1:120:D ==> [000] 15: 0:R
udevd-15 [000] 27.907601: 15: 0:S ==> [000] 2:115:R
##### CPU 0 buffer started ####
kthreadd-2 [000] 27.907616: 2:115:R + [001] 16:115:R
##### CPU 1 buffer started ####
<idle>-0 [001] 27.907620: 0:140:R ==> [001] 16:115:R
kthreadd-2 [000] 27.907621: 2:115:D ==> [000] 0:140:R
udevd-16 [001] 27.907625: 16:115:D + [000] 2:115:D
<idle>-0 [000] 27.907628: 0:140:R + [000] 4:115:S
udevd-16 [001] 27.907629: 16:115:D ==> [001] 0:140:R
<idle>-0 [000] 27.907631: 0:140:R ==> [000] 4:115:R
ksoftirqd/0-4 [000] 27.907636: 4:115:S ==> [000] 2:115:R
kthreadd-2 [000] 27.907644: 2:115:R + [000] 1:120:D
kthreadd-2 [000] 27.907647: 2:115:S ==> [000] 1:120:R
init-1 [000] 27.907657: 1:120:R + [001] 16: 0:D
<idle>-0 [001] 27.907666: 0:140:R ==> [001] 16: 0:R
[ 27.907703862] initcall stop_machine_init+0x0/0x50 returned 0 after 0 msecs
[ 27.907850704] calling filelock_init+0x0/0x30 @ 1
[ 27.907926573] initcall filelock_init+0x0/0x30 returned 0 after 0 msecs
[ 27.908071327] calling init_script_binfmt+0x0/0x10 @ 1
[ 27.908165195] initcall init_script_binfmt+0x0/0x10 returned 0 after 0 msecs
[ 27.908309461] calling init_elf_binfmt+0x0/0x10 @ 1
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
diff --git a/init/main.c b/init/main.c
index 16ca1ee..e810196 100644
--- a/init/main.c
+++ b/init/main.c
@@ -704,33 +704,35 @@
int do_one_initcall(initcall_t fn)
{
int count = preempt_count();
- ktime_t delta;
+ ktime_t calltime, delta, rettime;
char msgbuf[64];
- struct boot_trace it;
+ struct boot_trace_call call;
+ struct boot_trace_ret ret;
if (initcall_debug) {
- it.caller = task_pid_nr(current);
- printk("calling %pF @ %i\n", fn, it.caller);
- it.calltime = ktime_get();
+ call.caller = task_pid_nr(current);
+ printk("calling %pF @ %i\n", fn, call.caller);
+ calltime = ktime_get();
+ trace_boot_call(&call, fn);
enable_boot_trace();
}
- it.result = fn();
+ ret.result = fn();
if (initcall_debug) {
- it.rettime = ktime_get();
- delta = ktime_sub(it.rettime, it.calltime);
- it.duration = (unsigned long long) delta.tv64 >> 10;
- printk("initcall %pF returned %d after %Ld usecs\n", fn,
- it.result, it.duration);
- trace_boot(&it, fn);
disable_boot_trace();
+ rettime = ktime_get();
+ delta = ktime_sub(rettime, calltime);
+ ret.duration = (unsigned long long) delta.tv64 >> 10;
+ trace_boot_ret(&ret, fn);
+ printk("initcall %pF returned %d after %Ld usecs\n", fn,
+ ret.result, ret.duration);
}
msgbuf[0] = 0;
- if (it.result && it.result != -ENODEV && initcall_debug)
- sprintf(msgbuf, "error code %d ", it.result);
+ if (ret.result && ret.result != -ENODEV && initcall_debug)
+ sprintf(msgbuf, "error code %d ", ret.result);
if (preempt_count() != count) {
strlcat(msgbuf, "preemption imbalance ", sizeof(msgbuf));
@@ -744,7 +746,7 @@
printk("initcall %pF returned with %s\n", fn, msgbuf);
}
- return it.result;
+ return ret.result;
}