From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner+w=401wt.eu-S1755175AbYHSXNm@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1755175AbYHSXNm (ORCPT <rfc822;w@1wt.eu>);
	Tue, 19 Aug 2008 19:13:42 -0400
Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751260AbYHSXNa
	(ORCPT <rfc822;linux-kernel-outgoing>);
	Tue, 19 Aug 2008 19:13:30 -0400
Received: from mx1.redhat.com ([66.187.233.31]:39194 "EHLO mx1.redhat.com"
	rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP
	id S1751120AbYHSXNa (ORCPT <rfc822;linux-kernel@vger.kernel.org>);
	Tue, 19 Aug 2008 19:13:30 -0400
Message-ID: <48AB5388.5050106@redhat.com>
Date: Tue, 19 Aug 2008 19:13:12 -0400
From: Steven Rostedt <srostedt@redhat.com>
User-Agent: Thunderbird 1.5.0.12 (X11/20071019)
MIME-Version: 1.0
To: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
CC: linux-kernel@vger.kernel.org, Ingo Molnar <mingo@elte.hu>,
       Steven Rostedt <rostedt@goodmis.org>
Subject: Re: ftrace bad timings (was: No Subject)
References: <20080819225426.GA11464@Krystal>
In-Reply-To: <20080819225426.GA11464@Krystal>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

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