[PATCH] drivers: staging: comedi: Add ftrace support

Piotr Gregor piotrgregor at rsyncme.org
Wed Jul 19 13:57:28 UTC 2017


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 at 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



More information about the devel mailing list