Gitweb:     http://git.kernel.org/linus/cc51a0fca66658ea710db566ba17e80e3f7d4957
Commit:     cc51a0fca66658ea710db566ba17e80e3f7d4957
Parent:     03889384cee7a198a79447c1ea6aca2c8e54d155
Author:     Steven Rostedt <srostedt@redhat.com>
AuthorDate: Fri Dec 11 11:54:51 2009 -0500
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Fri Dec 11 13:19:51 2009 -0500

    tracing: Add stack trace to irqsoff tracer
    
    The irqsoff and friends tracers help in finding causes of latency in the
    kernel. The also work with the function tracer to show what was happening
    when interrupts or preemption are disabled. But the function tracer has
    a bit of an overhead and can cause exagerated readings.
    
    Currently, when tracing with /proc/sys/kernel/ftrace_enabled = 0, where the
    function tracer is disabled, the information that is provided can end up
    being useless. For example, a 2 and a half millisecond latency only showed:
    
     # tracer: preemptirqsoff
     #
     # preemptirqsoff latency trace v1.1.5 on 2.6.32
     # --------------------------------------------------------------------
     # latency: 2463 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
     #    -----------------
     #    | task: -4242 (uid:0 nice:0 policy:0 rt_prio:0)
     #    -----------------
     #  => started at: _spin_lock_irqsave
     #  => ended at:   remove_wait_queue
     #
     #
     #                  _------=> CPU#
     #                 / _-----=> irqs-off
     #                | / _----=> need-resched
     #                || / _---=> hardirq/softirq
     #                ||| / _--=> preempt-depth
     #                |||| /_--=> lock-depth
     #                |||||/     delay
     #  cmd     pid   |||||| time  |   caller
     #     \   /      ||||||   \   |   /
     hackbenc-4242    2d....    0us!: trace_hardirqs_off <-_spin_lock_irqsave
     hackbenc-4242    2...1. 2463us+: _spin_unlock_irqrestore <-remove_wait_queue
     hackbenc-4242    2...1. 2466us : trace_preempt_on <-remove_wait_queue
    
    The above lets us know that hackbench with pid 2463 grabbed a spin lock
    somewhere and enabled preemption at remove_wait_queue. This helps a little
    but where this actually happened is not informative.
    
    This patch adds the stack dump to the end of the irqsoff tracer. This provides
    the following output:
    
     hackbenc-4242    2d....    0us!: trace_hardirqs_off <-_spin_lock_irqsave
     hackbenc-4242    2...1. 2463us+: _spin_unlock_irqrestore <-remove_wait_queue
     hackbenc-4242    2...1. 2466us : trace_preempt_on <-remove_wait_queue
     hackbenc-4242    2...1. 2467us : <stack trace>
      => sub_preempt_count
      => _spin_unlock_irqrestore
      => remove_wait_queue
      => free_poll_entry
      => poll_freewait
      => do_sys_poll
      => sys_poll
      => system_call_fastpath
    
    Now we see that the culprit of this latency was the free_poll_entry code.
    
    Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_irqsoff.c |    2 ++
 1 files changed, 2 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 3aa7eaa..2974bc7 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -151,6 +151,8 @@ check_critical_timing(struct trace_array *tr,
 		goto out_unlock;
 
 	trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
+	/* Skip 5 functions to get to the irq/preempt enable function */
+	__trace_stack(tr, flags, 5, pc);
 
 	if (data->critical_sequence != max_sequence)
 		goto out_unlock;
--
To unsubscribe from this list: send the line "unsubscribe git-commits-head" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html