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 <[email protected]>
---
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
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
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