1. 13 11月, 2008 2 次提交
  2. 12 11月, 2008 3 次提交
    • S
      tracing: likely/unlikely branch annotation tracer · 52f232cb
      Steven Rostedt 提交于
      Impact: new likely/unlikely branch tracer
      
      This patch adds a way to record the instances of the likely() and unlikely()
      branch condition annotations.
      
      When "unlikely" is set in /debugfs/tracing/iter_ctrl the unlikely conditions
      will be added to any of the ftrace tracers. The change takes effect when
      a new tracer is passed into the current_tracer file.
      
      For example:
      
       bash-3471  [003]   357.014755: [INCORRECT] sched_info_dequeued:sched_stats.h:177
       bash-3471  [003]   357.014756: [correct] update_curr:sched_fair.c:489
       bash-3471  [003]   357.014758: [correct] calc_delta_fair:sched_fair.c:411
       bash-3471  [003]   357.014759: [correct] account_group_exec_runtime:sched_stats.h:356
       bash-3471  [003]   357.014761: [correct] update_curr:sched_fair.c:489
       bash-3471  [003]   357.014763: [INCORRECT] calc_delta_fair:sched_fair.c:411
       bash-3471  [003]   357.014765: [correct] calc_delta_mine:sched.c:1279
      
      Which shows the normal tracer heading, as well as whether the condition was
      correct "[correct]" or was mistaken "[INCORRECT]", followed by the function,
      file name and line number.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      52f232cb
    • F
      tracing/fastboot: Use the ring-buffer timestamp for initcall entries · 74239072
      Frederic Weisbecker 提交于
      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: NFrederic Weisbecker <fweisbec@gmail.com>
      Acked-by: NSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      74239072
    • F
      tracing/fastboot: move boot tracer structs and funcs into their own header. · 3f5ec136
      Frederic Weisbecker 提交于
      Impact: Cleanups on the boot tracer and ftrace
      
      This patch bring some cleanups about the boot tracer headers. The
      functions and structures of this tracer have nothing related to ftrace
      and should have so their own header file.
      Signed-off-by: NFrederic Weisbecker <fweisbec@gmail.com>
      Acked-by: NSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      3f5ec136
  3. 11 11月, 2008 1 次提交
    • F
      tracing: add a tracer to catch execution time of kernel functions · 15e6cb36
      Frederic Weisbecker 提交于
      Impact: add new tracing plugin which can trace full (entry+exit) function calls
      
      This tracer uses the low level function return ftrace plugin to
      measure the execution time of the kernel functions.
      
      The first field is the caller of the function, the second is the
      measured function, and the last one is the execution time in
      nanoseconds.
      
      - v3:
      
      - HAVE_FUNCTION_RET_TRACER have been added. Each arch that support ftrace return
        should enable it.
      - ftrace_return_stub becomes ftrace_stub.
      - CONFIG_FUNCTION_RET_TRACER depends now on CONFIG_FUNCTION_TRACER
      - Return traces printing can be used for other tracers on trace.c
      - Adapt to the new tracing API (no more ctrl_update callback)
      - Correct the check of "disabled" during insertion.
      - Minor changes...
      Signed-off-by: NFrederic Weisbecker <fweisbec@gmail.com>
      Cc: Steven Rostedt <rostedt@goodmis.org>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      15e6cb36
  4. 08 11月, 2008 5 次提交
    • S
      ftrace: display start of CPU buffer in trace output · a309720c
      Steven Rostedt 提交于
      Impact: change in trace output
      
      Because the trace buffers are per cpu ring buffers, the start of
      the trace can be confusing. If one CPU is very active at the
      end of the trace, its history will not go as far back as the
      other CPU traces.  This means that output for a particular CPU
      may not appear for the first part of a trace.
      
      To help annotate what is happening, and to prevent any more
      confusion, this patch adds a line that annotates the start of
      a CPU buffer output.
      
      For example:
      
             automount-3495  [001]   184.596443: dnotify_parent <-vfs_write
      [...]
             automount-3495  [001]   184.596449: dput <-path_put
             automount-3496  [002]   184.596450: down_read_trylock <-do_page_fault
      [...]
                 sshd-3497  [001]   184.597069: up_read <-do_page_fault
                <idle>-0     [000]   184.597074: __exit_idle <-exit_idle
      [...]
             automount-3496  [002]   184.597257: filemap_fault <-__do_fault
                <idle>-0     [003]   184.597261: exit_idle <-smp_apic_timer_interrupt
      
      Note, parsers of a trace output should always ignore any lines that
      start with a '#'.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      a309720c
    • S
      ftrace: remove trace array ctrl · c76f0694
      Steven Rostedt 提交于
      Impact: remove obsolete variable in trace_array structure
      
      With the new start / stop method of ftrace, the ctrl variable
      in the trace_array structure is now obsolete. Remove it.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      c76f0694
    • S
      ftrace: remove ctrl_update method · bbf5b1a0
      Steven Rostedt 提交于
      Impact: Remove the ctrl_update tracer method
      
      With the new quick start/stop method of tracing, the ctrl_update
      method is out of date.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      bbf5b1a0
    • S
      ftrace: fix sched_switch API · e168e051
      Steven Rostedt 提交于
      Impact: fix for sched_switch that broke dynamic ftrace startup
      
      The commit: tracing/fastboot: use sched switch tracer from boot tracer
      broke the API of the sched_switch trace. The use of the
      tracing_start/stop_cmdline record is for only recording the cmdline,
      NOT recording the schedule switches themselves.
      
      Seeing that the boot tracer broke the API to do something that it
      wanted, this patch adds a new interface for the API while
      puting back the original interface of the old API.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Acked-by: NFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      e168e051
    • S
      ftrace: fix boot trace sched startup · 75f5c47d
      Steven Rostedt 提交于
      Impact: boot tracer startup modified
      
      The boot tracer calls into some of the schedule tracing private functions
      that should not be exported. This patch cleans it up, and makes
      way for further changes in the ftrace infrastructure.
      
      This patch adds a api to assign a tracer array to the schedule
      context switch tracer.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Acked-by: NFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      75f5c47d
  5. 06 11月, 2008 1 次提交
    • S
      ftrace: restructure tracing start/stop infrastructure · 9036990d
      Steven Rostedt 提交于
      Impact: change where tracing is started up and stopped
      
      Currently, when a new tracer is selected via echo'ing a tracer name into
      the current_tracer file, the startup is only done if tracing_enabled is
      set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
      the tracing_enabled file) a full shutdown is performed.
      
      The full startup and shutdown of a tracer can be expensive and the
      user can lose out traces when echo'ing in 0 to the tracing_enabled file,
      because the process takes too long. There can also be places that
      the user would like to start and stop the tracer several times and
      doing the full startup and shutdown of a tracer might be too expensive.
      
      This patch performs the full startup and shutdown when a tracer is
      selected. It also adds a way to do a quick start or stop of a tracer.
      The quick version is just a flag that prevents the tracing from
      taking place, but the overhead of the code is still there.
      
      For example, the startup of a tracer may enable tracepoints, or enable
      the function tracer.  The stop and start will just set a flag to
      have the tracer ignore the calls when the tracepoint or function trace
      is called.  The overhead of the tracer may still be present when
      the tracer is stopped, but no tracing will occur. Setting the tracer
      to the 'nop' tracer (or any other tracer) will perform the shutdown
      of the tracer which will disable the tracepoint or disable the
      function tracer.
      
      The tracing_enabled file will simply start or stop tracing.
      
      This change is all internal. The end result for the user should be the same
      as before. If tracing_enabled is not set, no trace will happen.
      If tracing_enabled is set, then the trace will happen. The tracing_enabled
      variable is static between tracers. Enabling  tracing_enabled and
      going to another tracer will keep tracing_enabled enabled. Same
      is true with disabling tracing_enabled.
      
      This patch will now provide a fast start/stop method to the users
      for enabling or disabling tracing.
      
      Note: There were two methods to the struct tracer that were never
       used: The methods start and stop. These were to be used as a hook
       to the reading of the trace output, but ended up not being
       necessary. These two methods are now used to enable the start
       and stop of each tracer, in case the tracer needs to do more than
       just not write into the buffer. For example, the irqsoff tracer
       must stop recording max latencies when tracing is stopped.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      9036990d
  6. 05 11月, 2008 1 次提交
  7. 04 11月, 2008 2 次提交
    • S
      ftrace: function tracer with irqs disabled · b2a866f9
      Steven Rostedt 提交于
      Impact: disable interrupts during trace entry creation (as opposed to preempt)
      
      To help with performance, I set the ftracer to not disable interrupts,
      and only to disable preemption. If an interrupt occurred, it would not
      be traced, because the function tracer protects itself from recursion.
      This may be faster, but the trace output might miss some traces.
      
      This patch makes the fuction trace disable interrupts, but it also
      adds a runtime feature to disable preemption instead. It does this by
      having two different tracer functions. When the function tracer is
      enabled, it will check to see which version is requested (irqs disabled
      or preemption disabled). Then it will use the corresponding function
      as the tracer.
      
      Irq disabling is the default behaviour, but if the user wants better
      performance, with the chance of missing traces, then they can choose
      the preempt disabled version.
      
      Running hackbench 3 times with the irqs disabled and 3 times with
      the preempt disabled function tracer yielded:
      
      tracing type       times            entries recorded
      ------------      --------          ----------------
      irq disabled      43.393            166433066
                        43.282            166172618
                        43.298            166256704
      
      preempt disabled  38.969            159871710
                        38.943            159972935
                        39.325            161056510
      
      Average:
      
         irqs disabled:  43.324           166287462
      preempt disabled:  39.079           160300385
      
       preempt is 10.8 percent faster than irqs disabled.
      
      I wrote a patch to count function trace recursion and reran hackbench.
      
      With irq disabled: 1,150 times the function tracer did not trace due to
        recursion.
      with preempt disabled: 5,117,718 times.
      
      The thousand times with irq disabled could be due to NMIs, or simply a case
      where it called a function that was not protected by notrace.
      
      But we also see that a large amount of the trace is lost with the
      preempt version.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Cc: Andrew Morton <akpm@linux-foundation.org>
      Cc: Steven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      b2a866f9
    • S
      ftrace: introduce ftrace_preempt_disable()/enable() · 8f0a056f
      Steven Rostedt 提交于
      Impact: add new ftrace-plugin internal APIs
      
      Parts of the tracer needs to be careful about schedule recursion.
      If the NEED_RESCHED flag is set, a preempt_enable will call schedule.
      Inside the schedule function, the NEED_RESCHED flag is cleared.
      
      The problem arises when a trace happens in the schedule function but before
      NEED_RESCHED is cleared. The race is as follows:
      
      schedule()
        >> tracer called
      
          trace_function()
             preempt_disable()
             [ record trace ]
             preempt_enable()  <<- here's the issue.
      
               [check NEED_RESCHED]
                schedule()
                [ Repeat the above, over and over again ]
      
      The naive approach is simply to use preempt_enable_no_schedule instead.
      The problem with that approach is that, although we solve the schedule
      recursion issue, we now might lose a preemption check when not in the
      schedule function.
      
        trace_function()
          preempt_disable()
          [ record trace ]
          [Interrupt comes in and sets NEED_RESCHED]
          preempt_enable_no_resched()
          [continue without scheduling]
      
      The way ftrace handles this problem is with the following approach:
      
      	int resched;
      
      	resched = need_resched();
      	preempt_disable_notrace();
      	[record trace]
      	if (resched)
      		preempt_enable_no_sched_notrace();
      	else
      		preempt_enable_notrace();
      
      This may seem like the opposite of what we want. If resched is set
      then we call the "no_sched" version??  The reason we do this is because
      if NEED_RESCHED is set before we disable preemption, there's two reasons
      for that:
      
        1) we are in an atomic code path
        2) we are already on our way to the schedule function, and maybe even
           in the schedule function, but have yet to clear the flag.
      
      Both the above cases we do not want to schedule.
      
      This solution has already been implemented within the ftrace infrastructure.
      But the problem is that it has been implemented several times. This patch
      encapsulates this code to two nice functions.
      
        resched = ftrace_preempt_disable();
        [ record trace]
        ftrace_preempt_enable(resched);
      
      This way the tracers do not need to worry about getting it right.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      8f0a056f
  8. 31 10月, 2008 1 次提交
    • S
      ftrace: handle archs that do not support irqs_disabled_flags · 9244489a
      Steven Rostedt 提交于
      Impact: build fix on non-lockdep architectures
      
      Some architectures do not support a way to read the irq flags that
      is set from "local_irq_save(flags)" to determine if interrupts were
      disabled or enabled. Ftrace uses this information to display to the user
      if the trace occurred with interrupts enabled or disabled.
      
      Besides the fact that those archs that do not support this will fail to
      compile, unless they fix it, we do not want to have the trace simply
      say interrupts were not disabled or they were enabled, without knowing
      the real answer.
      
      This patch adds a 'X' in the output to let the user know that the
      architecture they are running on does not support a way for the tracer
      to determine if interrupts were enabled or disabled. It also lets those
      same archs compile with tracing enabled.
      Signed-off-by: NSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      9244489a
  9. 21 10月, 2008 1 次提交
  10. 14 10月, 2008 17 次提交
  11. 11 7月, 2008 1 次提交
  12. 27 5月, 2008 1 次提交
  13. 24 5月, 2008 4 次提交
    • P
      ftrace: mmiotrace, updates · bd8ac686
      Pekka Paalanen 提交于
      here is a patch that makes mmiotrace work almost well within the tracing
      framework. The patch applies on top of my previous patch. I have my own
      output formatting in place now.
      
      Summary of changes:
      - fix the NULL dereference that was due to not calling tracing_reset()
      - add print_line() callback into struct tracer
      - implement print_line() for mmiotrace, producing up-to-spec text
      - add my output header, but that is not really called in the right place
      - rewrote the main structs in mmiotrace
      - added two new trace entry types: TRACE_MMIO_RW and TRACE_MMIO_MAP
      - made some functions in trace.c non-static
      - check current==NULL in tracing_generic_entry_update()
      - fix(?) comparison in trace_seq_printf()
      
      Things seem to work fine except a few issues. Markers (text lines injected
      into mmiotrace log) are missing, I did not feel hacking them in before we
      have variable length entries. My output header is printed only for 'trace'
      file, but not 'trace_pipe'. For some reason, despite my quick fix,
      iter->trace is NULL in print_trace_line() when called from 'trace_pipe'
      file, which means I don't get proper output formatting.
      
      I only tried by loading nouveau.ko, which just detects the card, and that
      is traced fine. I didn't try further. Map, two reads and unmap. Works
      perfectly.
      
      I am missing the information about overflows, I'd prefer to have a
      counter for lost events. I didn't try, but I guess currently there is no
      way of knowning when it overflows?
      
      So, not too far from being fully operational, it seems :-)
      And looking at the diffstat, there also is some 700-900 lines of user space
      code that just became obsolete.
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      Signed-off-by: NThomas Gleixner <tglx@linutronix.de>
      bd8ac686
    • I
      ftrace: sysprof updates · d618b3e6
      Ingo Molnar 提交于
      make the sample period configurable.
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      Signed-off-by: NThomas Gleixner <tglx@linutronix.de>
      d618b3e6
    • I
      ftrace: sysprof-plugin, add self-tests · a6dd24f8
      Ingo Molnar 提交于
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      Signed-off-by: NThomas Gleixner <tglx@linutronix.de>
      a6dd24f8
    • I
      ftrace: stacktrace fix · 74f4e369
      Ingo Molnar 提交于
      Signed-off-by: NIngo Molnar <mingo@elte.hu>
      Signed-off-by: NThomas Gleixner <tglx@linutronix.de>
      74f4e369