Re: ftrace bad timings (was: No Subject)

From: Steven Rostedt
Date: Tue Aug 19 2008 - 19:13:42 EST


Mathieu Desnoyers wrote:
Hi Steven,

I am currently trying to get precise numbers on the interrupt latency
generated by a heavy load on my new writer-biased rwlock (previously
known as fair rwlock).

However, when trying to use the irqoff tracer, I hit this :

# tracer: irqsoff
#
irqsoff latency trace v1.1.5 on 2.6.27-rc3-trace
--------------------------------------------------------------------
latency: 3995 us, #3/3, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
-----------------
| task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
=> started at: apic_timer_interrupt
=> ended at: __do_softirq

# _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| / # ||||| delay # cmd pid ||||| time | caller # \ / ||||| \ | / <idle>-0 0d..1 0us!: trace_hardirqs_off_thunk (apic_timer_interrupt)
<idle>-0 0d.s2 3995us+: __do_softirq (0)
<idle>-0 0d.s3 3997us : trace_hardirqs_on (__do_softirq)

Is it known/does it have a solution ? I would really like to be able to
see sub 4ms numbers....



Could you go into kernel/trace/trace.c and search for ftrace_now. Then change cpu_clock to sched_clock. cpu_clock is known to give large inaccurate timings and is not reliable with ftrace. Unfortunately, sched_clock can be bad on various hardware, but should always be fine for preempt and irqs off latency timings since that is always local to a single CPU.

-- Steve

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/