1. 25 Jun, 2009 1 commit
    • Li Zefan's avatar
      ftrace: Remove duplicate newline · 00e54d08
      Li Zefan authored
      
      
      Before:
        # echo 'sys_open:traceon:' > set_ftrace_filter
        # echo 'sys_close:traceoff:5' > set_ftrace_filter
        # cat set_ftrace_filter
        #### all functions enabled ####
        sys_open:traceon:unlimited
      
        sys_close:traceoff:count=0
      
      After:
        # cat set_ftrace_filter
        #### all functions enabled ####
        sys_open:traceon:unlimited
        sys_close:traceoff:count=0
      Signed-off-by: default avatarLi Zefan <lizf@cn.fujitsu.com>
      Cc: Steven Rostedt <rostedt@goodmis.org>
      Cc: Frederic Weisbecker <fweisbec@gmail.com>
      LKML-Reference: <4A4313A7.7030105@cn.fujitsu.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      00e54d08
  2. 20 Jun, 2009 1 commit
    • Frederic Weisbecker's avatar
      tracing/urgent: fix unbalanced ftrace_start_up · c85a17e2
      Frederic Weisbecker authored
      
      
      Perfcounter reports the following stats for a wide system
      profiling:
      
       #
       # (2364 samples)
       #
       # Overhead  Symbol
       # ........  ......
       #
          15.40%  [k] mwait_idle_with_hints
           8.29%  [k] read_hpet
           5.75%  [k] ftrace_caller
           3.60%  [k] ftrace_call
           [...]
      
      This snapshot has been taken while neither the function tracer nor
      the function graph tracer was running.
      With dynamic ftrace, such results show a wrong ftrace behaviour
      because all calls to ftrace_caller or ftrace_graph_caller (the patched
      calls to mcount) are supposed to be patched into nop if none of those
      tracers are running.
      
      The problem occurs after the first run of the function tracer. Once we
      launch it a second time, the callsites will never be nopped back,
      unless you set custom filters.
      For example it happens during the self tests at boot time.
      The function tracer selftest runs, and then the dynamic tracing is
      tested too. After that, the callsites are left un-nopped.
      
      This is because the reset callback of the function tracer tries to
      unregister two ftrace callbacks in once: the common function tracer
      and the function tracer with stack backtrace, regardless of which
      one is currently in use.
      It then creates an unbalance on ftrace_start_up value which is expected
      to be zero when the last ftrace callback is unregistered. When it
      reaches zero, the FTRACE_DISABLE_CALLS is set on the next ftrace
      command, triggering the patching into nop. But since it becomes
      unbalanced, ie becomes lower than zero, if the kernel functions
      are patched again (as in every further function tracer runs), they
      won't ever be nopped back.
      
      Note that ftrace_call and ftrace_graph_call are still patched back
      to ftrace_stub in the off case, but not the callers of ftrace_call
      and ftrace_graph_caller. It means that the tracing is well deactivated
      but we waste a useless call into every kernel function.
      
      This patch just unregisters the right ftrace_ops for the function
      tracer on its reset callback and ignores the other one which is
      not registered, fixing the unbalance. The problem also happens
      is .30
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Cc: Steven Rostedt <rostedt@goodmis.org>
      Cc: stable@kernel.org
      c85a17e2
  3. 18 Feb, 2009 1 commit
    • Frederic Weisbecker's avatar
      tracing/core: use appropriate waiting on trace_pipe · 6eaaa5d5
      Frederic Weisbecker authored
      
      
      Impact: api and pipe waiting change
      
      Currently, the waiting used in tracing_read_pipe() is done through a
      100 msecs schedule_timeout() loop which periodically check if there
      are traces on the buffer.
      
      This can cause small latencies for programs which are reading the incoming
      events.
      
      This patch makes the reader waiting for the trace_wait waitqueue except
      for few tracers such as the sched and functions tracers which might be
      already hold the runqueue lock while waking up the reader.
      
      This is performed through a new callback wait_pipe() on struct tracer.
      If none is implemented on a specific tracer, the default waiting for
      trace_wait queue is attached.
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      6eaaa5d5
  4. 17 Feb, 2009 5 commits
  5. 06 Feb, 2009 1 commit
  6. 05 Feb, 2009 1 commit
  7. 16 Jan, 2009 4 commits
    • Steven Rostedt's avatar
      ftrace: remove static from function tracer functions · a225cdd2
      Steven Rostedt authored
      
      
      Impact: clean up
      
      After reorganizing the functions in trace.c and trace_function.c,
      they no longer need to be in global context. This patch makes the
      functions and one variable into static.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      a225cdd2
    • Steven Rostedt's avatar
      ftrace: combine stack trace in function call · 3eb36aa0
      Steven Rostedt authored
      
      
      Impact: less likely to interleave function and stack traces
      
      This patch does replaces the separate stack trace on function with
      a record function and stack trace together. This will switch between
      the function only recording to a function and stack recording.
      
      Also some whitespace fix ups as well.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      3eb36aa0
    • Steven Rostedt's avatar
      ftrace: move function tracer functions out of trace.c · bb3c3c95
      Steven Rostedt authored
      
      
      Impact: clean up of trace.c
      
      The function tracer functions were put in trace.c because it needed
      to share static variables that were in trace.c.  Since then, those
      variables have become global for various reasons. This patch moves
      the function tracer functions into trace_function.c where they belong.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      bb3c3c95
    • Steven Rostedt's avatar
      ftrace: add stack trace to function tracer · 53614991
      Steven Rostedt authored
      
      
      Impact: new feature to stack trace any function
      
      Chris Mason asked about being able to pick and choose a function
      and get a stack trace from it. This feature enables his request.
      
       # echo io_schedule > /debug/tracing/set_ftrace_filter
       # echo function > /debug/tracing/current_tracer
       # echo func_stack_trace > /debug/tracing/trace_options
      
      Produces the following in /debug/tracing/trace:
      
             kjournald-702   [001]   135.673060: io_schedule <-sync_buffer
             kjournald-702   [002]   135.673671:
       <= sync_buffer
       <= __wait_on_bit
       <= out_of_line_wait_on_bit
       <= __wait_on_buffer
       <= sync_dirty_buffer
       <= journal_commit_transaction
       <= kjournald
      
      Note, be careful about turning this on without filtering the functions.
      You may find that you have a 10 second lag between typing and seeing
      what you typed. This is why the stack trace for the function tracer
      does not use the same stack_trace flag as the other tracers use.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      53614991
  8. 19 Dec, 2008 1 commit
  9. 16 Nov, 2008 1 commit
  10. 08 Nov, 2008 2 commits
  11. 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
  12. 20 Oct, 2008 1 commit
  13. 14 Oct, 2008 1 commit
  14. 11 Jul, 2008 1 commit
  15. 26 May, 2008 1 commit
  16. 23 May, 2008 6 commits
    • Steven Rostedt's avatar
      ftrace: fix comm on function trace output · 25b0b44a
      Steven Rostedt authored
      
      
      In cleaning up of the sched_switch code, the function trace recording
      of task comms was removed. This patch adds back the recording of comms
      for function trace. The output of ftrace now has the task comm instead
      of <...>.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      25b0b44a
    • Ingo Molnar's avatar
      ftrace: remove notrace · e309b41d
      Ingo Molnar authored
      
      
      now that we have a kbuild method for notrace, no need to pollute the
      C code with the annotations.
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      e309b41d
    • Ingo Molnar's avatar
      ftrace: build fix · 2e0f5761
      Ingo Molnar authored
      
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      2e0f5761
    • Ingo Molnar's avatar
      ftrace: timestamp syncing, prepare · 750ed1a4
      Ingo Molnar authored
      
      
      rename and uninline now() to ftrace_now().
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      750ed1a4
    • Steven Rostedt's avatar
      ftrace: add self-tests · 60a11774
      Steven Rostedt authored
      
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      60a11774
    • Steven Rostedt's avatar
      ftrace: function tracer · 1b29b018
      Steven Rostedt authored
      
      
      This is a simple trace that uses the ftrace infrastructure. It is
      designed to be fast and small, and easy to use. It is useful to
      record things that happen over a very short period of time, and
      not to analyze the system in general.
      
       Updates:
      
        available_tracers
           "function" is added to this file.
      
        current_tracer
          To enable the function tracer:
      
            echo function > /debugfs/tracing/current_tracer
      
           To disable the tracer:
      
             echo disable > /debugfs/tracing/current_tracer
      
      The output of the function_trace file is as follows
      
        "echo noverbose > /debugfs/tracing/iter_ctrl"
      
      preemption latency trace v1.1.5 on 2.6.24-rc7-tst
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      --------------------------------------------------------------------
       latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
          -----------------
          | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
          -----------------
      
                       _------=> CPU#
                      / _-----=> irqs-off
                     | / _----=> need-resched
                     || / _---=> hardirq/softirq
                     ||| / _--=> preempt-depth
                     |||| /
                     |||||     delay
         cmd     pid ||||| time  |   caller
            \   /    |||||   \   |   /
       swapper-0     0d.h. 1595128us+: set_normalized_timespec+0x8/0x2d <c043841d> (ktime_get_ts+0x4a/0x4e <c04499d4>)
       swapper-0     0d.h. 1595131us+: _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
      
      Or with verbose turned on:
      
        "echo verbose > /debugfs/tracing/iter_ctrl"
      
      preemption latency trace v1.1.5 on 2.6.24-rc7-tst
      --------------------------------------------------------------------
       latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
          -----------------
          | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
          -----------------
      
               swapper     0 0 9 00000000 00000000 [f3675f41] 1595.128ms (+0.003ms): set_normalized_timespec+0x8/0x2d <c043841d> (ktime_get_ts+0x4a/0x4e <c04499d4>)
               swapper     0 0 9 00000000 00000001 [f3675f45] 1595.131ms (+0.003ms): _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
               swapper     0 0 9 00000000 00000002 [f3675f48] 1595.135ms (+0.003ms): _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
      
      The "trace" file is not affected by the verbose mode, but is by the symonly.
      
       echo "nosymonly" > /debugfs/tracing/iter_ctrl
      
      tracer:
      [   81.479967] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66 <ffffffff80337a4d> <-- _spin_unlock_irqrestore+0xe/0x5a <ffffffff8048cc8f>
      [   81.479967] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a <ffffffff8048ccbf> <-- sub_preempt_count+0xc/0x7a <ffffffff80233d7b>
      [   81.479968] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a <ffffffff80233d9f> <-- in_lock_functions+0x9/0x24 <ffffffff8025a75d>
      [   81.479968] CPU 0: bash:3154 vfs_write+0x11d/0x155 <ffffffff8029a043> <-- dnotify_parent+0x12/0x78 <ffffffff802d54fb>
      [   81.479968] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 <ffffffff802d5516> <-- _spin_lock+0xe/0x70 <ffffffff8048c910>
      [   81.479969] CPU 0: bash:3154 _spin_lock+0x1b/0x70 <ffffffff8048c91d> <-- add_preempt_count+0xe/0x77 <ffffffff80233df7>
      [   81.479969] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 <ffffffff80233e27> <-- in_lock_functions+0x9/0x24 <ffffffff8025a75d>
      
       echo "symonly" > /debugfs/tracing/iter_ctrl
      
      tracer:
      [   81.479913] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66 <-- _spin_unlock_irqrestore+0xe/0x5a
      [   81.479913] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a <-- sub_preempt_count+0xc/0x7a
      [   81.479913] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a <-- in_lock_functions+0x9/0x24
      [   81.479914] CPU 0: bash:3154 vfs_write+0x11d/0x155 <-- dnotify_parent+0x12/0x78
      [   81.479914] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 <-- _spin_lock+0xe/0x70
      [   81.479914] CPU 0: bash:3154 _spin_lock+0x1b/0x70 <-- add_preempt_count+0xe/0x77
      [   81.479914] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 <-- in_lock_functions+0x9/0x24
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      Signed-off-by: default avatarArnaldo Carvalho de Melo <acme@ghostprotocols.net>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
      1b29b018