aboutsummaryrefslogtreecommitdiffstats
path: root/init
diff options
context:
space:
mode:
authorFrederic Weisbecker <fweisbec@gmail.com>2008-11-11 17:24:42 -0500
committerIngo Molnar <mingo@elte.hu>2008-11-12 04:17:19 -0500
commit74239072830ef3f1398edeb1bc1076fc330fd4a2 (patch)
tree60a244c6c88d9943760ded98a1a29ce018292107 /init
parent3f5ec13696fd4a33bde42f385406cbb1d3cc96fd (diff)
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>
Diffstat (limited to 'init')
-rw-r--r--init/main.c32
1 files changed, 17 insertions, 15 deletions
diff --git a/init/main.c b/init/main.c
index 16ca1ee071c4..e810196bf2f2 100644
--- a/init/main.c
+++ b/init/main.c
@@ -704,33 +704,35 @@ core_param(initcall_debug, initcall_debug, bool, 0644);
704int do_one_initcall(initcall_t fn) 704int do_one_initcall(initcall_t fn)
705{ 705{
706 int count = preempt_count(); 706 int count = preempt_count();
707 ktime_t delta; 707 ktime_t calltime, delta, rettime;
708 char msgbuf[64]; 708 char msgbuf[64];
709 struct boot_trace it; 709 struct boot_trace_call call;
710 struct boot_trace_ret ret;
710 711
711 if (initcall_debug) { 712 if (initcall_debug) {
712 it.caller = task_pid_nr(current); 713 call.caller = task_pid_nr(current);
713 printk("calling %pF @ %i\n", fn, it.caller); 714 printk("calling %pF @ %i\n", fn, call.caller);
714 it.calltime = ktime_get(); 715 calltime = ktime_get();
716 trace_boot_call(&call, fn);
715 enable_boot_trace(); 717 enable_boot_trace();
716 } 718 }
717 719
718 it.result = fn(); 720 ret.result = fn();
719 721
720 if (initcall_debug) { 722 if (initcall_debug) {
721 it.rettime = ktime_get();
722 delta = ktime_sub(it.rettime, it.calltime);
723 it.duration = (unsigned long long) delta.tv64 >> 10;
724 printk("initcall %pF returned %d after %Ld usecs\n", fn,
725 it.result, it.duration);
726 trace_boot(&it, fn);
727 disable_boot_trace(); 723 disable_boot_trace();
724 rettime = ktime_get();
725 delta = ktime_sub(rettime, calltime);
726 ret.duration = (unsigned long long) delta.tv64 >> 10;
727 trace_boot_ret(&ret, fn);
728 printk("initcall %pF returned %d after %Ld usecs\n", fn,
729 ret.result, ret.duration);
728 } 730 }
729 731
730 msgbuf[0] = 0; 732 msgbuf[0] = 0;
731 733
732 if (it.result && it.result != -ENODEV && initcall_debug) 734 if (ret.result && ret.result != -ENODEV && initcall_debug)
733 sprintf(msgbuf, "error code %d ", it.result); 735 sprintf(msgbuf, "error code %d ", ret.result);
734 736
735 if (preempt_count() != count) { 737 if (preempt_count() != count) {
736 strlcat(msgbuf, "preemption imbalance ", sizeof(msgbuf)); 738 strlcat(msgbuf, "preemption imbalance ", sizeof(msgbuf));
@@ -744,7 +746,7 @@ int do_one_initcall(initcall_t fn)
744 printk("initcall %pF returned with %s\n", fn, msgbuf); 746 printk("initcall %pF returned with %s\n", fn, msgbuf);
745 } 747 }
746 748
747 return it.result; 749 return ret.result;
748} 750}
749 751
750 752
generated by cgit v1.2.2 (git 2.25.0) at 2024-10-24 01:34:32 -0400