An error occurred fetching the project authors.
  1. 13 Nov, 2008 1 commit
    • Steven Rostedt's avatar
      ftrace: CPU buffer start annotation clean ups · 12ef7d44
      Steven Rostedt authored
      Impact: better handling of CPU buffer start annotation
      
      Because of the confusion with the per CPU buffers wrapping where
      one CPU might be more active at the end of the trace than the other
      CPUs causing that one CPU to have a shorter history. Kernel
      developers were confused by the "missing" data of that one CPU
      at the beginning of the trace output. An annotation was added to
      the trace output to show that the buffer had started:
      
       # tracer: function
       #
       #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
       #              | |       |          |         |
       ##### CPU 3 buffer started ####
                <idle>-0     [003]   158.192959: smp_apic_timer_interrupt
       [...]
                 <idle>-0     [003]   161.556520: default_idle
       ##### CPU 1 buffer started ####
                 <idle>-0     [001]   161.592494: hrtimer_force_reprogram
       [etc]
      
      But this annotation gets a bit messy when tracers do not fill the
      buffers. This patch does a couple of things:
      
       One) it adds a flag to trace_options to disable these annotations
      
       Two) it does not annotate if the tracer did not overflow its buffer.
      
      This makes the output much cleaner.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      12ef7d44
  2. 12 Nov, 2008 6 commits
    • Steven Rostedt's avatar
      ftrace: add tracer called branch · 80e5ea45
      Steven Rostedt authored
      Impact: added new branch tracer
      
      Currently the tracing of branch profiling (unlikelys and likelys hit)
      is only activated by the iter_ctrl. This patch adds a tracer called
      "branch" that will just trace the branch profiling. The advantage
      of adding this tracer is that it can be added to the ftrace selftests
      on startup.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      80e5ea45
    • Steven Rostedt's avatar
      ftrace: rename unlikely iter_ctrl to branch · 9f029e83
      Steven Rostedt authored
      Impact: rename of iter_ctrl unlikely to branch
      
      The unlikely name is ugly. This patch converts the iter_ctrl command
      "unlikely" and "nounlikely" to "branch" and "nobranch" respectively.
      
      It also renames a lot of internal functions to use "branch" instead
      of "unlikely".
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      9f029e83
    • Steven Rostedt's avatar
      trace: rename unlikely profiler to branch profiler · 2ed84eeb
      Steven Rostedt authored
      Impact: name change of unlikely tracer and profiler
      
      Ingo Molnar suggested changing the config from UNLIKELY_PROFILE
      to BRANCH_PROFILING. I never did like the "unlikely" name so I
      went one step farther, and renamed all the unlikely configurations
      to a "BRANCH" variant.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      2ed84eeb
    • Steven Rostedt's avatar
      tracing: likely/unlikely branch annotation tracer · 52f232cb
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      52f232cb
    • 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
    • Frederic Weisbecker's avatar
      tracing/fastboot: move boot tracer structs and funcs into their own header. · 3f5ec136
      Frederic Weisbecker authored
      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: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      3f5ec136
  3. 11 Nov, 2008 1 commit
    • Frederic Weisbecker's avatar
      tracing: add a tracer to catch execution time of kernel functions · 15e6cb36
      Frederic Weisbecker authored
      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: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Cc: Steven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      15e6cb36
  4. 08 Nov, 2008 5 commits
    • Steven Rostedt's avatar
      ftrace: display start of CPU buffer in trace output · a309720c
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      a309720c
    • Steven Rostedt's avatar
      ftrace: remove trace array ctrl · c76f0694
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      c76f0694
    • Steven Rostedt's avatar
      ftrace: remove ctrl_update method · bbf5b1a0
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      bbf5b1a0
    • Steven Rostedt's avatar
      ftrace: fix sched_switch API · e168e051
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Acked-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      e168e051
    • Steven Rostedt's avatar
      ftrace: fix boot trace sched startup · 75f5c47d
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Acked-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      75f5c47d
  5. 06 Nov, 2008 1 commit
    • Steven Rostedt's avatar
      ftrace: restructure tracing start/stop infrastructure · 9036990d
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      9036990d
  6. 04 Nov, 2008 3 commits
    • Frederic Weisbecker's avatar
      tracing/fastboot: use sched switch tracer from boot tracer · d7ad44b6
      Frederic Weisbecker authored
      Impact: enhance boot trace output with scheduling events
      
      Use the sched_switch tracer from the boot tracer.
      
      We also can trace schedule events inside the initcalls.
      Sched tracing is disabled after the initcall has finished and
      then reenabled before the next one is started.
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      d7ad44b6
    • Steven Rostedt's avatar
      ftrace: function tracer with irqs disabled · b2a866f9
      Steven Rostedt authored
      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: default avatarSteven 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: default avatarIngo Molnar <mingo@elte.hu>
      b2a866f9
    • Steven Rostedt's avatar
      ftrace: introduce ftrace_preempt_disable()/enable() · 8f0a056f
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      8f0a056f
  7. 30 Oct, 2008 1 commit
    • Steven Rostedt's avatar
      ftrace: handle archs that do not support irqs_disabled_flags · 9244489a
      Steven Rostedt authored
      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: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      9244489a
  8. 20 Oct, 2008 1 commit
  9. 14 Oct, 2008 17 commits
    • Steven Rostedt's avatar
      ftrace: preempt disable over interrupt disable · 38697053
      Steven Rostedt authored
      With the new ring buffer infrastructure in ftrace, I'm trying to make
      ftrace a little more light weight.
      
      This patch converts a lot of the local_irq_save/restore into
      preempt_disable/enable.  The original preempt count in a lot of cases
      has to be sent in as a parameter so that it can be recorded correctly.
      Some places were recording it incorrectly before anyway.
      
      This is also laying the ground work to make ftrace a little bit
      more reentrant, and remove all locking. The function tracers must
      still protect from reentrancy.
      
      Note: All the function tracers must be careful when using preempt_disable.
        It must do the following:
      
        resched = need_resched();
        preempt_disable_notrace();
        [...]
        if (resched)
      	preempt_enable_no_resched_notrace();
        else
      	preempt_enable_notrace();
      
      The reason is that if this function traces schedule() itself, the
      preempt_enable_notrace() will cause a schedule, which will lead
      us into a recursive failure.
      
      If we needed to reschedule before calling preempt_disable, we
      should have already scheduled. Since we did not, this is most
      likely that we should not and are probably inside a schedule
      function.
      
      If resched was not set, we still need to catch the need resched
      flag being set when preemption was off and the if case at the
      end will catch that for us.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      38697053
    • Steven Rostedt's avatar
      ftrace: type cast filter+verifier · 7104f300
      Steven Rostedt authored
      The mmiotrace map had a bug that would typecast the entry from
      the trace to the wrong type. That is a known danger of C typecasts,
      there's absolutely zero checking done on them.
      
      Help that problem a bit by using a GCC extension to implement a
      type filter that restricts the types that a trace record can be
      cast into, and by adding a dynamic check (in debug mode) to verify
      the type of the entry.
      
      This patch adds a macro to assign all entries of ftrace using the type
      of the variable and checking the entry id. The typecasts are now done
      in the macro for only those types that it knows about, which should
      be all the types that are allowed to be read from the tracer.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      7104f300
    • Frederic Weisbecker's avatar
      tracing/ftrace: change the type of the print_line callback · 2c4f035f
      Frederic Weisbecker authored
      We need a kind of disambiguation when a print_line callback
      returns 0.
      
      _There is not enough space to print all the entry.
       Please flush the seq and retry.
      _I can't handle this type of entry
      
      This patch changes the type of this callback for better information.
      
      Also some changes have been made in this V2.
      
      _ Only relay to default functions after the print_line callback fails.
      _ This patch doesn't fix the issue with the broken pipe (see patch 2/4 for that)
      
      Some things are still in discussion:
      
      _ Find better names for the enum print_line_t values
      _ Change the type of print_trace_line into boolean.
      
      Patches to change that can be sent later.
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Acked-by: default avatarPekka Paalanen <pq@iki.fi>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      2c4f035f
    • Steven Rostedt's avatar
      ftrace: take advantage of variable length entries · 777e208d
      Steven Rostedt authored
      Now that the underlining ring buffer for ftrace now hold variable length
      entries, we can take advantage of this by only storing the size of the
      actual event into the buffer. This happens to increase the number of
      entries in the buffer dramatically.
      
      We can also get rid of the "trace_cont" operation, but I'm keeping that
      until we have no more users. Some of the ftrace tracers can now change
      their code to adapt to this new feature.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      777e208d
    • Steven Rostedt's avatar
      ftrace: make work with new ring buffer · 3928a8a2
      Steven Rostedt authored
      This patch ports ftrace over to the new ring buffer.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      3928a8a2
    • Frédéric Weisbecker's avatar
      tracing/ftrace: add the boot tracer · d13744cd
      Frédéric Weisbecker authored
      Add the boot/initcall tracer.
      
      It's primary purpose is to be able to trace the initcalls.
      
      It is intended to be used with scripts/bootgraph.pl after some small
      improvements.
      
      Note that it is not active after its init. To avoid tracing (and so
      crashing) before the whole tracing engine init, you have to explicitly
      call start_boot_trace() after do_pre_smp_initcalls() to enable it.
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      d13744cd
    • Frédéric Weisbecker's avatar
      tracing/ftrace: replace none tracer by nop tracer · 43a15386
      Frédéric Weisbecker authored
      Replace "none" tracer by the recently created "nop" tracer.
      Both are pretty similar except that nop accepts TRACE_PRINT
      or TRACE_SPECIAL entries.
      
      And as a consequence, changing the size of the ring buffer now
      requires that tracing has already been disabled.
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Cc: Steven Rostedt <rostedt@goodmis.org>
      Cc: Steven Noonan <steven@uplinklabs.net>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      43a15386
    • Steven Noonan's avatar
      trace: remove pointless ifdefs · 8925b394
      Steven Noonan authored
      The functions are already 'extern' anyway, so there's no problem
      with linkage. Removing these ifdefs also helps find any potential
      compiler errors.
      
      Suggested by Andrew Morton.
      Signed-off-by: default avatarSteven Noonan <steven@uplinklabs.net>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      8925b394
    • Steven Noonan's avatar
      ftrace: add nop tracer · fb1b6d8b
      Steven Noonan authored
      A no-op tracer which can serve two purposes:
      
       1. A template for development of a new tracer.
       2. A convenient way to see ftrace_printk() calls without
          an irrelevant trace making the output messy.
      
      [ mingo@elte.hu: resolved conflicts ]
      Signed-off-by: default avatarSteven Noonan <steven@uplinklabs.net>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      fb1b6d8b
    • Pekka Paalanen's avatar
      ftrace: inject markers via trace_marker file · 5bf9a1ee
      Pekka Paalanen authored
      Allow a user to inject a marker (TRACE_PRINT entry) into the trace ring
      buffer. The related file operations are derived from code by Frédéric
      Weisbecker <fweisbec@gmail.com>.
      Signed-off-by: default avatarPekka Paalanen <pq@iki.fi>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      5bf9a1ee
    • Pekka Paalanen's avatar
      mmiotrace: handle TRACE_PRINT entries · fc5e27ae
      Pekka Paalanen authored
      Also make trace_seq_print_cont() non-static, and add a newline if the
      seq buffer can't hold all data.
      Signed-off-by: default avatarPekka Paalanen <pq@iki.fi>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      fc5e27ae
    • Pekka Paalanen's avatar
      ftrace: add trace_vprintk() · 801fe400
      Pekka Paalanen authored
      trace_vprintk() for easier implementation of tracer specific *_printk
      functions. Add check check for no_tracer, and implement
      __ftrace_printk() as a wrapper.
      Signed-off-by: default avatarPekka Paalanen <pq@iki.fi>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      801fe400
    • Pekka Paalanen's avatar
      ftrace: move mmiotrace functions out of trace.c · 45dcd8b8
      Pekka Paalanen authored
      Moves the mmiotrace specific functions from trace.c to
      trace_mmiotrace.c. Functions trace_wake_up(), tracing_get_trace_entry(),
      and tracing_generic_entry_update() are therefore made available outside
      trace.c.
      Signed-off-by: default avatarPekka Paalanen <pq@iki.fi>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      45dcd8b8
    • Peter Zijlstra's avatar
      ftrace: sched_switch: show the wakee's cpu · 80b5e940
      Peter Zijlstra authored
      While profiling the smp behaviour of the scheduler it was needed to know to
      which cpu a task got woken.
      Signed-off-by: default avatarPeter Zijlstra <a.p.zijlstra@chello.nl>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      80b5e940
    • Peter Zijlstra's avatar
      ftrace: make ftrace_printk usable with the other tracers · f09ce573
      Peter Zijlstra authored
      Currently ftrace_printk only works with the ftrace tracer, switch it to an
      iter_ctrl setting so we can make us of them with other tracers too.
      
      [rostedt@redhat.com: tweak to the disable condition]
      Signed-off-by: default avatarPeter Zijlstra <a.p.zijlstra@chello.nl>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      f09ce573
    • Steven Rostedt's avatar
      ftrace: printk formatting infrastructure · dd0e545f
      Steven Rostedt authored
      This patch adds a feature that can help kernel developers debug their
      code using ftrace.
      
        int ftrace_printk(const char *fmt, ...);
      
      This records into the ftrace buffer using printf formatting. The entry
      size in the buffers are still a fixed length. A new type has been added
      that allows for more entries to be used for a single recording.
      
      The start of the print is still the same as the other entries.
      
      It returns the number of characters written to the ftrace buffer.
      
      For example:
      
      Having a module with the following code:
      
      static int __init ftrace_print_test(void)
      {
              ftrace_printk("jiffies are %ld\n", jiffies);
              return 0;
      }
      
      Gives me:
      
        insmod-5441  3...1 7569us : ftrace_print_test: jiffies are 4296626666
      
      for the latency_trace file and:
      
                insmod-5441  [03]  1959.370498: ftrace_print_test jiffies are 4296626666
      
      for the trace file.
      
      Note: Only the infrastructure should go into the kernel. It is to help
      facilitate debugging for other kernel developers. Calls to ftrace_printk
      is not intended to be left in the kernel, and should be frowned upon just
      like scattering printks around in the code.
      
      But having this easily at your fingertips helps the debugging go faster
      and bugs be solved quicker.
      
      Maybe later on, we can hook this with markers and have their printf format
      be sucked into ftrace output.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      dd0e545f
    • Steven Rostedt's avatar
      ftrace: new continue entry - separate out from trace_entry · 2e2ca155
      Steven Rostedt authored
      Some tracers will need to work with more than one entry. In order to do this
      the trace_entry structure was split into two fields. One for the start of
      all entries, and one to continue an existing entry.
      
      The trace_entry structure now has a "field" entry that consists of the previous
      content of the trace_entry, and a "cont" entry that is just a string buffer
      the size of the "field" entry.
      
      Thanks to Andrew Morton for suggesting this idea.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      2e2ca155
  10. 11 Jul, 2008 1 commit
  11. 26 May, 2008 1 commit
  12. 24 May, 2008 1 commit
    • Pekka Paalanen's avatar
      ftrace: mmiotrace, updates · bd8ac686
      Pekka Paalanen authored
      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: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      bd8ac686
  13. 23 May, 2008 1 commit