| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20080820064341.GA24987@Krystal>
Date: Wed, 20 Aug 2008 02:43:41 -0400
From: Mathieu Desnoyers <mathieu.desnoyers@...ymtl.ca>
To: Steven Rostedt <srostedt@...hat.com>
Cc: linux-kernel@...r.kernel.org, Ingo Molnar <mingo@...e.hu>,
Steven Rostedt <rostedt@...dmis.org>
Subject: Re: ftrace bad timings
* Steven Rostedt (srostedt@...hat.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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists