All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH] drivers: staging: comedi: Add ftrace support
@ 2017-07-19 11:30 Piotr Gregor
  2017-07-19 11:38 ` Greg Kroah-Hartman
  2017-07-19 13:25 ` Dan Carpenter
  0 siblings, 2 replies; 8+ messages in thread
From: Piotr Gregor @ 2017-07-19 11:30 UTC (permalink / raw)
  To: Ian Abbott; +Cc: H Hartley Sweeten, Greg Kroah-Hartman, linux-kernel, devel

This patch originates from the need to measure latency
introduced by driver for Amplicon's PCIE215 during interrupt
handling.

Added is a single ftrace event:

/*
* Tracepoint for calling from various places inside Comedi.
* Takes simple id and prints it to the trace log if trace
* events from Comedi are enabled.
*
* Currently following tracepoints are in use:
*
* Id : Description
* 0   Enter the interrupt of amplc_dio200_common
* 1   Called from same ISR of amplc_dio200_common if IRQ is handled
*
* If you would like to add new tracepoint just add a call to
*     trace_comedi_event(id)
* with id incremented.
*/
TRACE_EVENT(comedi_event,
        TP_PROTO(__u8 id),
        TP_ARGS(id),
        TP_STRUCT__entry(
                         __field(__u8, id)
                        ),
        TP_fast_assign(
                       __entry->id = id;
                       ),
        TP_printk("[%u]", __entry->id)
);

Event can be raised from multiple places in code
and when read from trace log and disambiguated by id
allows for latency (timing) measurement between
corresponding points in code.

Event with id 0 has been put inside amplc_dio200_common
interrupt handler to mark ISR entry. Event with id 1
has been put right after previous one to mark cases when
IRQ is handled.

Example

By enabling triggering of Comedi ftrace events together
with sched_wakeup event

        cd /sys/kernel/debug/tracing
        echo 1 > events/comedi/enable
        echo 1 > events/sched/sched_wakeup/enable
        echo nop > trace
                start the program using Comedi to execute blocking read
                to sense the signal asserted on pin PPI_Y_C0 of PCIE215
        echo 1 > tracing_on
        echo 0 > tracing_on
        vim trace

and by analysing the content of produced trace file

(...)
35732           <idle>-0     [001] dN..3..  7470.471776: sched_wakeup:
                comm=ktimersoftd/1 pid=19 prio=98 target_cpu=001
35733           <idle>-0     [005] dN..3..  7470.471784: sched_wakeup:
                comm=ktimersoftd/5 pid=51 prio=98 target_cpu=005
35734   irq/19-pcie215-7661  [005] .....11  7470.471802: comedi_event: [0]
35735   irq/19-pcie215-7661  [005] .....11  7470.471803: comedi_event: [1]
35736           <idle>-0     [004] dN.h3..  7470.471820: sched_wakeup:
                comm=rcuc/4 pid=42 prio=120 target_cpu=004
35737           <idle>-0     [002] dN.h3..  7470.471820: sched_wakeup:
                comm=rcuc/2 pid=26 prio=120 target_cpu=002
35738           <idle>-0     [003] dN.h3..  7470.471820: sched_wakeup:
                comm=rcuc/3 pid=34 prio=120 target_cpu=003
35739           <idle>-0     [007] dN.h3..  7470.471820: sched_wakeup:
                comm=rcuc/7 pid=66 prio=120 target_cpu=007
35740           <idle>-0     [000] dN.h3..  7470.471821: sched_wakeup:
                comm=rcuc/0 pid=10 prio=120 target_cpu=000
35741           <idle>-0     [006] dN..3..  7470.471824: sched_wakeup:
                comm=ktimersoftd/6 pid=59 prio=98 target_cpu=006
35742           <idle>-0     [003] dN..3..  7470.471840: sched_wakeup:
                comm=ksoftirqd/3 pid=36 prio=120 target_cpu=003
35743           <idle>-0     [002] dN..3..  7470.471840: sched_wakeup:
                comm=ktimersoftd/2 pid=27 prio=98 target_cpu=002
35744           <idle>-0     [000] dN..3..  7470.471841: sched_wakeup:
                comm=ktimersoftd/0 pid=4 prio=98 target_cpu=000
35745           <idle>-0     [004] dN..3..  7470.471843: sched_wakeup:
                comm=ktimersoftd/4 pid=43 prio=98 target_cpu=004
35746           <idle>-0     [007] dN..3..  7470.471845: sched_wakeup:
                comm=ktimersoftd/7 pid=67 prio=98 target_cpu=007
35747           <idle>-0     [003] dN..3..  7470.471849: sched_wakeup:
                comm=ktimersoftd/3 pid=35 prio=98 target_cpu=003
35748   irq/19-pcie215-7661  [005] d...213  7470.471859: sched_wakeup:
                comm=txrx pid=7683 prio=120 target_cpu=001
35749           txrx-7683  [001] d...313  7470.472163: sched_wakeup:
                comm=kworker/u16:3 pid=3444 prio=120 target_cpu=003
35750           txrx-7683  [001] d...313  7470.472270: sched_wakeup:
                comm=kworker/u16:1 pid=20072 prio=120 target_cpu=006
35751    kworker/u16:3-3444  [003] d...211  7470.472280: sched_wakeup:
                comm=mate-terminal pid=1465 prio=120 target_cpu=002
35752    mate-terminal-1465  [002] dN..2..  7470.472766: sched_wakeup:
                comm=ktimersoftd/2 pid=27 prio=98 target_cpu=002
35753           <idle>-0     [006] dN..3..  7470.472766: sched_wakeup:
                comm=ktimersoftd/6 pid=59 prio=98 target_cpu=006
(...)

it has been found that on the sample of 625 interrupts the worse
case latency for Comedi driver to wake up the sleeper on a blocking
call to read() was 80 microseconds (19.31 us on average).

wakeup latency (all in seconds)
Mean                    0.000 019 31
Standard Error          3.127172298894E-007
Mode                    0.000 016 000
Median                  0.000 017 000
Variance                6.11200411685624E-011
Standard Deviation      0.000 007 818
Kurtosis                8.9662160643
Skewness                2.333413546
Range                   0.000 070 000
Minimum                 0.000 010 000
Maximum                 0.000 080 000
Sum                     0.012072
Count                   625

Testing environment

cat /proc/cpuinfo
processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model       : 94
model name  : Intel(R) Core(TM) i7-6700 CPU @ 3.40GHz
stepping    : 3
microcode   : 0xa0
cpu MHz     : 799.929
cache size  : 8192 KB
physical id : 0
siblings    : 8
core id     : 0
cpu cores   : 4
apicid      : 0
initial apicid  : 0
fpu     : yes
fpu_exception   : yes
cpuid level : 22
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca
cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall
nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl
xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor
ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2
x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm
abm 3dnowprefetch ida arat pln pts dtherm hwp hwp_notify hwp_act_window
hwp_epp intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase
tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx rdseed adx smap
clflushopt xsaveopt xsavec xgetbv1
bugs        :
bogomips    : 6812.95
clflush size    : 64
cache_alignment : 64
address sizes   : 39 bits physical, 48 bits virtual
power management:
(...)

uname -a
Linux piotrpc 4.4.70-rt83 #1 SMP PREEMPT RT Thu Jul 13 08:42:02 BST 2017
x86_64 GNU/Linux

RAM: 8GB

Signed-off-by: Piotr Gregor <pgregor@quadrant-systems.co.uk>
---
 drivers/staging/comedi/drivers/Makefile            |  2 ++
 .../staging/comedi/drivers/amplc_dio200_common.c   |  5 +++
 drivers/staging/comedi/drivers/comedi-trace.h      | 42 ++++++++++++++++++++++
 3 files changed, 49 insertions(+)
 create mode 100644 drivers/staging/comedi/drivers/comedi-trace.h

diff --git a/drivers/staging/comedi/drivers/Makefile b/drivers/staging/comedi/drivers/Makefile
index 0c8cfa7..1511a064 100644
--- a/drivers/staging/comedi/drivers/Makefile
+++ b/drivers/staging/comedi/drivers/Makefile
@@ -143,5 +143,7 @@ obj-$(CONFIG_COMEDI_NI_LABPC_ISADMA)        += ni_labpc_isadma.o
 obj-$(CONFIG_COMEDI_8255)              += comedi_8255.o
 obj-$(CONFIG_COMEDI_8255_SA)           += 8255.o
 obj-$(CONFIG_COMEDI_AMPLC_DIO200)      += amplc_dio200_common.o
+CFLAGS_amplc_dio200_common.o = -I$(src)
+#EXTRA_CFLAGS = -I$(src)
 obj-$(CONFIG_COMEDI_AMPLC_PC236)       += amplc_pc236_common.o
 obj-$(CONFIG_COMEDI_DAS08)             += das08.o
diff --git a/drivers/staging/comedi/drivers/amplc_dio200_common.c b/drivers/staging/comedi/drivers/amplc_dio200_common.c
index f6e4e98..fa356db 100644
--- a/drivers/staging/comedi/drivers/amplc_dio200_common.c
+++ b/drivers/staging/comedi/drivers/amplc_dio200_common.c
@@ -28,6 +28,9 @@
 #include "comedi_8254.h"
 #include "8255.h"              /* only for register defines */

+#define CREATE_TRACE_POINTS
+#include "comedi-trace.h"
+
 /* 200 series registers */
 #define DIO200_IO_SIZE         0x20
 #define DIO200_PCIE_IO_SIZE    0x4000
@@ -482,8 +485,10 @@ static irqreturn_t dio200_interrupt(int irq, void *d)
        struct comedi_subdevice *s = dev->read_subdev;
        int handled;

+       trace_comedi_event(0);
        if (!dev->attached)
                return IRQ_NONE;
+       trace_comedi_event(1);

        handled = dio200_handle_read_intr(dev, s);

diff --git a/drivers/staging/comedi/drivers/comedi-trace.h b/drivers/staging/comedi/drivers/comedi-trace.h
new file mode 100644
index 0000000..1fa0a19
--- /dev/null
+++ b/drivers/staging/comedi/drivers/comedi-trace.h
@@ -0,0 +1,42 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM comedi
+
+#if !defined(_TRACE_COMEDI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_COMEDI_H
+
+#include <linux/tracepoint.h>
+
+/*
+ * Tracepoint for calling from various places inside Comedi.
+ * Takes simple id and prints it to the trace log if trace
+ * events from Comedi are enabled.
+ *
+ * Currently following tracepoints are in use:
+ *
+ * Id : Description
+ * 0   Enter the interrupt of amplc_dio200_common
+ * 1   Called from same ISR of amplc_dio200_common if IRQ is handled
+ *
+ * If you would like to add new tracepoint just add a call to
+ *     trace_comedi_event(id)
+ * with id incremented.
+ */
+TRACE_EVENT(comedi_event,
+       TP_PROTO(__u8 id),
+       TP_ARGS(id),
+       TP_STRUCT__entry(
+                        __field(__u8, id)
+                       ),
+       TP_fast_assign(
+                      __entry->id = id;
+                      ),
+       TP_printk("[%u]", __entry->id)
+);
+
+#endif /* _TRACE_COMEDI_H */
+
+/* This part must be outside protection */
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE comedi-trace
+#include <trace/define_trace.h>
--
2.1.4


--
Piotr Gregor
________________________________


The information contained in this e-mail is confidential. It may also be legally privileged. It is only intended for the stated addressee(s) and access to it by any other person is unauthorised.

If you are not an addressee, you must not disclose, copy, circulate or in any other way use or rely on the information contained in this e-mail. Such unauthorised use may be unlawful.

If you have received this e-mail in error, please inform us immediately and delete it (and all copies) from your system.

________________________________

^ permalink raw reply related	[flat|nested] 8+ messages in thread

* Re: [PATCH] drivers: staging: comedi: Add ftrace support
  2017-07-19 11:30 [PATCH] drivers: staging: comedi: Add ftrace support Piotr Gregor
@ 2017-07-19 11:38 ` Greg Kroah-Hartman
  2017-07-19 13:25 ` Dan Carpenter
  1 sibling, 0 replies; 8+ messages in thread
From: Greg Kroah-Hartman @ 2017-07-19 11:38 UTC (permalink / raw)
  To: Piotr Gregor; +Cc: Ian Abbott, H Hartley Sweeten, linux-kernel, devel

On Wed, Jul 19, 2017 at 12:30:28PM +0100, Piotr Gregor wrote:
 
> 
> The information contained in this e-mail is confidential. It may also be legally privileged. It is only intended for the stated addressee(s) and access to it by any other person is unauthorised.
> 
> If you are not an addressee, you must not disclose, copy, circulate or in any other way use or rely on the information contained in this e-mail. Such unauthorised use may be unlawful.
> 
> If you have received this e-mail in error, please inform us immediately and delete it (and all copies) from your system.

Ok, now deleted :(

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH] drivers: staging: comedi: Add ftrace support
  2017-07-19 11:30 [PATCH] drivers: staging: comedi: Add ftrace support Piotr Gregor
  2017-07-19 11:38 ` Greg Kroah-Hartman
@ 2017-07-19 13:25 ` Dan Carpenter
  2017-07-19 21:05   ` Piotr Gregor
  1 sibling, 1 reply; 8+ messages in thread
From: Dan Carpenter @ 2017-07-19 13:25 UTC (permalink / raw)
  To: Piotr Gregor; +Cc: Ian Abbott, devel, linux-kernel, Greg Kroah-Hartman

Everyone please delete this confidential email.  Piotr is leakier than
the Trump administration!

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH] drivers: staging: comedi: Add ftrace support
  2017-07-19 13:25 ` Dan Carpenter
@ 2017-07-19 21:05   ` Piotr Gregor
  2017-07-20  8:35     ` Dan Carpenter
  0 siblings, 1 reply; 8+ messages in thread
From: Piotr Gregor @ 2017-07-19 21:05 UTC (permalink / raw)
  To: Dan Carpenter
  Cc: Piotr Gregor, Ian Abbott, devel, linux-kernel, Greg Kroah-Hartman

On Wed, Jul 19, 2017 at 2:25 PM, Dan Carpenter <dan.carpenter@oracle.com> wrote:
> Everyone please delete this confidential email.  Piotr is leakier than
> the Trump administration!
>

Sanity level of Dan's assessments is less than half the average level
of Hillary's supporter!

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH] drivers: staging: comedi: Add ftrace support
  2017-07-19 21:05   ` Piotr Gregor
@ 2017-07-20  8:35     ` Dan Carpenter
  0 siblings, 0 replies; 8+ messages in thread
From: Dan Carpenter @ 2017-07-20  8:35 UTC (permalink / raw)
  To: Piotr Gregor
  Cc: Piotr Gregor, Ian Abbott, devel, linux-kernel, Greg Kroah-Hartman

;)

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH] drivers: staging: comedi: Add ftrace support
  2017-07-19 14:21 ` Greg Kroah-Hartman
@ 2017-07-19 15:28   ` Piotr Gregor
  0 siblings, 0 replies; 8+ messages in thread
From: Piotr Gregor @ 2017-07-19 15:28 UTC (permalink / raw)
  To: Greg Kroah-Hartman; +Cc: Ian Abbott, H Hartley Sweeten, linux-kernel, devel

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH] drivers: staging: comedi: Add ftrace support
  2017-07-19 13:57 Piotr Gregor
@ 2017-07-19 14:21 ` Greg Kroah-Hartman
  2017-07-19 15:28   ` Piotr Gregor
  0 siblings, 1 reply; 8+ messages in thread
From: Greg Kroah-Hartman @ 2017-07-19 14:21 UTC (permalink / raw)
  To: Piotr Gregor; +Cc: Ian Abbott, H Hartley Sweeten, linux-kernel, devel

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

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [PATCH] drivers: staging: comedi: Add ftrace support
@ 2017-07-19 13:57 Piotr Gregor
  2017-07-19 14:21 ` Greg Kroah-Hartman
  0 siblings, 1 reply; 8+ messages in thread
From: Piotr Gregor @ 2017-07-19 13:57 UTC (permalink / raw)
  To: Ian Abbott; +Cc: H Hartley Sweeten, Greg Kroah-Hartman, linux-kernel, devel

This patch originates from the need to measure latency
introduced by driver for Amplicon's PCIE215 during interrupt
handling.

Added is a single ftrace event:

/*
* Tracepoint for calling from various places inside Comedi.
* Takes simple id and prints it to the trace log if trace
* events from Comedi are enabled.
*
* Currently following tracepoints are in use:
*
* Id : Description
* 0   Enter the interrupt of amplc_dio200_common
* 1   Called from same ISR of amplc_dio200_common if IRQ is handled
*
* If you would like to add new tracepoint just add a call to
*     trace_comedi_event(id)
* with id incremented.
*/
TRACE_EVENT(comedi_event,
	TP_PROTO(__u8 id),
	TP_ARGS(id),
	TP_STRUCT__entry(
			 __field(__u8, id)
			),
	TP_fast_assign(
		       __entry->id = id;
		       ),
	TP_printk("[%u]", __entry->id)
);

Event can be raised from multiple places in code
and when read from trace log and disambiguated by id
allows for latency (timing) measurement between
corresponding points in code.

Event with id 0 has been put inside amplc_dio200_common
interrupt handler to mark ISR entry. Event with id 1
has been put right after previous one to mark cases when
IRQ is handled.

Example

By enabling triggering of Comedi ftrace events together
with sched_wakeup event

	cd /sys/kernel/debug/tracing
	echo 1 > events/comedi/enable
	echo 1 > events/sched/sched_wakeup/enable
	echo nop > trace
		start the program using Comedi to execute blocking read
		to sense the signal asserted on pin PPI_Y_C0 of PCIE215
	echo 1 > tracing_on
	echo 0 > tracing_on
	vim trace

and by analysing the content of produced trace file

(...)
35732           <idle>-0     [001] dN..3..  7470.471776: sched_wakeup:
		comm=ktimersoftd/1 pid=19 prio=98 target_cpu=001
35733           <idle>-0     [005] dN..3..  7470.471784: sched_wakeup:
		comm=ktimersoftd/5 pid=51 prio=98 target_cpu=005
35734   irq/19-pcie215-7661  [005] .....11  7470.471802: comedi_event: [0]
35735   irq/19-pcie215-7661  [005] .....11  7470.471803: comedi_event: [1]
35736           <idle>-0     [004] dN.h3..  7470.471820: sched_wakeup:
		comm=rcuc/4 pid=42 prio=120 target_cpu=004
35737           <idle>-0     [002] dN.h3..  7470.471820: sched_wakeup:
		comm=rcuc/2 pid=26 prio=120 target_cpu=002
35738           <idle>-0     [003] dN.h3..  7470.471820: sched_wakeup:
		comm=rcuc/3 pid=34 prio=120 target_cpu=003
35739           <idle>-0     [007] dN.h3..  7470.471820: sched_wakeup:
		comm=rcuc/7 pid=66 prio=120 target_cpu=007
35740           <idle>-0     [000] dN.h3..  7470.471821: sched_wakeup:
		comm=rcuc/0 pid=10 prio=120 target_cpu=000
35741           <idle>-0     [006] dN..3..  7470.471824: sched_wakeup:
		comm=ktimersoftd/6 pid=59 prio=98 target_cpu=006
35742           <idle>-0     [003] dN..3..  7470.471840: sched_wakeup:
		comm=ksoftirqd/3 pid=36 prio=120 target_cpu=003
35743           <idle>-0     [002] dN..3..  7470.471840: sched_wakeup:
		comm=ktimersoftd/2 pid=27 prio=98 target_cpu=002
35744           <idle>-0     [000] dN..3..  7470.471841: sched_wakeup:
		comm=ktimersoftd/0 pid=4 prio=98 target_cpu=000
35745           <idle>-0     [004] dN..3..  7470.471843: sched_wakeup:
		comm=ktimersoftd/4 pid=43 prio=98 target_cpu=004
35746           <idle>-0     [007] dN..3..  7470.471845: sched_wakeup:
		comm=ktimersoftd/7 pid=67 prio=98 target_cpu=007
35747           <idle>-0     [003] dN..3..  7470.471849: sched_wakeup:
		comm=ktimersoftd/3 pid=35 prio=98 target_cpu=003
35748   irq/19-pcie215-7661  [005] d...213  7470.471859: sched_wakeup:
		comm=txrx pid=7683 prio=120 target_cpu=001
35749           txrx-7683  [001] d...313  7470.472163: sched_wakeup:
		comm=kworker/u16:3 pid=3444 prio=120 target_cpu=003
35750           txrx-7683  [001] d...313  7470.472270: sched_wakeup:
		comm=kworker/u16:1 pid=20072 prio=120 target_cpu=006
35751    kworker/u16:3-3444  [003] d...211  7470.472280: sched_wakeup:
		comm=mate-terminal pid=1465 prio=120 target_cpu=002
35752    mate-terminal-1465  [002] dN..2..  7470.472766: sched_wakeup:
		comm=ktimersoftd/2 pid=27 prio=98 target_cpu=002
35753           <idle>-0     [006] dN..3..  7470.472766: sched_wakeup:
		comm=ktimersoftd/6 pid=59 prio=98 target_cpu=006
(...)

it has been found that on the sample of 625 interrupts the worse
case latency for Comedi driver to wake up the sleeper on a blocking
call to read() was 80 microseconds (19.31 us on average).

wakeup latency (all in seconds)
Mean			0.000 019 31
Standard Error		3.127172298894E-007
Mode			0.000 016 000
Median			0.000 017 000
Variance		6.11200411685624E-011
Standard Deviation	0.000 007 818
Kurtosis		8.9662160643
Skewness		2.333413546
Range			0.000 070 000
Minimum			0.000 010 000
Maximum			0.000 080 000
Sum			0.012072
Count			625

Testing environment

cat /proc/cpuinfo
processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model	    : 94
model name  : Intel(R) Core(TM) i7-6700 CPU @ 3.40GHz
stepping    : 3
microcode   : 0xa0
cpu MHz	    : 799.929
cache size  : 8192 KB
physical id : 0
siblings    : 8
core id	    : 0
cpu cores   : 4
apicid	    : 0
initial apicid	: 0
fpu	: yes
fpu_exception	: yes
cpuid level : 22
wp	: yes
flags	    : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca
cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall
nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl
xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor
ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2
x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm
abm 3dnowprefetch ida arat pln pts dtherm hwp hwp_notify hwp_act_window
hwp_epp intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase
tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx rdseed adx smap
clflushopt xsaveopt xsavec xgetbv1
bugs	    :
bogomips    : 6812.95
clflush size	: 64
cache_alignment	: 64
address sizes	: 39 bits physical, 48 bits virtual
power management:
(...)

uname -a
Linux piotrpc 4.4.70-rt83 #1 SMP PREEMPT RT Thu Jul 13 08:42:02 BST 2017
x86_64 GNU/Linux

RAM: 8GB

Signed-off-by: Piotr Gregor <pgregor@quadrant-systems.co.uk>
---
 drivers/staging/comedi/drivers/Makefile            |  2 ++
 .../staging/comedi/drivers/amplc_dio200_common.c   |  5 +++
 drivers/staging/comedi/drivers/comedi-trace.h      | 42 ++++++++++++++++++++++
 3 files changed, 49 insertions(+)
 create mode 100644 drivers/staging/comedi/drivers/comedi-trace.h

diff --git a/drivers/staging/comedi/drivers/Makefile b/drivers/staging/comedi/drivers/Makefile
index 0c8cfa7..1511a064 100644
--- a/drivers/staging/comedi/drivers/Makefile
+++ b/drivers/staging/comedi/drivers/Makefile
@@ -143,5 +143,7 @@ obj-$(CONFIG_COMEDI_NI_LABPC_ISADMA)	+= ni_labpc_isadma.o
 obj-$(CONFIG_COMEDI_8255)		+= comedi_8255.o
 obj-$(CONFIG_COMEDI_8255_SA)		+= 8255.o
 obj-$(CONFIG_COMEDI_AMPLC_DIO200)	+= amplc_dio200_common.o
+CFLAGS_amplc_dio200_common.o = -I$(src)
+#EXTRA_CFLAGS = -I$(src)
 obj-$(CONFIG_COMEDI_AMPLC_PC236)	+= amplc_pc236_common.o
 obj-$(CONFIG_COMEDI_DAS08)		+= das08.o
diff --git a/drivers/staging/comedi/drivers/amplc_dio200_common.c b/drivers/staging/comedi/drivers/amplc_dio200_common.c
index f6e4e98..fa356db 100644
--- a/drivers/staging/comedi/drivers/amplc_dio200_common.c
+++ b/drivers/staging/comedi/drivers/amplc_dio200_common.c
@@ -28,6 +28,9 @@
 #include "comedi_8254.h"
 #include "8255.h"		/* only for register defines */
 
+#define CREATE_TRACE_POINTS
+#include "comedi-trace.h"
+
 /* 200 series registers */
 #define DIO200_IO_SIZE		0x20
 #define DIO200_PCIE_IO_SIZE	0x4000
@@ -482,8 +485,10 @@ static irqreturn_t dio200_interrupt(int irq, void *d)
 	struct comedi_subdevice *s = dev->read_subdev;
 	int handled;
 
+	trace_comedi_event(0);
 	if (!dev->attached)
 		return IRQ_NONE;
+	trace_comedi_event(1);
 
 	handled = dio200_handle_read_intr(dev, s);
 
diff --git a/drivers/staging/comedi/drivers/comedi-trace.h b/drivers/staging/comedi/drivers/comedi-trace.h
new file mode 100644
index 0000000..1fa0a19
--- /dev/null
+++ b/drivers/staging/comedi/drivers/comedi-trace.h
@@ -0,0 +1,42 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM comedi
+
+#if !defined(_TRACE_COMEDI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_COMEDI_H
+
+#include <linux/tracepoint.h>
+
+/*
+ * Tracepoint for calling from various places inside Comedi.
+ * Takes simple id and prints it to the trace log if trace
+ * events from Comedi are enabled.
+ *
+ * Currently following tracepoints are in use:
+ *
+ * Id : Description
+ * 0	Enter the interrupt of amplc_dio200_common
+ * 1	Called from same ISR of amplc_dio200_common if IRQ is handled
+ *
+ * If you would like to add new tracepoint just add a call to
+ *	trace_comedi_event(id)
+ * with id incremented.
+ */
+TRACE_EVENT(comedi_event,
+	TP_PROTO(__u8 id),
+	TP_ARGS(id),
+	TP_STRUCT__entry(
+			 __field(__u8, id)
+			),
+	TP_fast_assign(
+		       __entry->id = id;
+		       ),
+	TP_printk("[%u]", __entry->id)
+);
+
+#endif /* _TRACE_COMEDI_H */
+
+/* This part must be outside protection */
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE comedi-trace
+#include <trace/define_trace.h>
-- 
2.1.4

^ permalink raw reply related	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2017-07-20  8:36 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-07-19 11:30 [PATCH] drivers: staging: comedi: Add ftrace support Piotr Gregor
2017-07-19 11:38 ` Greg Kroah-Hartman
2017-07-19 13:25 ` Dan Carpenter
2017-07-19 21:05   ` Piotr Gregor
2017-07-20  8:35     ` Dan Carpenter
2017-07-19 13:57 Piotr Gregor
2017-07-19 14:21 ` Greg Kroah-Hartman
2017-07-19 15:28   ` Piotr Gregor

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.