RE: [PATCH 2/2] trace,x86: Add x86 irq vector entry/exit tracepoints

[Steven Rostedt <rostedt@goodmis.org>]

On Wed, 2011-12-14 at 12:46 -0500, Seiji Aguchi wrote:
> >Well ftrace is a whole subsystem that includes the function tracer and also an interface
> >for tracepoints in debugfs. I was rather suggesting the latter one. This is a good
> >choice for background tracing. And it supports stacktraces. If those generate too much
> >overhead perhaps you can tune the number of entries in the stacktrace, I don't remember
> >if we can do that currently but this can be an interesting feature.
> 
> I would like to periodically check which function call is executed
> rather than seeing stacktrace.
> 
> AFAIK, purpose of stack tracing is showing where the biggest use of the stack takes place.
> I don't think stack tracing achieves my goal.

You may be getting confused with /proc/sys/kernel/stack_tracer_enabled
and /debug/tracing/options/stacktrace
+ /debug/tracing/options/func_stack_trace

The "stack_tracer" is started via the proc file system and detects the
largest stack:

where doing echo 1 > /proc/sys/kernel/stack_tracer_enabled
gives you:

# cat /debug/tracing/stack_trace 
        Depth    Size   Location    (16 entries)
        -----    ----   --------
  0)     2976     416   find_busiest_group+0x6ff/0x7b6
  1)     2560     272   load_balance+0xa3/0x6c7
  2)     2288     144   __schedule+0x31a/0x6c5
  3)     2144      16   schedule+0x5a/0x5c
  4)     2128     160   schedule_timeout+0x37/0xf7
  5)     1968     112   wait_for_common+0xab/0x105
  6)     1856      16   wait_for_completion+0x1d/0x1f
  7)     1840     176   flush_work+0x46/0x60
  8)     1664      16   tty_flush_to_ldisc+0x15/0x17
  9)     1648      32   input_available_p+0x17/0x57
 10)     1616      48   n_tty_poll+0x6b/0x136
 11)     1568      64   tty_poll+0x64/0x7f
 12)     1504     880   do_select+0x327/0x519
 13)      624     400   core_sys_select+0x190/0x22f
 14)      224      96   sys_select+0x91/0xb9
 15)      128     128   system_call_fastpath+0x16/0x1b

But this is not what we are talking about. We are talking about either:

echo 1 > /debug/tracing/options/stacktrace
echo 1 > /debug/tracing/options/irq/irq_handler_entry
# tracer: nop
#
# entries-in-buffer/entries-written: 690/690   #P:2
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     rb_consumer-35    [001] d.h2   435.246779: irq_handler_entry: irq=21 name=uhci_hcd:usb4
     rb_consumer-35    [001] d.h2   435.246788: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper
     rb_consumer-35    [001] d.h2   435.246789: irq_handler_entry: irq=21 name=eth0
     rb_consumer-35    [001] d.h2   435.246796: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper
     rb_consumer-35    [001] d.h2   435.247027: irq_handler_entry: irq=21 name=uhci_hcd:usb4
     rb_consumer-35    [001] d.h2   435.247034: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper
     rb_consumer-35    [001] d.h2   435.247035: irq_handler_entry: irq=21 name=eth0
     rb_consumer-35    [001] d.h2   435.247041: <stack trace>
 => handle_irq_event_percpu
 => handle_irq_event
 => handle_fasteoi_irq
 => handle_irq
 => do_IRQ
 => ret_from_intr
 => ring_buffer_consume
 => ring_buffer_consumer_thread
 => kthread
 => kernel_thread_helper


(Note, the new header isn't pushed to mainline yet).

Or with function tracing:

echo do_irq > /debug/tracing/set_ftrace_filter
echo function > /debug/tracing/current_tracer
echo 1 > /debug/tracing/options/ftrace_stack_trace

# tracer: function
#
# entries-in-buffer/entries-written: 18/18   #P:2
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [001] d..1   609.407279: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.407286: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
          <idle>-0     [001] d..1   609.407527: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.407532: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
          <idle>-0     [001] d..1   609.407777: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.407781: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
          <idle>-0     [001] d..1   609.814166: do_IRQ <-ret_from_intr
          <idle>-0     [001] d..1   609.814171: <stack trace>
 => ret_from_intr
 => cpu_idle
 => start_secondary
            sshd-2293  [001] d.s3   609.814416: do_IRQ <-ret_from_intr
            sshd-2293  [001] d.s3   609.814430: <stack trace>
 => ret_from_intr
 => _raw_spin_unlock_irqrestore
 => __queue_work
 => delayed_work_timer_fn
 => run_timer_softirq
 => __do_softirq
 => call_softirq
 => do_softirq
 => irq_exit
 => smp_apic_timer_interrupt
 => apic_timer_interrupt
 => _raw_spin_unlock_irqrestore
 => __wake_up
 => put_ldisc
 => tty_ldisc_deref
 => tty_poll
 => do_select
 => core_sys_select
 => sys_select
 => system_call_fastpath


Note, the above commands can be done easier if you download trace-cmd:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

The first operation is:

trace-cmd start -e irq_handler_entry -O stacktrace
# cat /sys/kernel/debug/tracing/trace

the second is:

trace-cmd start -p function -l do_IRQ --func-stack
# cat /sys/kernel/debug/tracing/trace


> 
> Rip in local timer interrupt is more accurate information 
> for achieving my goal than stacktrace

Does the above change your mind?

-- Steve