From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S1760780AbcINJoh (ORCPT <rfc822;w@1wt.eu>);
        Wed, 14 Sep 2016 05:44:37 -0400
Received: from Galois.linutronix.de ([146.0.238.70]:33607 "EHLO
        Galois.linutronix.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
        with ESMTP id S1756759AbcINJod (ORCPT
        <rfc822;linux-kernel@vger.kernel.org>);
        Wed, 14 Sep 2016 05:44:33 -0400
Date: Wed, 14 Sep 2016 11:42:03 +0200 (CEST)
From: Thomas Gleixner <tglx@linutronix.de>
To: Binoy Jayan <binoy.jayan@linaro.org>
cc: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>,
        Ingo Molnar <mingo@redhat.com>,
        Daniel Wagner <daniel.wagner@bmw-carit.de>,
        Arnd Bergmann <arnd@arndb.de>,
        Linux kernel mailing list <linux-kernel@vger.kernel.org>,
        Masami <masami.hiramatsu@linaro.org>, Carsten Emde <C.Emde@osadl.org>
Subject: Re: [PATCH v6 3/4] tracing: Add trace_irqsoff tracepoints
In-Reply-To: <CAHv-k_-AxyBGsrAR7NpvYnbGU=5YhizkHOcp=hddPTKCvgw4Rg@mail.gmail.com>
Message-ID: <alpine.DEB.2.20.1609141134441.6233@nanos>
References: <1473246835-30075-1-git-send-email-binoy.jayan@linaro.org> <1473246835-30075-4-git-send-email-binoy.jayan@linaro.org> <alpine.DEB.2.20.1609080923190.5647@nanos> <CAHv-k_-AxyBGsrAR7NpvYnbGU=5YhizkHOcp=hddPTKCvgw4Rg@mail.gmail.com>
User-Agent: Alpine 2.20 (DEB 67 2015-01-07)
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Binoy,

On Wed, 14 Sep 2016, Binoy Jayan wrote:
> On 8 September 2016 at 13:36, Thomas Gleixner <tglx@linutronix.de> wrote:
> > On Wed, 7 Sep 2016, Binoy Jayan wrote:
> >> This captures only the latencies introduced by disabled irqs and
> >> preemption. Additional per process data has to be captured to calculate
> >> the effective latencies introduced for individual processes.
> >
> > And what is the additional per process data and how is it captured and
> > used?
> 
> This is the patch which would touch the scheduler code which I did not
> want to do.  I was trying to achieve the same using kprobes but did not
> get around to make it work with the histograms.

So the questions remain:

   - How is this facility useful on it's own?
   - What is the value of adding this?
   - How is it used and what valuable debug information can be collected?

And these questions need to be answered independently of additional data,
which you are obviously unable to sample.
    
> > Aside of that it is silly to evaluate trace_clock_local() for the actual
> > tracepoint simply because that time is already stored in the tracepoint
> > itself. The flow here is:
> >
> >         event = trace_event_buffer_lock_reserve();
> >         entry = ring_buffer_event_data(event);
> >         { <assign>; }  <-- Here we assign the entries by the __field and
> >                            __array macros.
> >
> >
> > So you should talk to Steven about having a way to retrieve that time from
> > entry itself in a generic way.
> >
> Steven mentioned that the timestamp in the ring buffer is in the offset
> form and also it may not be equivalent to trace_clock_local() time. I
> also tried using the timestamp from the per cpu trace data but it did not
> seem to provide correct value for the timestamp.

That's what we have today. Now if we want to add something like this then
we really want to avoid reading timestamps twice. And it's irrelevant
whether the timestamp comes from trace_clock_local() or
ktime_get_[mono|raw]_fast_ns because you can do the histogram based on that
as well.

Fact is that the tracer core itself takes a timestamp already and it should
not be rocket science to make the core store it as a full timestamp when
requested by the caller. Such a store is way cheeper than accessing
hardware over and over.

Thanks,

	tglx