1. 02 Nov, 2012 2 commits
  2. 31 Oct, 2012 5 commits
    • Steven Rostedt's avatar
      tracing: Cache comms only after an event occurred · 7ffbd48d
      Steven Rostedt authored
      
      
      Whenever an event is registered, the comm of tasks are saved at
      every task switch instead of saving them at every event. But if
      an event isn't executed much, the comm cache will be filled up
      by tasks that did not record the event and you lose out on the comms
      that did.
      
      Here's an example, if you enable the following events:
      
      echo 1 > /debug/tracing/events/kvm/kvm_cr/enable
      echo 1 > /debug/tracing/events/net/net_dev_xmit/enable
      
      Note, there's no kvm running on this machine so the first event will
      never be triggered, but because it is enabled, the storing of comms
      will continue. If we now disable the network event:
      
      echo 0 > /debug/tracing/events/net/net_dev_xmit/enable
      
      and look at the trace:
      
      cat /debug/tracing/trace
                  sshd-2672  [001] ..s2   375.731616: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s1   375.731617: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s2   375.859356: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s1   375.859357: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s2   375.947351: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s1   375.947352: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s2   376.035383: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s1   376.035383: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                  sshd-2672  [001] ..s2   377.563806: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=226 rc=0
                  sshd-2672  [001] ..s1   377.563807: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=226 rc=0
                  sshd-2672  [001] ..s2   377.563834: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6be0 len=114 rc=0
                  sshd-2672  [001] ..s1   377.563842: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6be0 len=114 rc=0
      
      We see that process 2672 which triggered the events has the comm "sshd".
      But if we run hackbench for a bit and look again:
      
      cat /debug/tracing/trace
                 <...>-2672  [001] ..s2   375.731616: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s1   375.731617: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s2   375.859356: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s1   375.859357: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s2   375.947351: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s1   375.947352: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s2   376.035383: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s1   376.035383: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
                 <...>-2672  [001] ..s2   377.563806: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=226 rc=0
                 <...>-2672  [001] ..s1   377.563807: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=226 rc=0
                 <...>-2672  [001] ..s2   377.563834: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6be0 len=114 rc=0
                 <...>-2672  [001] ..s1   377.563842: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6be0 len=114 rc=0
      
      The stored "sshd" comm has been flushed out and we get a useless "<...>".
      
      But by only storing comms after a trace event occurred, we can run
      hackbench all day and still get the same output.
      
      Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
      Cc: Thomas Gleixner <tglx@linutronix.de>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      7ffbd48d
    • Steven Rostedt's avatar
      tracing: Enable comm recording if trace_printk() is used · 81698831
      Steven Rostedt authored
      
      
      If comm recording is not enabled when trace_printk() is used then
      you just get this type of output:
      
      [ adding trace_printk("hello! %d", irq); in do_IRQ ]
      
                 <...>-2843  [001] d.h.    80.812300: do_IRQ: hello! 14
                 <...>-2734  [002] d.h2    80.824664: do_IRQ: hello! 14
                 <...>-2713  [003] d.h.    80.829971: do_IRQ: hello! 14
                 <...>-2814  [000] d.h.    80.833026: do_IRQ: hello! 14
      
      By enabling the comm recorder when trace_printk is enabled:
      
             hackbench-6715  [001] d.h.   193.233776: do_IRQ: hello! 21
                  sshd-2659  [001] d.h.   193.665862: do_IRQ: hello! 21
                <idle>-0     [001] d.h1   193.665996: do_IRQ: hello! 21
      Suggested-by: default avatarPeter Zijlstra <a.p.zijlstra@chello.nl>
      Cc: Thomas Gleixner <tglx@linutronix.de>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      81698831
    • Steven Rostedt's avatar
      tracing: Expand ring buffer when trace_printk() is used · b382ede6
      Steven Rostedt authored
      
      
      Since tracing is not used by 99% of Linux users, even though tracing
      may be configured in, it does not make sense to allocate 1.4 Megs
      per CPU for the ring buffers if they are not used. Thus, on boot up
      the ring buffers are set to a minimal size until something needs the
      and they are expanded.
      
      This works well for events and tracers (function, etc), but for the
      asynchronous use of trace_printk() which can write to the ring buffer
      at any time, does not expand the buffers.
      
      On boot up a check is made to see if any trace_printk() is used to
      see if the trace_printk() temp buffer pages should be allocated. This
      same code can be used to expand the buffers as well.
      Suggested-by: default avatarPeter Zijlstra <a.p.zijlstra@chello.nl>
      Cc: Thomas Gleixner <tglx@linutronix.de>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      b382ede6
    • Slava Pestov's avatar
      ring-buffer: Add a 'dropped events' counter · 884bfe89
      Slava Pestov authored
      The existing 'overrun' counter is incremented when the ring
      buffer wraps around, with overflow on (the default). We wanted
      a way to count requests lost from the buffer filling up with
      overflow off, too. I decided to add a new counter instead
      of retro-fitting the existing one because it seems like a
      different statistic to count conceptually, and also because
      of how the code was structured.
      
      Link: http://lkml.kernel.org/r/1310765038-26399-1-git-send-email-slavapestov@google.com
      
      Signed-off-by: default avatarSlava Pestov <slavapestov@google.com>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      884bfe89
    • Daniel Walter's avatar
      tracing: Replace strict_strto* with kstrto* · bcd83ea6
      Daniel Walter authored
       * remove old string conversions with kstrto*
      
      Link: http://lkml.kernel.org/r/20120926200838.GC1244@0x90.at
      
      Signed-off-by: default avatarDaniel Walter <sahne@0x90.at>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      bcd83ea6
  3. 28 Sep, 2012 1 commit
  4. 24 Sep, 2012 1 commit
  5. 18 Sep, 2012 1 commit
  6. 07 Aug, 2012 1 commit
  7. 17 Jul, 2012 1 commit
  8. 11 Jul, 2012 1 commit
  9. 28 Jun, 2012 2 commits
    • Steven Rostedt's avatar
      tracing: Remove NR_CPUS array from trace_iterator · 6d158a81
      Steven Rostedt authored
      
      
      Replace the NR_CPUS array of buffer_iter from the trace_iterator
      with an allocated array. This will just create an array of
      possible CPUS instead of the max number specified.
      
      The use of NR_CPUS in that array caused allocation failures for
      machines that were tight on memory. This did not cause any failures
      to the system itself (no crashes), but caused unnecessary failures
      for reading the trace files.
      
      Added a helper function called 'trace_buffer_iter()' that returns
      the buffer_iter item or NULL if it is not defined or the array was
      not allocated. Some routines do not require the array
      (tracing_open_pipe() for one).
      Reported-by: default avatarDave Jones <davej@redhat.com>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      6d158a81
    • Steven Rostedt's avatar
      tracing/selftest: Add a WARN_ON() if a tracer test fails · 0be61ebc
      Steven Rostedt authored
      
      
      Add a WARN_ON() output on test failures so that they are easier to detect
      in automated tests. Although, the WARN_ON() will not print if the test
      causes the system to crash, obviously.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      0be61ebc
  10. 13 Jun, 2012 1 commit
    • Eric Dumazet's avatar
      splice: fix racy pipe->buffers uses · 047fe360
      Eric Dumazet authored
      Dave Jones reported a kernel BUG at mm/slub.c:3474! triggered
      by splice_shrink_spd() called from vmsplice_to_pipe()
      
      commit 35f3d14d
      
       (pipe: add support for shrinking and growing pipes)
      added capability to adjust pipe->buffers.
      
      Problem is some paths don't hold pipe mutex and assume pipe->buffers
      doesn't change for their duration.
      
      Fix this by adding nr_pages_max field in struct splice_pipe_desc, and
      use it in place of pipe->buffers where appropriate.
      
      splice_shrink_spd() loses its struct pipe_inode_info argument.
      Reported-by: default avatarDave Jones <davej@redhat.com>
      Signed-off-by: default avatarEric Dumazet <edumazet@google.com>
      Cc: Jens Axboe <axboe@kernel.dk>
      Cc: Alexander Viro <viro@zeniv.linux.org.uk>
      Cc: Tom Herbert <therbert@google.com>
      Cc: stable <stable@vger.kernel.org> # 2.6.35
      Tested-by: default avatarDave Jones <davej@redhat.com>
      Signed-off-by: default avatarJens Axboe <axboe@kernel.dk>
      047fe360
  11. 07 Jun, 2012 1 commit
    • Steven Rostedt's avatar
      tracing: Have tracing_off() actually turn tracing off · f2bf1f6f
      Steven Rostedt authored
      
      
      A recent update to have tracing_on/off() only affect the ftrace ring
      buffers instead of all ring buffers had a cut and paste error.
      The tracing_off() did the exact same thing as tracing_on() and
      would not actually turn off tracing. Unfortunately, tracing_off()
      is more important to be working than tracing_on() as this is a key
      development tool, as it lets the developer turn off tracing as soon
      as a problem is discovered. It is also used by panic and oops code.
      
      This bug also breaks the 'echo func:traceoff > set_ftrace_filter'
      
      Cc: <stable@vger.kernel.org> # 3.4
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      f2bf1f6f
  12. 19 May, 2012 2 commits
  13. 16 May, 2012 4 commits
  14. 09 May, 2012 2 commits
  15. 24 Apr, 2012 3 commits
    • Vaibhav Nagarnaik's avatar
      ring-buffer: Add per_cpu ring buffer control files · 438ced17
      Vaibhav Nagarnaik authored
      Add a debugfs entry under per_cpu/ folder for each cpu called
      buffer_size_kb to control the ring buffer size for each CPU
      independently.
      
      If the global file buffer_size_kb is used to set size, the individual
      ring buffers will be adjusted to the given size. The buffer_size_kb will
      report the common size to maintain backward compatibility.
      
      If the buffer_size_kb file under the per_cpu/ directory is used to
      change buffer size for a specific CPU, only the size of the respective
      ring buffer is updated. When tracing/buffer_size_kb is read, it reports
      'X' to indicate that sizes of per_cpu ring buffers are not equivalent.
      
      Link: http://lkml.kernel.org/r/1328212844-11889-1-git-send-email-vnagarnaik@google.com
      
      
      
      Cc: Frederic Weisbecker <fweisbec@gmail.com>
      Cc: Michael Rubin <mrubin@google.com>
      Cc: David Sharp <dhsharp@google.com>
      Cc: Justin Teravest <teravest@google.com>
      Signed-off-by: default avatarVaibhav Nagarnaik <vnagarnaik@google.com>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      438ced17
    • Dan Carpenter's avatar
      tracing: Remove an unneeded check in trace_seq_buffer() · 5a26c8f0
      Dan Carpenter authored
      memcpy() returns a pointer to "bug".  Hopefully, it's not NULL here or
      we would already have Oopsed.
      
      Link: http://lkml.kernel.org/r/20120420063145.GA22649@elgon.mountain
      
      
      
      Cc: Frederic Weisbecker <fweisbec@gmail.com>
      Cc: Eduard - Gabriel Munteanu <eduard.munteanu@linux360.ro>
      Signed-off-by: default avatarDan Carpenter <dan.carpenter@oracle.com>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      5a26c8f0
    • Steven Rostedt's avatar
      tracing: Add percpu buffers for trace_printk() · 07d777fe
      Steven Rostedt authored
      
      
      Currently, trace_printk() uses a single buffer to write into
      to calculate the size and format needed to save the trace. To
      do this safely in an SMP environment, a spin_lock() is taken
      to only allow one writer at a time to the buffer. But this could
      also affect what is being traced, and add synchronization that
      would not be there otherwise.
      
      Ideally, using percpu buffers would be useful, but since trace_printk()
      is only used in development, having per cpu buffers for something
      never used is a waste of space. Thus, the use of the trace_bprintk()
      format section is changed to be used for static fmts as well as dynamic ones.
      Then at boot up, we can check if the section that holds the trace_printk
      formats is non-empty, and if it does contain something, then we
      know a trace_printk() has been added to the kernel. At this time
      the trace_printk per cpu buffers are allocated. A check is also
      done at module load time in case a module is added that contains a
      trace_printk().
      
      Once the buffers are allocated, they are never freed. If you use
      a trace_printk() then you should know what you are doing.
      
      A buffer is made for each type of context:
      
        normal
        softirq
        irq
        nmi
      
      The context is checked and the appropriate buffer is used.
      This allows for totally lockless usage of trace_printk(),
      and they no longer even disable interrupts.
      Requested-by: default avatarPeter Zijlstra <a.p.zijlstra@chello.nl>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      07d777fe
  16. 16 Apr, 2012 1 commit
    • Steven Rostedt's avatar
      tracing: Fix regression with tracing_on · 348f0fc2
      Steven Rostedt authored
      
      
      The change to make tracing_on affect only the ftrace ring buffer, caused
      a bug where it wont affect any ring buffer. The problem was that the buffer
      of the trace_array was passed to the write function and not the trace array
      itself.
      
      The trace_array can change the buffer when running a latency tracer. If this
      happens, then the buffer being disabled may not be the buffer currently used
      by ftrace. This will cause the tracing_on file to become useless.
      
      The simple fix is to pass the trace_array to the write function instead of
      the buffer. Then the actual buffer may be changed.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      348f0fc2
  17. 27 Mar, 2012 1 commit
    • Steven Rostedt's avatar
      tracing: Fix ent_size in trace output · 12b5da34
      Steven Rostedt authored
      
      
      When reading the trace file, the records of each of the per_cpu buffers
      are examined to find the next event to print out. At the point of looking
      at the event, the size of the event is recorded. But if the first event is
      chosen, the other events in the other CPU buffers will reset the event size
      that is stored in the iterator descriptor, causing the event size passed to
      the output functions to be incorrect.
      
      In most cases this is not a problem, but for the case of stack traces, it
      is. With the change to the stack tracing to record a dynamic number of
      back traces, the output depends on the size of the entry instead of the
      fixed 8 back traces. When the entry size is not correct, the back traces
      would not be fully printed.
      
      Note, reading from the per-cpu trace files were not affected.
      Reported-by: default avatarThomas Gleixner <tglx@linutronix.de>
      Tested-by: default avatarThomas Gleixner <tglx@linutronix.de>
      Cc: stable@vger.kernel.org
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      12b5da34
  18. 02 Mar, 2012 1 commit
    • Steven Rostedt's avatar
      tracing: Keep NMI watchdog from triggering when dumping trace · b892e5c8
      Steven Rostedt authored
      
      
      As ftrace_dump() (called by ftrace_dump_on_oops) disables interrupts
      as it dumps its output to the console, it can keep interrupts disabled
      for long periods of time. This is likely to trigger the NMI watchdog,
      and it can disrupt the output of critical data.
      
      Add a touch_nmi_watchdog() to each event that is written to the screen
      to keep the NMI watchdog from affecting the output.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      b892e5c8
  19. 22 Feb, 2012 1 commit
    • Steven Rostedt's avatar
      tracing/ring-buffer: Only have tracing_on disable tracing buffers · 499e5470
      Steven Rostedt authored
      
      
      As the ring-buffer code is being used by other facilities in the
      kernel, having tracing_on file disable *all* buffers is not a desired
      affect. It should only disable the ftrace buffers that are being used.
      
      Move the code into the trace.c file and use the buffer disabling
      for tracing_on() and tracing_off(). This way only the ftrace buffers
      will be affected by them and other kernel utilities will not be
      confused to why their output suddenly stopped.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      499e5470
  20. 13 Feb, 2012 1 commit
  21. 04 Jan, 2012 1 commit
  22. 11 Dec, 2011 1 commit
  23. 17 Nov, 2011 2 commits
    • Steven Rostedt's avatar
      tracing: Add entries in buffer and total entries to default output header · 39eaf7ef
      Steven Rostedt authored
      
      
      Knowing the number of event entries in the ring buffer compared
      to the total number that were written is useful information. The
      latency format gives this information and there's no reason that the
      default format does not.
      
      This information is now added to the default header, along with the
      number of online CPUs:
      
       # tracer: nop
       #
       # entries-in-buffer/entries-written: 159836/64690869   #P:4
       #
       #                              _-----=> irqs-off
       #                             / _----=> need-resched
       #                            | / _---=> hardirq/softirq
       #                            || / _--=> preempt-depth
       #                            ||| /     delay
       #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
       #              | |       |   ||||       |         |
                 <idle>-0     [000] ...2    49.442971: local_touch_nmi <-cpu_idle
                 <idle>-0     [000] d..2    49.442973: enter_idle <-cpu_idle
                 <idle>-0     [000] d..2    49.442974: atomic_notifier_call_chain <-enter_idle
                 <idle>-0     [000] d..2    49.442976: __atomic_notifier_call_chain <-atomic_notifier
      
      The above shows that the trace contains 159836 entries, but
      64690869 were written. One could figure out that there were
      64531033 entries that were dropped.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      39eaf7ef
    • Steven Rostedt's avatar
      tracing: Add irq, preempt-count and need resched info to default trace output · 77271ce4
      Steven Rostedt authored
      
      
      People keep asking how to get the preempt count, irq, and need resched info
      and we keep telling them to enable the latency format. Some developers think
      that traces without this info is completely useless, and for a lot of tasks
      it is useless.
      
      The first option was to enable the latency trace as the default format, but
      the header for the latency format is pretty useless for most tracers and
      it also does the timestamp in straight microseconds from the time the trace
      started. This is sometimes more difficult to read as the default trace is
      seconds from the start of boot up.
      
      Latency format:
      
       # tracer: nop
       #
       # nop latency trace v1.1.5 on 3.2.0-rc1-test+
       # --------------------------------------------------------------------
       # latency: 0 us, #159771/64234230, CPU#1 | (M:preempt 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
       #     \   /      |||||  \    |   /
       migratio-6       0...2 41778231us+: rcu_note_context_switch <-__schedule
       migratio-6       0...2 41778233us : trace_rcu_utilization <-rcu_note_context_switch
       migratio-6       0...2 41778235us+: rcu_sched_qs <-rcu_note_context_switch
       migratio-6       0d..2 41778236us+: rcu_preempt_qs <-rcu_note_context_switch
       migratio-6       0...2 41778238us : trace_rcu_utilization <-rcu_note_context_switch
       migratio-6       0...2 41778239us+: debug_lockdep_rcu_enabled <-__schedule
      
      default format:
      
       # tracer: nop
       #
       #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
       #              | |       |          |         |
            migration/0-6     [000]    50.025810: rcu_note_context_switch <-__schedule
            migration/0-6     [000]    50.025812: trace_rcu_utilization <-rcu_note_context_switch
            migration/0-6     [000]    50.025813: rcu_sched_qs <-rcu_note_context_switch
            migration/0-6     [000]    50.025815: rcu_preempt_qs <-rcu_note_context_switch
            migration/0-6     [000]    50.025817: trace_rcu_utilization <-rcu_note_context_switch
            migration/0-6     [000]    50.025818: debug_lockdep_rcu_enabled <-__schedule
            migration/0-6     [000]    50.025820: debug_lockdep_rcu_enabled <-__schedule
      
      The latency format header has latency information that is pretty meaningless
      for most tracers. Although some of the header is useful, and we can add that
      later to the default format as well.
      
      What is really useful with the latency format is the irqs-off, need-resched
      hard/softirq context and the preempt count.
      
      This commit adds the option irq-info which is on by default that adds this
      information:
      
       # tracer: nop
       #
       #                              _-----=> irqs-off
       #                             / _----=> need-resched
       #                            | / _---=> hardirq/softirq
       #                            || / _--=> preempt-depth
       #                            ||| /     delay
       #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
       #              | |       |   ||||       |         |
                 <idle>-0     [000] d..2    49.309305: cpuidle_get_driver <-cpuidle_idle_call
                 <idle>-0     [000] d..2    49.309307: mwait_idle <-cpu_idle
                 <idle>-0     [000] d..2    49.309309: need_resched <-mwait_idle
                 <idle>-0     [000] d..2    49.309310: test_ti_thread_flag <-need_resched
                 <idle>-0     [000] d..2    49.309312: trace_power_start.constprop.13 <-mwait_idle
                 <idle>-0     [000] d..2    49.309313: trace_cpu_idle <-mwait_idle
                 <idle>-0     [000] d..2    49.309315: need_resched <-mwait_idle
      
      If a user wants the old format, they can disable the 'irq-info' option:
      
       # tracer: nop
       #
       #           TASK-PID   CPU#      TIMESTAMP  FUNCTION
       #              | |       |          |         |
                 <idle>-0     [000]     49.309305: cpuidle_get_driver <-cpuidle_idle_call
                 <idle>-0     [000]     49.309307: mwait_idle <-cpu_idle
                 <idle>-0     [000]     49.309309: need_resched <-mwait_idle
                 <idle>-0     [000]     49.309310: test_ti_thread_flag <-need_resched
                 <idle>-0     [000]     49.309312: trace_power_start.constprop.13 <-mwait_idle
                 <idle>-0     [000]     49.309313: trace_cpu_idle <-mwait_idle
                 <idle>-0     [000]     49.309315: need_resched <-mwait_idle
      Requested-by: default avatarThomas Gleixner <tglx@linutronix.de>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      77271ce4
  24. 07 Nov, 2011 1 commit
    • Jiri Olsa's avatar
      tracing/latency: Fix header output for latency tracers · 7e9a49ef
      Jiri Olsa authored
      In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
      function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
      do not display proper latency header.
      
      The involved/fixed latency tracers are:
              wakeup_rt
              wakeup
              preemptirqsoff
              preemptoff
              irqsoff
      
      The patch adds proper handling of tracer configuration options for latency
      tracers, and displaying correct header info accordingly.
      
      * The current output (for wakeup tracer) with both graph and function
        tracers disabled is:
      
        # tracer: wakeup
        #
          <idle>-0       0d.h5    1us+:      0:120:R   + [000]     7:  0:R watchdog/0
          <idle>-0       0d.h5    3us+: ttwu_do_activate.clone.1 <-try_to_wake_up
          ...
      
      * The fixed output is:
      
        # tracer: wakeup
        #
        # wakeup latency trace v1.1.5 on 3.1.0-tip+
        # --------------------------------------------------------------------
        # latency: 55 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
        #    -----------------
        #    | task: migration/0-6 (uid:0 nice:0 policy:1 rt_prio:99)
        #    -----------------
        #
        #                  _------=> CPU#
        #                 / _-----=> irqs-off
        #                | / _----=> need-resched
        #                || / _---=> hardirq/softirq
        #                ||| / _--=> preempt-depth
        #                |||| /     delay
        #  cmd     pid   ||||| time  |   caller
        #     \   /      |||||  \    |   /
             cat-1129    0d..4    1us :   1129:120:R   + [000]     6:  0:R migration/0
             cat-1129    0d..4    2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
      
      * The current output (for wakeup tracer) with only function
        tracer enabled is:
      
        # tracer: wakeup
        #
             cat-1140    0d..4    1us+:   1140:120:R   + [000]     6:  0:R migration/0
             cat-1140    0d..4    2us : ttwu_do_activate.clone.1 <-try_to_wake_up
      
      * The fixed output is:
        # tracer: wakeup
        #
        # wakeup latency trace v1.1.5 on 3.1.0-tip+
        # --------------------------------------------------------------------
        # latency: 207 us, #109/109, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
        #    -----------------
        #    | task: watchdog/1-12 (uid:0 nice:0 policy:1 rt_prio:99)
        #    -----------------
        #
        #                  _------=> CPU#
        #                 / _-----=> irqs-off
        #                | / _----=> need-resched
        #                || / _---=> hardirq/softirq
        #                ||| / _--=> preempt-depth
        #                |||| /     delay
        #  cmd     pid   ||||| time  |   caller
        #     \   /      |||||  \    |   /
          <idle>-0       1d.h5    1us+:      0:120:R   + [001]    12:  0:R watchdog/1
          <idle>-0       1d.h5    3us : ttwu_do_activate.clone.1 <-try_to_wake_up
      
      Link: http://lkml.kernel.org/r/20111107150849.GE1807@m.brq.redhat.com
      
      
      
      Cc: Frederic Weisbecker <fweisbec@gmail.com>
      Cc: Ingo Molnar <mingo@redhat.com>
      Signed-off-by: default avatarJiri Olsa <jolsa@redhat.com>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      7e9a49ef
  25. 14 Oct, 2011 2 commits