From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758239AbZBZDUg (ORCPT ); Wed, 25 Feb 2009 22:20:36 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751662AbZBZDU1 (ORCPT ); Wed, 25 Feb 2009 22:20:27 -0500 Received: from mx3.mail.elte.hu ([157.181.1.138]:45617 "EHLO mx3.mail.elte.hu" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751564AbZBZDU0 (ORCPT ); Wed, 25 Feb 2009 22:20:26 -0500 Date: Thu, 26 Feb 2009 04:19:10 +0100 From: Ingo Molnar To: Steven Rostedt Cc: Andrew Morton , Pekka Enberg , LKML , Thomas Gleixner , Peter Zijlstra , Frederic Weisbecker , Theodore Tso , Arjan van de Ven , Pekka Paalanen , Arnaldo Carvalho de Melo , Jason Baron , Martin Bligh , Mathieu Desnoyers , "Frank Ch. Eigler" , KOSAKI Motohiro , Jens Axboe , Masami Hiramatsu , Steven Rostedt Subject: Re: [PATCH 2/4] tracing: add event trace infrastructure Message-ID: <20090226031910.GF7526@elte.hu> References: <20090224194548.3effb746.akpm@linux-foundation.org> <20090224203308.8d623e0b.akpm@linux-foundation.org> <20090225081118.GC15303@elte.hu> <20090225002852.5ef5b869.akpm@linux-foundation.org> <84144f020902250100k41e55dd7w8a9c8d2ca96908ea@mail.gmail.com> <20090225012250.db68e480.akpm@linux-foundation.org> <20090225155709.GA12732@elte.hu> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.18 (2008-05-17) X-ELTE-VirusStatus: clean X-ELTE-SpamScore: -1.5 X-ELTE-SpamLevel: X-ELTE-SpamCheck: no X-ELTE-SpamVersion: ELTE 2.0 X-ELTE-SpamCheck-Details: score=-1.5 required=5.9 tests=BAYES_00 autolearn=no SpamAssassin version=3.2.3 -1.5 BAYES_00 BODY: Bayesian spam probability is 0 to 1% [score: 0.0000] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org * Steven Rostedt wrote: > > > On Wed, 25 Feb 2009, Ingo Molnar wrote: > > > > > * Steven Rostedt wrote: > > > > > > # _------=> 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.s. 97us : __do_softirq (do_softirq) > > > > -0 0d.s1 98us : trace_hardirqs_on (do_softirq) > > [...] > > > > > > > > your time starts now. > > > > > > Note, that is a legacy format, that works great for the > > > latency tracers. Those include (the example you used) irqsoff, > > > the preempt off, wake up latencies. This gives us a nice > > > listing of why we are hitting a latency. All other plugins > > > generally use the trace file, although they could also use > > > that file too. > > > > > > As for your English comment. I showed the header to my wife, > > > and she had no idea what irqs-off means, nor need-resched, nor > > > preempt-depth ;-) They are not quite English as they are > > > technical terms. Most of the names are hard coded into the > > > kernel too. > > > > > > Yeah, maybe that file (latency_trace) is a bit too much. I for > > > one love it. It is great to load a kernel on some remote box, > > > and run the irqs off latency tracer to see where the > > > interrupts are disabled for the longest time. This format is > > > really nice because it shows me when we are in an interrupt, > > > or interrupts are disabled, and when the task should have been > > > rescheduled. > > > > > > This has help find places that we miss a preemption check too. > > > > Could we get that, as PeterZ has suggested, as a trace_option > > column in the 'trace' file? It would be default off for > > non-latency tracers, with latency tracing plugins turning it on > > by default. Would that work? > > I guess adding options will be a high priority for me now. I > can't parse irqsoff output anymore :-( > > Besides the information of the ..... area, the times were all > based off of the start of the trace, not global. This allowed > you to see the latency in the trace. That is something that is sane to have as a default anyway. It always annoys me that i have to start looking at a trace by subtracting the first timestamp from the last timestamp. Ingo