Re: ftrace bad timings

[Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>]

* Steven Rostedt (srostedt@redhat.com) wrote:
> 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.
>

Thanks! It works well now.

Hrm, I think I've got something pretty nice wrt interrupt latency. Some
numbers if you happen to be interested... :)


** High contention test **
TEST_DURATION 60s
NR_WRITERS 2
NR_TRYLOCK_WRITERS 1
NR_READERS 4
NR_TRYLOCK_READERS 1
WRITER_DELAY 100us
TRYLOCK_WRITER_DELAY 1000us
TRYLOCK_WRITERS_FAIL_ITER 100
THREAD_READER_DELAY 0   /* busy loop */
INTERRUPT_READER_DELAY 100ms

Standard Linux rwlock

irqsoff latency trace v1.1.5 on 2.6.27-rc3-trace
--------------------------------------------------------------------
 latency: 2902 us, #3/3, CPU#5 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
    -----------------
    | task: wbiasrwlock_wri-4984 (uid:0 nice:-5 policy:0 rt_prio:0)
    -----------------
 => started at: _write_lock_irq
 => ended at:   _write_unlock_irq

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
wbiasrwl-4984  5d..1    0us!: _write_lock_irq (0)
wbiasrwl-4984  5d..2 2902us : _write_unlock_irq (0)
wbiasrwl-4984  5d..3 2903us : trace_hardirqs_on (_write_unlock_irq)


Writer-biased rwlock, same test routine


irqsoff latency trace v1.1.5 on 2.6.27-rc3-trace
--------------------------------------------------------------------
 latency: 33 us, #3/3, CPU#7 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
    -----------------
    | task: events/7-27 (uid:0 nice:-5 policy:0 rt_prio:0)
    -----------------
 => started at: _spin_lock_irqsave
 => ended at:   _spin_unlock_irqrestore

#                _------=> CPU#
#               / _-----=> irqs-off
#              | / _----=> need-resched
#              || / _---=> hardirq/softirq
#              ||| / _--=> preempt-depth
#              |||| /
#              |||||     delay
#  cmd     pid ||||| time  |   caller
#     \   /    |||||   \   |   /
events/7-27    7d...    0us+: _spin_lock_irqsave (0)
events/7-27    7d..1   33us : _spin_unlock_irqrestore (0)
events/7-27    7d..2   33us : trace_hardirqs_on (_spin_unlock_irqrestore)

(latency unrelated to the tests, therefore irq latency <= 33us)

wbias rwlock instrumentation (below) shows that interrupt latency has been 14176
cycles, for a total of 7us.

Detailed writer-biased rwlock latency breakdown :

IRQ latency for cpu 0 disabled 1086419 times, [min,avg,max] 316,2833,14176 cycles
IRQ latency for cpu 1 disabled 1099517 times, [min,avg,max] 316,1820,8254 cycles
IRQ latency for cpu 3 disabled 159088 times, [min,avg,max] 316,1409,5632 cycles
IRQ latency for cpu 4 disabled 161 times, [min,avg,max] 340,1882,5206 cycles
SoftIRQ latency for cpu 0 disabled 1086419 times, [min,avg,max] 2212,5350,166402 cycles
SoftIRQ latency for cpu 1 disabled 1099517 times, [min,avg,max] 2230,4265,138988 cycles
SoftIRQ latency for cpu 3 disabled 159088 times, [min,avg,max] 2212,3319,14992 cycles
SoftIRQ latency for cpu 4 disabled 161 times, [min,avg,max] 2266,3802,7138 cycles
Preemption latency for cpu 3 disabled 59855 times, [min,avg,max] 5266,15706,53494 cycles
Preemption latency for cpu 4 disabled 72 times, [min,avg,max] 5728,14132,28042 cycles
Preemption latency for cpu 5 disabled 55586612 times, [min,avg,max] 196,2080,126526 cycles


> -- Steve
>

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68