From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753398AbYHTGny (ORCPT ); Wed, 20 Aug 2008 02:43:54 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751597AbYHTGno (ORCPT ); Wed, 20 Aug 2008 02:43:44 -0400 Received: from tomts16-srv.bellnexxia.net ([209.226.175.4]:54856 "EHLO tomts16-srv.bellnexxia.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751560AbYHTGnn (ORCPT ); Wed, 20 Aug 2008 02:43:43 -0400 X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: Aq0EANRZq0hMRKxB/2dsb2JhbACBYrN9gVs Date: Wed, 20 Aug 2008 02:43:41 -0400 From: Mathieu Desnoyers To: Steven Rostedt Cc: linux-kernel@vger.kernel.org, Ingo Molnar , Steven Rostedt Subject: Re: ftrace bad timings Message-ID: <20080820064341.GA24987@Krystal> References: <20080819225426.GA11464@Krystal> <48AB5388.5050106@redhat.com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline In-Reply-To: <48AB5388.5050106@redhat.com> X-Editor: vi X-Info: http://krystal.dyndns.org:8080 X-Operating-System: Linux/2.6.21.3-grsec (i686) X-Uptime: 02:41:27 up 76 days, 11:21, 6 users, load average: 0.84, 0.75, 0.70 User-Agent: Mutt/1.5.16 (2007-06-11) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org * 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 # \ / ||||| \ >> | / -0 0d..1 0us!: trace_hardirqs_off_thunk >> (apic_timer_interrupt) >> -0 0d.s2 3995us+: __do_softirq (0) >> -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