Skip to content
  • Frederic Weisbecker's avatar
    tracing/fastboot: Use the ring-buffer timestamp for initcall entries · 74239072
    Frederic Weisbecker authored
    
    
    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: default avatarFrederic Weisbecker <fweisbec@gmail.com>
    Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    74239072