Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S933070AbdGSPtb (ORCPT <rfc822;w@1wt.eu>);
        Wed, 19 Jul 2017 11:49:31 -0400
Received: from mail-wr0-f174.google.com ([209.85.128.174]:37748 "EHLO
        mail-wr0-f174.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
        with ESMTP id S932828AbdGSP24 (ORCPT
        <rfc822;linux-kernel@vger.kernel.org>);
        Wed, 19 Jul 2017 11:28:56 -0400
Date: Wed, 19 Jul 2017 16:28:51 +0100
From: Piotr Gregor <piotrgregor@rsyncme.org>
To: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Ian Abbott <abbotti@mev.co.uk>,
        H Hartley Sweeten <hsweeten@visionengravers.com>,
        linux-kernel@vger.kernel.org, devel@driverdev.osuosl.org
Subject: Re: [PATCH] drivers: staging: comedi: Add ftrace support
Message-ID: <20170719152850.6gs2z3bh3qfevmlt@debian1.home>
References: <20170719135724.3oqaeojico7dxyj5@debian1.home>
 <20170719142106.GA30753@kroah.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20170719142106.GA30753@kroah.com>
User-Agent: Mutt/1.6.2-neo (2016-06-11)
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org
Content-Length: 2245
Lines: 44

On Wed, Jul 19, 2017 at 04:21:06PM +0200, Greg Kroah-Hartman wrote:
> On Wed, Jul 19, 2017 at 02:57:28PM +0100, Piotr Gregor wrote:
> > + * Id : Description
> > + * 0	Enter the interrupt of amplc_dio200_common
> > + * 1	Called from same ISR of amplc_dio200_common if IRQ is handled
> 
> That is a very device-specific tracepoint, do we really want each driver
> to be able to set these up?
> 
> Why can't ftrace handle this type of thing instead?
> 
> thanks,
> 
> greg k-h

There is obviously sched* class of ftrace event, though if one wants to measure
the latency introduced by the _driver_ than one needs to raise event from
the specific place in the driver's code.

I do not exclude the possibility that there may be even better way
to chieve this and it's already implemented in ftrace.
But I didn't see it based on what I have seen so far.
There is sched_wakeup event - I used it as a moment the sleeper is
awoken, but it is not exactly when ISR starts to run.

For example:


          <idle>-0     [005] dN..3.. 335059.686293: sched_wakeup: comm=ktimersoftd/5 pid=51 prio=98 target_cpu=005
          <idle>-0     [005] dN.h3.. 335059.686310: sched_wakeup: comm=irq/19-pcie215 pid=28912 prio=49 target_cpu=005
          <idle>-0     [004] dN.h3.. 335059.686323: sched_wakeup: comm=rcuc/4 pid=42 prio=120 target_cpu=004
          <idle>-0     [000] dN.h3.. 335059.686323: sched_wakeup: comm=rcuc/0 pid=10 prio=120 target_cpu=000
          <idle>-0     [007] dN.h3.. 335059.686323: sched_wakeup: comm=rcuc/7 pid=66 prio=120 target_cpu=007
          <idle>-0     [003] dN.h3.. 335059.686323: sched_wakeup: comm=rcuc/3 pid=34 prio=120 target_cpu=003
          <idle>-0     [006] dN.h3.. 335059.686323: sched_wakeup: comm=rcuc/6 pid=58 prio=120 target_cpu=006
          <idle>-0     [002] dN.h3.. 335059.686323: sched_wakeup: comm=rcuc/2 pid=26 prio=120 target_cpu=002
  irq/19-pcie215-28912 [005] .....11 335059.686328: pcie215_isr: IRQ# [8568], IRQ spurious# [0], IRQ status [00]
          <idle>-0     [003] dN..3.. 335059.686334: sched_wakeup: comm=ksoftirqd/3 pid=36 prio=120 target_cpu=003

If I used sched_wakeup I would start counting time from 335059.686310
but ISR started running at 335059.686328, i.e. 18 us later.

cheers,
Piotr