From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934082AbXGXIbV (ORCPT ); Tue, 24 Jul 2007 04:31:21 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1759924AbXGXIbL (ORCPT ); Tue, 24 Jul 2007 04:31:11 -0400 Received: from smtp4-g19.free.fr ([212.27.42.30]:59091 "EHLO smtp4-g19.free.fr" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750944AbXGXIbJ (ORCPT ); Tue, 24 Jul 2007 04:31:09 -0400 Message-ID: <46A5B8E3.4060004@free.fr> Date: Tue, 24 Jul 2007 10:31:31 +0200 From: John Sigler User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.0.8) Gecko/20061108 SeaMonkey/1.0.6 MIME-Version: 1.0 To: Ingo Molnar CC: linux-rt-users@vger.kernel.org, oprofile-list@lists.sourceforge.net, linux-kernel@vger.kernel.org Subject: Re: Pin-pointing the root of unusual application latencies References: <469600F7.3060603@free.fr> <20070723095357.GA886@elte.hu> <46A4B7C2.1070304@free.fr> <20070723160442.GA7995@elte.hu> In-Reply-To: <20070723160442.GA7995@elte.hu> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 8bit Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org Ingo Molnar wrote: > add 'notrace' to the definition of read_tsc in arch/i386/kernel/tsc.c ( check_dektec_in-1095 |#0): new 271 us user-latency. ( check_dektec_in-1095 |#0): new 275 us user-latency. ( check_dektec_in-1095 |#0): new 290 us user-latency. ( check_dektec_in-1095 |#0): new 297 us user-latency. ( check_dektec_in-1095 |#0): new 345 us user-latency. ( check_dektec_in-1095 |#0): new 358 us user-latency. ( check_dektec_in-1095 |#0): new 384 us user-latency. ( check_dektec_in-1095 |#0): new 392 us user-latency. ( check_dektec_in-1095 |#0): new 395 us user-latency. ( check_dektec_in-1095 |#0): new 396 us user-latency. ( check_dektec_in-1095 |#0): new 1031 us user-latency. ( check_dektec_in-1095 |#0): new 1100 us user-latency. ( check_dektec_in-1095 |#0): new 1105 us user-latency. ( check_dektec_in-1095 |#0): new 1106 us user-latency. Here's the function trace for the 1106-µs latency: http://linux.kernel.free.fr/latency/1106-us-trace.txt These two lines repeat ~2000 times for ~800 µs: softirq--4 0.... 272us : __lock_text_start (rt_run_flush) softirq--4 0.... 272us : rt_spin_unlock (rt_run_flush) With a pair of the following in the middle: softirq--4 0.... 670us : call_rcu (rt_run_flush) softirq--4 0D..1 670us : __rcu_advance_callbacks (call_rcu) PID 4 is [softirq-timer/0] and has priority 50 in SCHED_FIFO. My process has priority 80 in SCHED_RR. It is waiting for IRQ10. # cat /proc/interrupts CPU0 0: 37 XT-PIC-XT timer 1: 2 XT-PIC-XT i8042 2: 0 XT-PIC-XT cascade 7: 0 XT-PIC-XT acpi 10: 151250933 XT-PIC-XT eth2, Dta1xx 11: 12435 XT-PIC-XT eth0 12: 4 XT-PIC-XT eth1 14: 17154 XT-PIC-XT ide0 NMI: 0 LOC: 5786548 ERR: 0 MIS: 0 > or do echo 1 > /proc/sys/kernel/trace_use_raw_cycles > if you are using recent enough -rt http://people.redhat.com/mingo/realtime-preempt/older/patch-2.6.20-rt8 +int trace_use_raw_cycles = 0; + +#ifdef CONFIG_EVENT_TRACE +/* + * Convert raw cycles to usecs. + * Note: this is not the 'clocksource cycles' value, it's the raw + * cycle counter cycles. We use GTOD to timestamp latency start/end + * points, but the trace entries inbetween are timestamped with + * get_cycles(). + */ +static unsigned long notrace cycles_to_us(cycle_t delta) +{ + if (!trace_use_raw_cycles) + return cycles_to_usecs(delta); +#ifdef CONFIG_X86 + do_div(delta, cpu_khz/1000+1); +#elif defined(CONFIG_PPC) + delta = mulhwu(tb_to_us, delta); +#elif defined(CONFIG_ARM) + delta = mach_cycles_to_usecs(delta); +#else + #error Implement cycles_to_usecs. +#endif + + return (unsigned long) delta; +} +#endif # cat /proc/sys/kernel/trace_use_raw_cycles 0 Should I set trace_use_raw_cycles=1 even if I notrace read_tsc? Regards.