lkml.org 
[lkml]   [2008]   [Aug]   [19]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: ftrace bad timings (was: No Subject)
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



\
 
 \ /
  Last update: 2008-08-20 01:15    [W:0.037 / U:33.700 seconds]
©2003-2018 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site