[RFC][PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[RFC][PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Wade Farnsworth]

Greetings,

We've found this patch helpful for making some simple performance measurements on 
V4L2 systems using the standard Linux tracers (FTRACE, LTTng, etc.), and were 
wondering if the larger community would find it useful to have this in mainline as 
well.

This patch adds two tracepoints for the VIDIOC_DQBUF and VIDIOC_QBUF ioctls.  We've 
identified two ways we can use this information to measure performance, though this  
is likely not an exhaustive list:

1. Measuring the difference in timestamps between QBUF events on a display device 
   provides a throughput (framerate) measurement for the display.
2. Measuring the difference between the timestamps on a DQBUF event for a capture 
   device and a corresponding timestamp on a QBUF event on a display device provides 
   a rough approximation of the latency of that particular frame.  However, this 
   tends to only work for simple video pipelines where captured and displayed 
   frames can be correlated in such a fashion.

Comments are welcome.  If there is interest, I'll post another patch suitable
for merge.

Signed-off-by: Wade Farnsworth <wade_farnsworth@mentor.com>
---
 drivers/media/v4l2-core/v4l2-dev.c |    9 ++++++
 include/trace/events/v4l2.h        |   48 ++++++++++++++++++++++++++++++++++++
 2 files changed, 57 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/v4l2.h

diff --git a/drivers/media/v4l2-core/v4l2-dev.c b/drivers/media/v4l2-core/v4l2-dev.c
index b5aaaac..1cc1749 100644
--- a/drivers/media/v4l2-core/v4l2-dev.c
+++ b/drivers/media/v4l2-core/v4l2-dev.c
@@ -31,6 +31,10 @@
 #include <media/v4l2-device.h>
 #include <media/v4l2-ioctl.h>
 
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/v4l2.h>
+
 #define VIDEO_NUM_DEVICES	256
 #define VIDEO_NAME              "video4linux"
 
@@ -391,6 +395,11 @@ static long v4l2_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
 	} else
 		ret = -ENOTTY;
 
+	if (cmd == VIDIOC_DQBUF)
+		trace_v4l2_dqbuf(vdev->minor, (struct v4l2_buffer *)arg);
+	else if (cmd == VIDIOC_QBUF)
+		trace_v4l2_qbuf(vdev->minor, (struct v4l2_buffer *)arg);
+
 	return ret;
 }
 
diff --git a/include/trace/events/v4l2.h b/include/trace/events/v4l2.h
new file mode 100644
index 0000000..1697441
--- /dev/null
+++ b/include/trace/events/v4l2.h
@@ -0,0 +1,48 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM v4l2
+
+#if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_V4L2_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(v4l2_dqbuf,
+	TP_PROTO(int minor, struct v4l2_buffer *buf),
+
+	TP_ARGS(minor, buf),
+
+	TP_STRUCT__entry(
+		__field(int, minor)
+		__field(s64, ts)
+	),
+
+	TP_fast_assign(
+		__entry->minor = minor;
+		__entry->ts = timeval_to_ns(&buf->timestamp);
+	),
+
+	TP_printk("%d [%lld]", __entry->minor, __entry->ts)
+);
+
+TRACE_EVENT(v4l2_qbuf,
+	TP_PROTO(int minor, struct v4l2_buffer *buf),
+
+	TP_ARGS(minor, buf),
+
+	TP_STRUCT__entry(
+		__field(int, minor)
+		__field(s64, ts)
+	),
+
+	TP_fast_assign(
+		__entry->minor = minor;
+		__entry->ts = timeval_to_ns(&buf->timestamp);
+	),
+
+	TP_printk("%d [%lld]", __entry->minor, __entry->ts)
+);
+
+#endif /* if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ) */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
1.7.0.4

Re: [RFC][PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Mauro Carvalho Chehab]

Hi Wade,

Em Fri, 18 Oct 2013 08:03:21 -0700
Wade Farnsworth <wade_farnsworth@mentor.com> escreveu:

> Greetings,
> 
> We've found this patch helpful for making some simple performance measurements on 
> V4L2 systems using the standard Linux tracers (FTRACE, LTTng, etc.), and were 
> wondering if the larger community would find it useful to have this in mainline as 
> well.
> 
> This patch adds two tracepoints for the VIDIOC_DQBUF and VIDIOC_QBUF ioctls.  We've 
> identified two ways we can use this information to measure performance, though this  
> is likely not an exhaustive list:
> 
> 1. Measuring the difference in timestamps between QBUF events on a display device 
>    provides a throughput (framerate) measurement for the display.
> 2. Measuring the difference between the timestamps on a DQBUF event for a capture 
>    device and a corresponding timestamp on a QBUF event on a display device provides 
>    a rough approximation of the latency of that particular frame.  However, this 
>    tends to only work for simple video pipelines where captured and displayed 
>    frames can be correlated in such a fashion.
> 
> Comments are welcome.  If there is interest, I'll post another patch suitable
> for merge.

I like the idea of adding those tracepoints.

See my comments below.

> 
> Signed-off-by: Wade Farnsworth <wade_farnsworth@mentor.com>
> ---
>  drivers/media/v4l2-core/v4l2-dev.c |    9 ++++++
>  include/trace/events/v4l2.h        |   48 ++++++++++++++++++++++++++++++++++++
>  2 files changed, 57 insertions(+), 0 deletions(-)
>  create mode 100644 include/trace/events/v4l2.h
> 
> diff --git a/drivers/media/v4l2-core/v4l2-dev.c b/drivers/media/v4l2-core/v4l2-dev.c
> index b5aaaac..1cc1749 100644
> --- a/drivers/media/v4l2-core/v4l2-dev.c
> +++ b/drivers/media/v4l2-core/v4l2-dev.c
> @@ -31,6 +31,10 @@
>  #include <media/v4l2-device.h>
>  #include <media/v4l2-ioctl.h>
>  
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/v4l2.h>
> +
>  #define VIDEO_NUM_DEVICES	256
>  #define VIDEO_NAME              "video4linux"
>  
> @@ -391,6 +395,11 @@ static long v4l2_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
>  	} else
>  		ret = -ENOTTY;
>  
> +	if (cmd == VIDIOC_DQBUF)
> +		trace_v4l2_dqbuf(vdev->minor, (struct v4l2_buffer *)arg);
> +	else if (cmd == VIDIOC_QBUF)
> +		trace_v4l2_qbuf(vdev->minor, (struct v4l2_buffer *)arg);
> +
>  	return ret;
>  }
>  
> diff --git a/include/trace/events/v4l2.h b/include/trace/events/v4l2.h
> new file mode 100644
> index 0000000..1697441
> --- /dev/null
> +++ b/include/trace/events/v4l2.h
> @@ -0,0 +1,48 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM v4l2
> +
> +#if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_V4L2_H
> +
> +#include <linux/tracepoint.h>
> +
> +TRACE_EVENT(v4l2_dqbuf,
> +	TP_PROTO(int minor, struct v4l2_buffer *buf),
> +
> +	TP_ARGS(minor, buf),
> +
> +	TP_STRUCT__entry(
> +		__field(int, minor)
> +		__field(s64, ts)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->minor = minor;
> +		__entry->ts = timeval_to_ns(&buf->timestamp);
> +	),
> +
> +	TP_printk("%d [%lld]", __entry->minor, __entry->ts)
> +);
> +
> +TRACE_EVENT(v4l2_qbuf,
> +	TP_PROTO(int minor, struct v4l2_buffer *buf),
> +
> +	TP_ARGS(minor, buf),
> +
> +	TP_STRUCT__entry(
> +		__field(int, minor)
> +		__field(s64, ts)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->minor = minor;
> +		__entry->ts = timeval_to_ns(&buf->timestamp);

On both events, you're only decoding the buffer timestamp. I think you
should also decode the other metadata there. For example, on some devices,
the dqbuf order is different than the qbuf one. One may need to associate
both, in order to be able to time how much time a buffer takes to be
filled.

> +	),
> +
> +	TP_printk("%d [%lld]", __entry->minor, __entry->ts)
> +);
> +
> +#endif /* if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ) */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>


-- 

Cheers,
Mauro

[PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Wade Farnsworth]

Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
performance measurements using standard kernel tracers.

Signed-off-by: Wade Farnsworth <wade_farnsworth@mentor.com>
---

This is the update to the RFC patch I posted a few weeks back.  I've added 
several bits of metadata to the tracepoint output per Mauro's suggestion.

 drivers/media/v4l2-core/v4l2-dev.c |    9 ++
 include/trace/events/v4l2.h        |  157 ++++++++++++++++++++++++++++++++++++
 2 files changed, 166 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/v4l2.h

diff --git a/drivers/media/v4l2-core/v4l2-dev.c b/drivers/media/v4l2-core/v4l2-dev.c
index b5aaaac..1cc1749 100644
--- a/drivers/media/v4l2-core/v4l2-dev.c
+++ b/drivers/media/v4l2-core/v4l2-dev.c
@@ -31,6 +31,10 @@
 #include <media/v4l2-device.h>
 #include <media/v4l2-ioctl.h>
 
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/v4l2.h>
+
 #define VIDEO_NUM_DEVICES	256
 #define VIDEO_NAME              "video4linux"
 
@@ -391,6 +395,11 @@ static long v4l2_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
 	} else
 		ret = -ENOTTY;
 
+	if (cmd == VIDIOC_DQBUF)
+		trace_v4l2_dqbuf(vdev->minor, (struct v4l2_buffer *)arg);
+	else if (cmd == VIDIOC_QBUF)
+		trace_v4l2_qbuf(vdev->minor, (struct v4l2_buffer *)arg);
+
 	return ret;
 }
 
diff --git a/include/trace/events/v4l2.h b/include/trace/events/v4l2.h
new file mode 100644
index 0000000..0b7d6cb
--- /dev/null
+++ b/include/trace/events/v4l2.h
@@ -0,0 +1,157 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM v4l2
+
+#if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_V4L2_H
+
+#include <linux/tracepoint.h>
+
+#define show_type(type)							       \
+	__print_symbolic(type,						       \
+		{ V4L2_BUF_TYPE_VIDEO_CAPTURE,	      "VIDEO_CAPTURE" },       \
+		{ V4L2_BUF_TYPE_VIDEO_OUTPUT,	      "VIDEO_OUTPUT" },	       \
+		{ V4L2_BUF_TYPE_VIDEO_OVERLAY,	      "VIDEO_OVERLAY" },       \
+		{ V4L2_BUF_TYPE_VBI_CAPTURE,	      "VBI_CAPTURE" },	       \
+		{ V4L2_BUF_TYPE_VBI_OUTPUT,	      "VBI_OUTPUT" },	       \
+		{ V4L2_BUF_TYPE_SLICED_VBI_CAPTURE,   "SLICED_VBI_CAPTURE" },  \
+		{ V4L2_BUF_TYPE_SLICED_VBI_OUTPUT,    "SLICED_VBI_OUTPUT" },   \
+		{ V4L2_BUF_TYPE_VIDEO_OUTPUT_OVERLAY, "VIDEO_OUTPUT_OVERLAY" },\
+		{ V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE, "VIDEO_CAPTURE_MPLANE" },\
+		{ V4L2_BUF_TYPE_VIDEO_OUTPUT_MPLANE,  "VIDEO_OUTPUT_MPLANE" }, \
+		{ V4L2_BUF_TYPE_PRIVATE,	      "PRIVATE" })
+
+#define show_field(field)						\
+	__print_symbolic(field,						\
+		{ V4L2_FIELD_ANY,		"ANY" },		\
+		{ V4L2_FIELD_NONE,		"NONE" },		\
+		{ V4L2_FIELD_TOP,		"TOP" },		\
+		{ V4L2_FIELD_BOTTOM,		"BOTTOM" },		\
+		{ V4L2_FIELD_INTERLACED,	"INTERLACED" },		\
+		{ V4L2_FIELD_SEQ_TB,		"SEQ_TB" },		\
+		{ V4L2_FIELD_SEQ_BT,		"SEQ_BT" },		\
+		{ V4L2_FIELD_ALTERNATE,		"ALTERNATE" },		\
+		{ V4L2_FIELD_INTERLACED_TB,	"INTERLACED_TB" },      \
+		{ V4L2_FIELD_INTERLACED_BT,	"INTERLACED_BT" })
+
+#define show_timecode_type(type)					\
+	__print_symbolic(type,						\
+		{ V4L2_TC_TYPE_24FPS,		"24FPS" },		\
+		{ V4L2_TC_TYPE_25FPS,		"25FPS" },		\
+		{ V4L2_TC_TYPE_30FPS,		"30FPS" },		\
+		{ V4L2_TC_TYPE_50FPS,		"50FPS" },		\
+		{ V4L2_TC_TYPE_60FPS,		"60FPS" })
+
+#define show_flags(flags)						      \
+	__print_flags(flags, "|",					      \
+		{ V4L2_BUF_FLAG_MAPPED,		     "MAPPED" },	      \
+		{ V4L2_BUF_FLAG_QUEUED,		     "QUEUED" },	      \
+		{ V4L2_BUF_FLAG_DONE,		     "DONE" },		      \
+		{ V4L2_BUF_FLAG_KEYFRAME,	     "KEYFRAME" },	      \
+		{ V4L2_BUF_FLAG_PFRAME,		     "PFRAME" },	      \
+		{ V4L2_BUF_FLAG_BFRAME,		     "BFRAME" },	      \
+		{ V4L2_BUF_FLAG_ERROR,		     "ERROR" },		      \
+		{ V4L2_BUF_FLAG_TIMECODE,	     "TIMECODE" },	      \
+		{ V4L2_BUF_FLAG_PREPARED,	     "PREPARED" },	      \
+		{ V4L2_BUF_FLAG_NO_CACHE_INVALIDATE, "NO_CACHE_INVALIDATE" }, \
+		{ V4L2_BUF_FLAG_NO_CACHE_CLEAN,	     "NO_CACHE_CLEAN" },      \
+		{ V4L2_BUF_FLAG_TIMESTAMP_MASK,	     "TIMESTAMP_MASK" },      \
+		{ V4L2_BUF_FLAG_TIMESTAMP_UNKNOWN,   "TIMESTAMP_UNKNOWN" },   \
+		{ V4L2_BUF_FLAG_TIMESTAMP_MONOTONIC, "TIMESTAMP_MONOTONIC" }, \
+		{ V4L2_BUF_FLAG_TIMESTAMP_COPY,	     "TIMESTAMP_COPY" })
+
+#define show_timecode_flags(flags)				          \
+	__print_flags(flags, "|",				          \
+		{ V4L2_TC_FLAG_DROPFRAME,       "DROPFRAME" },		  \
+		{ V4L2_TC_FLAG_COLORFRAME,      "COLORFRAME" },      	  \
+		{ V4L2_TC_USERBITS_USERDEFINED,	"USERBITS_USERDEFINED" }, \
+		{ V4L2_TC_USERBITS_8BITCHARS,	"USERBITS_8BITCHARS" })
+
+#define V4L2_TRACE_EVENT(event_name)					\
+	TRACE_EVENT(event_name,						\
+		TP_PROTO(int minor, struct v4l2_buffer *buf),		\
+									\
+		TP_ARGS(minor, buf),					\
+									\
+		TP_STRUCT__entry(					\
+			__field(int, minor)				\
+			__field(u32, index)				\
+			__field(u32, type)				\
+			__field(u32, bytesused)				\
+			__field(u32, flags)				\
+			__field(u32, field)				\
+			__field(s64, timestamp)				\
+			__field(u32, timecode_type)			\
+			__field(u32, timecode_flags)			\
+			__field(u8, timecode_frames)			\
+			__field(u8, timecode_seconds)			\
+			__field(u8, timecode_minutes)			\
+			__field(u8, timecode_hours)			\
+			__field(u8, timecode_userbits0)			\
+			__field(u8, timecode_userbits1)			\
+			__field(u8, timecode_userbits2)			\
+			__field(u8, timecode_userbits3)			\
+			__field(u32, sequence)				\
+		),							\
+									\
+		TP_fast_assign(						\
+			__entry->minor = minor;				\
+			__entry->index = buf->index;			\
+			__entry->type = buf->type;			\
+			__entry->bytesused = buf->bytesused;		\
+			__entry->flags = buf->flags;			\
+			__entry->field = buf->field;			\
+			__entry->timestamp =				\
+				timeval_to_ns(&buf->timestamp);		\
+			__entry->timecode_type = buf->timecode.type;	\
+			__entry->timecode_flags = buf->timecode.flags;	\
+			__entry->timecode_frames =			\
+				buf->timecode.frames;			\
+			__entry->timecode_seconds =			\
+				buf->timecode.seconds;			\
+			__entry->timecode_minutes =			\
+				buf->timecode.minutes;			\
+			__entry->timecode_hours = buf->timecode.hours;	\
+			__entry->timecode_userbits0 =			\
+				buf->timecode.userbits[0];		\
+			__entry->timecode_userbits1 =			\
+				buf->timecode.userbits[1];		\
+			__entry->timecode_userbits2 =			\
+				buf->timecode.userbits[2];		\
+			__entry->timecode_userbits3 =			\
+				buf->timecode.userbits[3];		\
+			__entry->sequence = buf->sequence;		\
+		),							\
+									\
+		TP_printk("minor = %d, index = %u, type = %s, "		\
+			  "bytesused = %u, flags = %s, "		\
+			  "field = %s, timestamp = %llu, timecode = { "	\
+			  "type = %s, flags = %s, frames = %u, "	\
+			  "seconds = %u, minutes = %u, hours = %u, "	\
+			  "userbits = { %u %u %u %u } }, "		\
+			  "sequence = %u", __entry->minor, 		\
+			  __entry->index, show_type(__entry->type), 	\
+			  __entry->bytesused,				\
+			  show_flags(__entry->flags), 			\
+			  show_field(__entry->field),			\
+			  __entry->timestamp,				\
+			  show_timecode_type(__entry->timecode_type),	\
+			  show_timecode_flags(__entry->timecode_flags),	\
+			  __entry->timecode_frames,			\
+			  __entry->timecode_seconds,			\
+			  __entry->timecode_minutes,			\
+			  __entry->timecode_hours,			\
+			  __entry->timecode_userbits0,			\
+			  __entry->timecode_userbits1,			\
+			  __entry->timecode_userbits2,			\
+			  __entry->timecode_userbits3,			\
+			  __entry->sequence				\
+		)							\
+	)
+
+V4L2_TRACE_EVENT(v4l2_dqbuf);
+V4L2_TRACE_EVENT(v4l2_qbuf);
+
+#endif /* if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ) */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
1.7.0.4

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Hans Verkuil]

Hi Wade,

On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
> performance measurements using standard kernel tracers.
> 
> Signed-off-by: Wade Farnsworth <wade_farnsworth@mentor.com>
> ---
> 
> This is the update to the RFC patch I posted a few weeks back.  I've added 
> several bits of metadata to the tracepoint output per Mauro's suggestion.

I don't like this. All v4l2 ioctls can already be traced by doing e.g.
echo 1 (or echo 2) >/sys/class/video4linux/video0/debug.

So this code basically duplicates that functionality. It would be nice to be able
to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.

Regards,

	Hans

> 
>  drivers/media/v4l2-core/v4l2-dev.c |    9 ++
>  include/trace/events/v4l2.h        |  157 ++++++++++++++++++++++++++++++++++++
>  2 files changed, 166 insertions(+), 0 deletions(-)
>  create mode 100644 include/trace/events/v4l2.h
> 
> diff --git a/drivers/media/v4l2-core/v4l2-dev.c b/drivers/media/v4l2-core/v4l2-dev.c
> index b5aaaac..1cc1749 100644
> --- a/drivers/media/v4l2-core/v4l2-dev.c
> +++ b/drivers/media/v4l2-core/v4l2-dev.c
> @@ -31,6 +31,10 @@
>  #include <media/v4l2-device.h>
>  #include <media/v4l2-ioctl.h>
>  
> +
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/v4l2.h>
> +
>  #define VIDEO_NUM_DEVICES	256
>  #define VIDEO_NAME              "video4linux"
>  
> @@ -391,6 +395,11 @@ static long v4l2_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
>  	} else
>  		ret = -ENOTTY;
>  
> +	if (cmd == VIDIOC_DQBUF)
> +		trace_v4l2_dqbuf(vdev->minor, (struct v4l2_buffer *)arg);
> +	else if (cmd == VIDIOC_QBUF)
> +		trace_v4l2_qbuf(vdev->minor, (struct v4l2_buffer *)arg);
> +
>  	return ret;
>  }
>  
> diff --git a/include/trace/events/v4l2.h b/include/trace/events/v4l2.h
> new file mode 100644
> index 0000000..0b7d6cb
> --- /dev/null
> +++ b/include/trace/events/v4l2.h
> @@ -0,0 +1,157 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM v4l2
> +
> +#if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_V4L2_H
> +
> +#include <linux/tracepoint.h>
> +
> +#define show_type(type)							       \
> +	__print_symbolic(type,						       \
> +		{ V4L2_BUF_TYPE_VIDEO_CAPTURE,	      "VIDEO_CAPTURE" },       \
> +		{ V4L2_BUF_TYPE_VIDEO_OUTPUT,	      "VIDEO_OUTPUT" },	       \
> +		{ V4L2_BUF_TYPE_VIDEO_OVERLAY,	      "VIDEO_OVERLAY" },       \
> +		{ V4L2_BUF_TYPE_VBI_CAPTURE,	      "VBI_CAPTURE" },	       \
> +		{ V4L2_BUF_TYPE_VBI_OUTPUT,	      "VBI_OUTPUT" },	       \
> +		{ V4L2_BUF_TYPE_SLICED_VBI_CAPTURE,   "SLICED_VBI_CAPTURE" },  \
> +		{ V4L2_BUF_TYPE_SLICED_VBI_OUTPUT,    "SLICED_VBI_OUTPUT" },   \
> +		{ V4L2_BUF_TYPE_VIDEO_OUTPUT_OVERLAY, "VIDEO_OUTPUT_OVERLAY" },\
> +		{ V4L2_BUF_TYPE_VIDEO_CAPTURE_MPLANE, "VIDEO_CAPTURE_MPLANE" },\
> +		{ V4L2_BUF_TYPE_VIDEO_OUTPUT_MPLANE,  "VIDEO_OUTPUT_MPLANE" }, \
> +		{ V4L2_BUF_TYPE_PRIVATE,	      "PRIVATE" })
> +
> +#define show_field(field)						\
> +	__print_symbolic(field,						\
> +		{ V4L2_FIELD_ANY,		"ANY" },		\
> +		{ V4L2_FIELD_NONE,		"NONE" },		\
> +		{ V4L2_FIELD_TOP,		"TOP" },		\
> +		{ V4L2_FIELD_BOTTOM,		"BOTTOM" },		\
> +		{ V4L2_FIELD_INTERLACED,	"INTERLACED" },		\
> +		{ V4L2_FIELD_SEQ_TB,		"SEQ_TB" },		\
> +		{ V4L2_FIELD_SEQ_BT,		"SEQ_BT" },		\
> +		{ V4L2_FIELD_ALTERNATE,		"ALTERNATE" },		\
> +		{ V4L2_FIELD_INTERLACED_TB,	"INTERLACED_TB" },      \
> +		{ V4L2_FIELD_INTERLACED_BT,	"INTERLACED_BT" })
> +
> +#define show_timecode_type(type)					\
> +	__print_symbolic(type,						\
> +		{ V4L2_TC_TYPE_24FPS,		"24FPS" },		\
> +		{ V4L2_TC_TYPE_25FPS,		"25FPS" },		\
> +		{ V4L2_TC_TYPE_30FPS,		"30FPS" },		\
> +		{ V4L2_TC_TYPE_50FPS,		"50FPS" },		\
> +		{ V4L2_TC_TYPE_60FPS,		"60FPS" })
> +
> +#define show_flags(flags)						      \
> +	__print_flags(flags, "|",					      \
> +		{ V4L2_BUF_FLAG_MAPPED,		     "MAPPED" },	      \
> +		{ V4L2_BUF_FLAG_QUEUED,		     "QUEUED" },	      \
> +		{ V4L2_BUF_FLAG_DONE,		     "DONE" },		      \
> +		{ V4L2_BUF_FLAG_KEYFRAME,	     "KEYFRAME" },	      \
> +		{ V4L2_BUF_FLAG_PFRAME,		     "PFRAME" },	      \
> +		{ V4L2_BUF_FLAG_BFRAME,		     "BFRAME" },	      \
> +		{ V4L2_BUF_FLAG_ERROR,		     "ERROR" },		      \
> +		{ V4L2_BUF_FLAG_TIMECODE,	     "TIMECODE" },	      \
> +		{ V4L2_BUF_FLAG_PREPARED,	     "PREPARED" },	      \
> +		{ V4L2_BUF_FLAG_NO_CACHE_INVALIDATE, "NO_CACHE_INVALIDATE" }, \
> +		{ V4L2_BUF_FLAG_NO_CACHE_CLEAN,	     "NO_CACHE_CLEAN" },      \
> +		{ V4L2_BUF_FLAG_TIMESTAMP_MASK,	     "TIMESTAMP_MASK" },      \
> +		{ V4L2_BUF_FLAG_TIMESTAMP_UNKNOWN,   "TIMESTAMP_UNKNOWN" },   \
> +		{ V4L2_BUF_FLAG_TIMESTAMP_MONOTONIC, "TIMESTAMP_MONOTONIC" }, \
> +		{ V4L2_BUF_FLAG_TIMESTAMP_COPY,	     "TIMESTAMP_COPY" })
> +
> +#define show_timecode_flags(flags)				          \
> +	__print_flags(flags, "|",				          \
> +		{ V4L2_TC_FLAG_DROPFRAME,       "DROPFRAME" },		  \
> +		{ V4L2_TC_FLAG_COLORFRAME,      "COLORFRAME" },      	  \
> +		{ V4L2_TC_USERBITS_USERDEFINED,	"USERBITS_USERDEFINED" }, \
> +		{ V4L2_TC_USERBITS_8BITCHARS,	"USERBITS_8BITCHARS" })
> +
> +#define V4L2_TRACE_EVENT(event_name)					\
> +	TRACE_EVENT(event_name,						\
> +		TP_PROTO(int minor, struct v4l2_buffer *buf),		\
> +									\
> +		TP_ARGS(minor, buf),					\
> +									\
> +		TP_STRUCT__entry(					\
> +			__field(int, minor)				\
> +			__field(u32, index)				\
> +			__field(u32, type)				\
> +			__field(u32, bytesused)				\
> +			__field(u32, flags)				\
> +			__field(u32, field)				\
> +			__field(s64, timestamp)				\
> +			__field(u32, timecode_type)			\
> +			__field(u32, timecode_flags)			\
> +			__field(u8, timecode_frames)			\
> +			__field(u8, timecode_seconds)			\
> +			__field(u8, timecode_minutes)			\
> +			__field(u8, timecode_hours)			\
> +			__field(u8, timecode_userbits0)			\
> +			__field(u8, timecode_userbits1)			\
> +			__field(u8, timecode_userbits2)			\
> +			__field(u8, timecode_userbits3)			\
> +			__field(u32, sequence)				\
> +		),							\
> +									\
> +		TP_fast_assign(						\
> +			__entry->minor = minor;				\
> +			__entry->index = buf->index;			\
> +			__entry->type = buf->type;			\
> +			__entry->bytesused = buf->bytesused;		\
> +			__entry->flags = buf->flags;			\
> +			__entry->field = buf->field;			\
> +			__entry->timestamp =				\
> +				timeval_to_ns(&buf->timestamp);		\
> +			__entry->timecode_type = buf->timecode.type;	\
> +			__entry->timecode_flags = buf->timecode.flags;	\
> +			__entry->timecode_frames =			\
> +				buf->timecode.frames;			\
> +			__entry->timecode_seconds =			\
> +				buf->timecode.seconds;			\
> +			__entry->timecode_minutes =			\
> +				buf->timecode.minutes;			\
> +			__entry->timecode_hours = buf->timecode.hours;	\
> +			__entry->timecode_userbits0 =			\
> +				buf->timecode.userbits[0];		\
> +			__entry->timecode_userbits1 =			\
> +				buf->timecode.userbits[1];		\
> +			__entry->timecode_userbits2 =			\
> +				buf->timecode.userbits[2];		\
> +			__entry->timecode_userbits3 =			\
> +				buf->timecode.userbits[3];		\
> +			__entry->sequence = buf->sequence;		\
> +		),							\
> +									\
> +		TP_printk("minor = %d, index = %u, type = %s, "		\
> +			  "bytesused = %u, flags = %s, "		\
> +			  "field = %s, timestamp = %llu, timecode = { "	\
> +			  "type = %s, flags = %s, frames = %u, "	\
> +			  "seconds = %u, minutes = %u, hours = %u, "	\
> +			  "userbits = { %u %u %u %u } }, "		\
> +			  "sequence = %u", __entry->minor, 		\
> +			  __entry->index, show_type(__entry->type), 	\
> +			  __entry->bytesused,				\
> +			  show_flags(__entry->flags), 			\
> +			  show_field(__entry->field),			\
> +			  __entry->timestamp,				\
> +			  show_timecode_type(__entry->timecode_type),	\
> +			  show_timecode_flags(__entry->timecode_flags),	\
> +			  __entry->timecode_frames,			\
> +			  __entry->timecode_seconds,			\
> +			  __entry->timecode_minutes,			\
> +			  __entry->timecode_hours,			\
> +			  __entry->timecode_userbits0,			\
> +			  __entry->timecode_userbits1,			\
> +			  __entry->timecode_userbits2,			\
> +			  __entry->timecode_userbits3,			\
> +			  __entry->sequence				\
> +		)							\
> +	)
> +
> +V4L2_TRACE_EVENT(v4l2_dqbuf);
> +V4L2_TRACE_EVENT(v4l2_qbuf);
> +
> +#endif /* if !defined(_TRACE_V4L2_H) || defined(TRACE_HEADER_MULTI_READ) */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> 

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Sylwester Nawrocki]

Hi,

On 11/23/2013 12:25 PM, Hans Verkuil wrote:
> Hi Wade,
>
> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>> performance measurements using standard kernel tracers.
>>
>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>> ---
>>
>> This is the update to the RFC patch I posted a few weeks back.  I've added
>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>
> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>
> So this code basically duplicates that functionality. It would be nice to be able
> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.

I think it would be really nice to have this kind of support for standard
traces at the v4l2 subsystem. Presumably it could even gradually replace
the v4l2 custom debug infrastructure.

If I understand things correctly, the current tracing/profiling 
infrastructure
is much less invasive than inserting printks all over, which may cause 
changes
in control flow. I doubt the system could be reliably profiled by 
enabling all
those debug prints.

So my vote would be to add support for standard tracers, like in other
subsystems in the kernel.

--
Regards,
Sylwester

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Hans Verkuil]

On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
> Hi,
> 
> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>> Hi Wade,
>>
>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>> performance measurements using standard kernel tracers.
>>>
>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>> ---
>>>
>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>
>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>
>> So this code basically duplicates that functionality. It would be nice to be able
>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
> 
> I think it would be really nice to have this kind of support for standard
> traces at the v4l2 subsystem. Presumably it could even gradually replace
> the v4l2 custom debug infrastructure.
> 
> If I understand things correctly, the current tracing/profiling 
> infrastructure
> is much less invasive than inserting printks all over, which may cause 
> changes
> in control flow. I doubt the system could be reliably profiled by 
> enabling all
> those debug prints.
> 
> So my vote would be to add support for standard tracers, like in other
> subsystems in the kernel.

The reason for the current system is to trace which ioctls are called in
what order by a misbehaving application. It's very useful for that,
especially when trying to debug user problems.

I don't mind switching to tracepoints as long as this functionality is
kept one way or another.

Regards,

	Hans

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Mauro Carvalho Chehab]

Em Sat, 23 Nov 2013 17:54:48 +0100
Hans Verkuil <hverkuil@xs4all.nl> escreveu:

> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
> > Hi,
> > 
> > On 11/23/2013 12:25 PM, Hans Verkuil wrote:
> >> Hi Wade,
> >>
> >> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
> >>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
> >>> performance measurements using standard kernel tracers.
> >>>
> >>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
> >>> ---
> >>>
> >>> This is the update to the RFC patch I posted a few weeks back.  I've added
> >>> several bits of metadata to the tracepoint output per Mauro's suggestion.
> >>
> >> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
> >> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
> >>
> >> So this code basically duplicates that functionality. It would be nice to be able
> >> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
> > 
> > I think it would be really nice to have this kind of support for standard
> > traces at the v4l2 subsystem. Presumably it could even gradually replace
> > the v4l2 custom debug infrastructure.
> > 
> > If I understand things correctly, the current tracing/profiling 
> > infrastructure
> > is much less invasive than inserting printks all over, which may cause 
> > changes
> > in control flow. I doubt the system could be reliably profiled by 
> > enabling all
> > those debug prints.
> > 
> > So my vote would be to add support for standard tracers, like in other
> > subsystems in the kernel.
> 
> The reason for the current system is to trace which ioctls are called in
> what order by a misbehaving application. It's very useful for that,
> especially when trying to debug user problems.
> 
> I don't mind switching to tracepoints as long as this functionality is
> kept one way or another.

I agree with Sylwester: we should move to tracepoints, and this is a good
start.

Regards,
Mauro

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Hans Verkuil]

On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
> Em Sat, 23 Nov 2013 17:54:48 +0100
> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> 
>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
>>> Hi,
>>>
>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>>>> Hi Wade,
>>>>
>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>>>> performance measurements using standard kernel tracers.
>>>>>
>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>>>> ---
>>>>>
>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>>>
>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>>>
>>>> So this code basically duplicates that functionality. It would be nice to be able
>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
>>>
>>> I think it would be really nice to have this kind of support for standard
>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
>>> the v4l2 custom debug infrastructure.
>>>
>>> If I understand things correctly, the current tracing/profiling 
>>> infrastructure
>>> is much less invasive than inserting printks all over, which may cause 
>>> changes
>>> in control flow. I doubt the system could be reliably profiled by 
>>> enabling all
>>> those debug prints.
>>>
>>> So my vote would be to add support for standard tracers, like in other
>>> subsystems in the kernel.
>>
>> The reason for the current system is to trace which ioctls are called in
>> what order by a misbehaving application. It's very useful for that,
>> especially when trying to debug user problems.
>>
>> I don't mind switching to tracepoints as long as this functionality is
>> kept one way or another.
> 
> I agree with Sylwester: we should move to tracepoints, and this is a good
> start.

As I mentioned, I don't mind switching to tracepoints, but not in the way the
current patch does it. I certainly don't agree with you merging this patch
as-is without further discussion.

To make it official:

Nacked-by: Hans Verkuil <hans.verkuil@cisco.com>

If we do tracepoints, then we do it right and for all ioctls, not in this
half-baked manner.

Please revert.

Regards,

	Hans

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Mauro Carvalho Chehab]

Hans,

Em Wed, 11 Dec 2013 08:29:58 +0100
Hans Verkuil <hverkuil@xs4all.nl> escreveu:

> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
> > Em Sat, 23 Nov 2013 17:54:48 +0100
> > Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> > 
> >> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
> >>> Hi,
> >>>
> >>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
> >>>> Hi Wade,
> >>>>
> >>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
> >>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
> >>>>> performance measurements using standard kernel tracers.
> >>>>>
> >>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
> >>>>> ---
> >>>>>
> >>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
> >>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
> >>>>
> >>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
> >>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
> >>>>
> >>>> So this code basically duplicates that functionality. It would be nice to be able
> >>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
> >>>
> >>> I think it would be really nice to have this kind of support for standard
> >>> traces at the v4l2 subsystem. Presumably it could even gradually replace
> >>> the v4l2 custom debug infrastructure.
> >>>
> >>> If I understand things correctly, the current tracing/profiling 
> >>> infrastructure
> >>> is much less invasive than inserting printks all over, which may cause 
> >>> changes
> >>> in control flow. I doubt the system could be reliably profiled by 
> >>> enabling all
> >>> those debug prints.
> >>>
> >>> So my vote would be to add support for standard tracers, like in other
> >>> subsystems in the kernel.
> >>
> >> The reason for the current system is to trace which ioctls are called in
> >> what order by a misbehaving application. It's very useful for that,
> >> especially when trying to debug user problems.
> >>
> >> I don't mind switching to tracepoints as long as this functionality is
> >> kept one way or another.
> > 
> > I agree with Sylwester: we should move to tracepoints, and this is a good
> > start.
> 
> As I mentioned, I don't mind switching to tracepoints, but not in the way the
> current patch does it. I certainly don't agree with you merging this patch
> as-is without further discussion.

Let's not mix the subjects here. There are two different demands that can be
either fulfilled by the same solution or by different ones:
	1) To have a way to enable debugging all parameters passed from/to
userspace;
	2) To be able to measure the driver (and core) performance while
streaming.

This patch's scope is to solve (2), by allowing userspace to hook the two
ioctls that queues/dequeues streaming buffers.

With that regards, what's wrong on this patch? I couldn't see anything bad
there. It is not meant to solve (1).

Before this patch, all we have is (1), as a non-dynamic printk is too
intrusive to be used for performance measurement. So, there's no way to
measure how much time a buffer takes to be filled.

In a matter of fact, in the case you didn't noticed, we are already somewhat
moving to traces, as several drivers are now using dynamic_printk for debug 
messages, Yet, lots of drivers still use either their own normal
printk-based debug macros.

Now, you're proposing to use the same solution for (1) too. 

Ok, we can go on that direction, but this is a separate issue. Converting
the v4l2-ioctl to use tracepoints is the easiest part. However, there are
several things to consider, if we decide to use it for debug purposes:

a) It will likely require to convert all printks to dynamic ones, as we
want to have all debug messages serialized.

Let me explain it better: if some debug messages come via the standard 
printk mechanism while others come via traces, we loose the capability
of receiving the messages at the same order that they were produced, and
it could be harder if not impossible to synchronize them into the right
order.

b) It may make sense to write an userspace tool similar to the rasdaemon
[1] to allow controlling the debug output. That tool directly reads the
events from the raw tracing queues, formatting the data on userspace and
hooking only the events that are needed. 

Currently, the rasdaemon has inside part of the code used by a perf
tool copied on it (as this code is not inside any library yet). However,
that code is being prepared to be used as a library. So, it should be
even easier to write such tool in a near future.

[1] https://git.fedorahosted.org/cgit/rasdaemon.git/

c) I don't think that tracepoints are the right mechanism for a post-mortem
analysis[2]. E. g. if the Kernel crashes, a printk-based mechanism will 
output something, but I'm not sure if doing the same is possible with traces
(e. g. forcing the trace messages to go to to tty).

You should notice that, with the dynamic_printk macros, it is possible to
compile the Kernel to use normal printk macros for debug macros.

However, if we convert the ioctl printk's to tracepoints, we may still
need to have a fallback printk mechanism for ioctl debug messages.

[2] There are actually some discussions at the RAS mailing lists about
how to store the tracing data and printk messages on newer hardware that
offer a non-volatile memory mechanism for that. So, we might actually
have a post-mortem mechanism for tracepoints in the future, depending on
the hardware. Yet, not all types of hardware will have such NVRAM.

Btw, it is possible to use strace to trace all ioctl's. So, the existing
mechanism is actually a duplicated feature, as userspace already covers it.
However, in practice, we opted to explicitly duplicate that feature at
Kernel level, for debugging purposes, because strace doesn't solve (a)
and (c).

What I'm saying is that a project to convert the debug facility into
tracepoints is something that:
	- it is independent of adding some facility for performance 
	  measurement (although it may share the same infrastructure);

	- it will require lots of effort to change every single driver
	  to use dynamic printk's;

	- it may require writing a helper tool to enable just the v4l2
	  traces and eventually collect them;

	- it may require a fallback printk mechanism in order to debug
	  kernel panic.

> To make it official:
> 
> Nacked-by: Hans Verkuil <hans.verkuil@cisco.com>
> 
> If we do tracepoints, then we do it right and for all ioctls, not in this
> half-baked manner.
> 
> Please revert.

Let's not mix things. If this patch is correct and solves for performance
measurement, I don't see any reason to revert.

Using tracepoints for debug is a separate and independent project.

Such project require lots of tests to proof that it is a viable solution,
several discussions and a huge time frame to convert all drivers to use
tracepoints too, plus some post-mortem debug logic.

Regards,
Mauro

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Hans Verkuil]

Hi Mauro,

On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
> Hans,
> 
> Em Wed, 11 Dec 2013 08:29:58 +0100
> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> 
>> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
>>> Em Sat, 23 Nov 2013 17:54:48 +0100
>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>
>>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
>>>>> Hi,
>>>>>
>>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>>>>>> Hi Wade,
>>>>>>
>>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>>>>>> performance measurements using standard kernel tracers.
>>>>>>>
>>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>>>>>> ---
>>>>>>>
>>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>>>>>
>>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>>>>>
>>>>>> So this code basically duplicates that functionality. It would be nice to be able
>>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
>>>>>
>>>>> I think it would be really nice to have this kind of support for standard
>>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
>>>>> the v4l2 custom debug infrastructure.
>>>>>
>>>>> If I understand things correctly, the current tracing/profiling 
>>>>> infrastructure
>>>>> is much less invasive than inserting printks all over, which may cause 
>>>>> changes
>>>>> in control flow. I doubt the system could be reliably profiled by 
>>>>> enabling all
>>>>> those debug prints.
>>>>>
>>>>> So my vote would be to add support for standard tracers, like in other
>>>>> subsystems in the kernel.
>>>>
>>>> The reason for the current system is to trace which ioctls are called in
>>>> what order by a misbehaving application. It's very useful for that,
>>>> especially when trying to debug user problems.
>>>>
>>>> I don't mind switching to tracepoints as long as this functionality is
>>>> kept one way or another.
>>>
>>> I agree with Sylwester: we should move to tracepoints, and this is a good
>>> start.
>>
>> As I mentioned, I don't mind switching to tracepoints, but not in the way the
>> current patch does it. I certainly don't agree with you merging this patch
>> as-is without further discussion.
> 
> Let's not mix the subjects here. There are two different demands that can be
> either fulfilled by the same solution or by different ones:
> 	1) To have a way to enable debugging all parameters passed from/to
> userspace;
> 	2) To be able to measure the driver (and core) performance while
> streaming.
> 
> This patch's scope is to solve (2), by allowing userspace to hook the two
> ioctls that queues/dequeues streaming buffers.
> 
> With that regards, what's wrong on this patch? I couldn't see anything bad
> there. It is not meant to solve (1).

I have two problems with it: 

1) Right now it is just checking for two ioctls, but as soon as we add more
tracepoints you get another switch on the ioctl command, something I've tried
to avoid by creating the table. So a table-oriented implementation would be
much preferred.

2) It duplicates the already existing code to dump the v4l2_buffer struct.
Is there a way to have just one copy of that? I was hoping Wade could look
into that, and if not, then it is something I can explore (although finding
time is an issue).

Bottom line as far as I am concerned: it was merged while I have outstanding
questions.

If there are good technical reasons why the two problems stated above can't
be easily resolved, then I will reconsider, but for now I think it is too early
to merge. For the record, I don't think I mentioned the first problem in my
original reply, it's something I noticed yesterday while looking at the patch
again.

> 
> Before this patch, all we have is (1), as a non-dynamic printk is too
> intrusive to be used for performance measurement. So, there's no way to
> measure how much time a buffer takes to be filled.

Having tracepoints here doesn't tell you anything about that. At best it gives
you information about the jitter.

How are these tracepoints supposed to be used? What information will they
provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
ioctls/fops as well? If so, which ones?

I just have too many questions and I'd like to see some answers before something
like this is merged in the v4l2 core.

Rereading my older replies I see that I wasn't particularly clear about what
my objections to the patch were, for which I apologies.

Nevertheless, I stand by my opinion that this patch needs more discussion.

Wade, I appreciate it if you can give some more insights into how you are
using this and what it gives you.

> In a matter of fact, in the case you didn't noticed, we are already somewhat
> moving to traces, as several drivers are now using dynamic_printk for debug 
> messages, Yet, lots of drivers still use either their own normal
> printk-based debug macros.
> 
> Now, you're proposing to use the same solution for (1) too. 
> 
> Ok, we can go on that direction, but this is a separate issue. Converting
> the v4l2-ioctl to use tracepoints is the easiest part. However, there are
> several things to consider, if we decide to use it for debug purposes:
> 
> a) It will likely require to convert all printks to dynamic ones, as we
> want to have all debug messages serialized.
> 
> Let me explain it better: if some debug messages come via the standard 
> printk mechanism while others come via traces, we loose the capability
> of receiving the messages at the same order that they were produced, and
> it could be harder if not impossible to synchronize them into the right
> order.
> 
> b) It may make sense to write an userspace tool similar to the rasdaemon
> [1] to allow controlling the debug output. That tool directly reads the
> events from the raw tracing queues, formatting the data on userspace and
> hooking only the events that are needed. 
> 
> Currently, the rasdaemon has inside part of the code used by a perf
> tool copied on it (as this code is not inside any library yet). However,
> that code is being prepared to be used as a library. So, it should be
> even easier to write such tool in a near future.
> 
> [1] https://git.fedorahosted.org/cgit/rasdaemon.git/
> 
> c) I don't think that tracepoints are the right mechanism for a post-mortem
> analysis[2]. E. g. if the Kernel crashes, a printk-based mechanism will 
> output something, but I'm not sure if doing the same is possible with traces
> (e. g. forcing the trace messages to go to to tty).
> 
> You should notice that, with the dynamic_printk macros, it is possible to
> compile the Kernel to use normal printk macros for debug macros.
> 
> However, if we convert the ioctl printk's to tracepoints, we may still
> need to have a fallback printk mechanism for ioctl debug messages.
> 
> [2] There are actually some discussions at the RAS mailing lists about
> how to store the tracing data and printk messages on newer hardware that
> offer a non-volatile memory mechanism for that. So, we might actually
> have a post-mortem mechanism for tracepoints in the future, depending on
> the hardware. Yet, not all types of hardware will have such NVRAM.
> 
> Btw, it is possible to use strace to trace all ioctl's. So, the existing
> mechanism is actually a duplicated feature, as userspace already covers it.
> However, in practice, we opted to explicitly duplicate that feature at
> Kernel level, for debugging purposes, because strace doesn't solve (a)
> and (c).
> 
> What I'm saying is that a project to convert the debug facility into
> tracepoints is something that:

That's not what I want to do. What I would like to avoid is duplicating
the code to dump ioctl arguments. Perhaps tracepoints can call a specified
function to dump the arguments? I tried to understand the tracepoint
implementation but I got lost in a maze of macros...

> 	- it is independent of adding some facility for performance 
> 	  measurement (although it may share the same infrastructure);
> 
> 	- it will require lots of effort to change every single driver
> 	  to use dynamic printk's;
> 
> 	- it may require writing a helper tool to enable just the v4l2
> 	  traces and eventually collect them;
> 
> 	- it may require a fallback printk mechanism in order to debug
> 	  kernel panic.
> 
>> To make it official:
>>
>> Nacked-by: Hans Verkuil <hans.verkuil@cisco.com>
>>
>> If we do tracepoints, then we do it right and for all ioctls, not in this
>> half-baked manner.
>>
>> Please revert.
> 
> Let's not mix things. If this patch is correct and solves for performance
> measurement, I don't see any reason to revert.

It duplicates code for dumping ioctl arguments, I would prefer a table-based
solution if possible and I am not convinced of the usefulness of tracepoints
here for performance measurements (at the very least I'd like to know more
about the use-case and for which ioctls and file operations tracepoints might
be useful).

In other words: this patch needs more discussion. I wouldn't care if this
was in a driver, but for the v4l2 core it's too early to merge.

> Using tracepoints for debug is a separate and independent project.

I agree, but that's not what my concerns are about (and I am not sure
whether a project like that would be desirable/necessary at all).

> Such project require lots of tests to proof that it is a viable solution,
> several discussions and a huge time frame to convert all drivers to use
> tracepoints too, plus some post-mortem debug logic.

Regards,

	Hans

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Mauro Carvalho Chehab]

Em Wed, 11 Dec 2013 12:53:55 +0100
Hans Verkuil <hverkuil@xs4all.nl> escreveu:

> Hi Mauro,
> 
> On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
> > Hans,
> > 
> > Em Wed, 11 Dec 2013 08:29:58 +0100
> > Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> > 
> >> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
> >>> Em Sat, 23 Nov 2013 17:54:48 +0100
> >>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> >>>
> >>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
> >>>>> Hi,
> >>>>>
> >>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
> >>>>>> Hi Wade,
> >>>>>>
> >>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
> >>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
> >>>>>>> performance measurements using standard kernel tracers.
> >>>>>>>
> >>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
> >>>>>>> ---
> >>>>>>>
> >>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
> >>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
> >>>>>>
> >>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
> >>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
> >>>>>>
> >>>>>> So this code basically duplicates that functionality. It would be nice to be able
> >>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
> >>>>>
> >>>>> I think it would be really nice to have this kind of support for standard
> >>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
> >>>>> the v4l2 custom debug infrastructure.
> >>>>>
> >>>>> If I understand things correctly, the current tracing/profiling 
> >>>>> infrastructure
> >>>>> is much less invasive than inserting printks all over, which may cause 
> >>>>> changes
> >>>>> in control flow. I doubt the system could be reliably profiled by 
> >>>>> enabling all
> >>>>> those debug prints.
> >>>>>
> >>>>> So my vote would be to add support for standard tracers, like in other
> >>>>> subsystems in the kernel.
> >>>>
> >>>> The reason for the current system is to trace which ioctls are called in
> >>>> what order by a misbehaving application. It's very useful for that,
> >>>> especially when trying to debug user problems.
> >>>>
> >>>> I don't mind switching to tracepoints as long as this functionality is
> >>>> kept one way or another.
> >>>
> >>> I agree with Sylwester: we should move to tracepoints, and this is a good
> >>> start.
> >>
> >> As I mentioned, I don't mind switching to tracepoints, but not in the way the
> >> current patch does it. I certainly don't agree with you merging this patch
> >> as-is without further discussion.
> > 
> > Let's not mix the subjects here. There are two different demands that can be
> > either fulfilled by the same solution or by different ones:
> > 	1) To have a way to enable debugging all parameters passed from/to
> > userspace;
> > 	2) To be able to measure the driver (and core) performance while
> > streaming.
> > 
> > This patch's scope is to solve (2), by allowing userspace to hook the two
> > ioctls that queues/dequeues streaming buffers.
> > 
> > With that regards, what's wrong on this patch? I couldn't see anything bad
> > there. It is not meant to solve (1).
> 
> I have two problems with it: 
> 
> 1) Right now it is just checking for two ioctls, but as soon as we add more
> tracepoints you get another switch on the ioctl command, something I've tried
> to avoid by creating the table. So a table-oriented implementation would be
> much preferred.

>From performance measurement PoV, I don't see any reason to add it to any
other ioctl. Of course if we revisit it and other traces become needed,
then we should use a table approach instead.

> 
> 2) It duplicates the already existing code to dump the v4l2_buffer struct.
> Is there a way to have just one copy of that? I was hoping Wade could look
> into that, and if not, then it is something I can explore (although finding
> time is an issue).

Having implemented tracepoints myself, I'd say that the answer is no.

Let me give you an example.

The ras:aer_event trace is a simple tracepoint that also uses the 
__print_flags() macro. It is implemented at include/trace/events/ras.h
as:

#define aer_correctable_errors		\
	{BIT(0),	"Receiver Error"},		\
	{BIT(6),	"Bad TLP"},			\
	{BIT(7),	"Bad DLLP"},			\
	{BIT(8),	"RELAY_NUM Rollover"},		\
	{BIT(12),	"Replay Timer Timeout"},	\
	{BIT(13),	"Advisory Non-Fatal"}

#define aer_uncorrectable_errors		\
	{BIT(4),	"Data Link Protocol"},		\
	{BIT(12),	"Poisoned TLP"},		\
	{BIT(13),	"Flow Control Protocol"},	\
	{BIT(14),	"Completion Timeout"},		\
	{BIT(15),	"Completer Abort"},		\
	{BIT(16),	"Unexpected Completion"},	\
	{BIT(17),	"Receiver Overflow"},		\
	{BIT(18),	"Malformed TLP"},		\
	{BIT(19),	"ECRC"},			\
	{BIT(20),	"Unsupported Request"}

TRACE_EVENT(aer_event,
	TP_PROTO(const char *dev_name,
		 const u32 status,
		 const u8 severity),

	TP_ARGS(dev_name, status, severity),

	TP_STRUCT__entry(
		__string(	dev_name,	dev_name	)
		__field(	u32,		status		)
		__field(	u8,		severity	)
	),

	TP_fast_assign(
		__assign_str(dev_name, dev_name);
		__entry->status		= status;
		__entry->severity	= severity;
	),

	TP_printk("%s PCIe Bus Error: severity=%s, %s\n",
		__get_str(dev_name),
		__entry->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" :
			__entry->severity == HW_EVENT_ERR_FATAL ?
			"Fatal" : "Uncorrected",
		__entry->severity == HW_EVENT_ERR_CORRECTED ?
		__print_flags(__entry->status, "|", aer_correctable_errors) :
		__print_flags(__entry->status, "|", aer_uncorrectable_errors))


Tracepoints work by having a binary ringbuffer where the data at TP_STRUCT
is passed. In this case, it passes a string, an u32 and an u8.

The TP_printk() macro actually produces a format filenode, describing
each field that would be filled in the ringbuffer and how to convert the
data structure from binary to text:

# cat /sys/kernel/debug/tracing/events/ras/aer_event/format 
name: aer_event
ID: 877
format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:__data_loc char[] dev_name;	offset:8;	size:4;	signed:1;
	field:u32 status;	offset:12;	size:4;	signed:0;
	field:u8 severity;	offset:16;	size:1;	signed:0;

print fmt: "%s PCIe Bus Error: severity=%s, %s
", __get_str(dev_name), REC->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" : REC->severity == HW_EVENT_ERR_FATAL ? "Fatal" : "Uncorrected", REC->severity == HW_EVENT_ERR_CORRECTED ? __print_flags(REC->status, "|", {(1UL << (0)), "Receiver Error"}, {(1UL << (6)), "Bad TLP"}, {(1UL << (7)), "Bad DLLP"}, {(1UL << (8)), "RELAY_NUM Rollover"}, {(1UL << (12)), "Replay Timer Timeout"}, {(1UL << (13)), "Advisory Non-Fatal"}) : __print_flags(REC->status, "|", {(1UL << (4)), "Data Link Protocol"}, {(1UL << (12)), "Poisoned TLP"}, {(1UL << (13)), "Flow Control Protocol"}, {(1UL << (14)), "Completion Timeout"}, {(1UL << (15)), "Completer Abort"}, {(1UL << (16)), "Unexpected Completion"}, {(1UL << (17)), "Receiver Overflow"}, {(1UL << (18)), "Malformed TLP"}, {(1UL << (19)), "ECRC"}, {(1UL << (20)), "Unsupported Request"})

You can see that _print_flags() actually produced a lot of code inside "print fmt".

When someone reads from /sys/kernel/debug/tracing/trace, the print fmt is
handled by the Kernel.

However, when someone uses a performance tool like perf, the binary blobs
are read from the per-CPU raw trace filenodes:
	/sys/kernel/debug/tracing/per_cpu/cpu*/trace_pipe_raw

And the "print fmt" line at the format file is actually used as a hint
for tracing userspace tool to handle it that can be used or not.
For example, at the rasdaemon, I'm overriding all default handlers,
using my own handler, as I want to store all events on a sqlite database:

	https://git.fedorahosted.org/cgit/rasdaemon.git/tree/ras-aer-handler.c

> 
> Bottom line as far as I am concerned: it was merged while I have outstanding
> questions.

Well, only on this email you're letting clear what are your concerns.

> If there are good technical reasons why the two problems stated above can't
> be easily resolved, then I will reconsider, but for now I think it is too early
> to merge. For the record, I don't think I mentioned the first problem in my
> original reply, it's something I noticed yesterday while looking at the patch
> again.
> 
> > 
> > Before this patch, all we have is (1), as a non-dynamic printk is too
> > intrusive to be used for performance measurement. So, there's no way to
> > measure how much time a buffer takes to be filled.
> 
> Having tracepoints here doesn't tell you anything about that. At best it gives
> you information about the jitter.
> 
> How are these tracepoints supposed to be used? What information will they
> provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
> ioctls/fops as well? If so, which ones?

As shown above, a performance tool can add handlers for tracepoint data,
allowing to discover, for example, if dequeue occurred on a different order
than queue, associating each dequeued buffer to the corresponding queued
one, and to measure the time between each queue/dequeue pairs.

> 
> I just have too many questions and I'd like to see some answers before something
> like this is merged in the v4l2 core.
> 
> Rereading my older replies I see that I wasn't particularly clear about what
> my objections to the patch were, for which I apologies.
> 
> Nevertheless, I stand by my opinion that this patch needs more discussion.
> 
> Wade, I appreciate it if you can give some more insights into how you are
> using this and what it gives you.
> 
> > In a matter of fact, in the case you didn't noticed, we are already somewhat
> > moving to traces, as several drivers are now using dynamic_printk for debug 
> > messages, Yet, lots of drivers still use either their own normal
> > printk-based debug macros.
> > 
> > Now, you're proposing to use the same solution for (1) too. 
> > 
> > Ok, we can go on that direction, but this is a separate issue. Converting
> > the v4l2-ioctl to use tracepoints is the easiest part. However, there are
> > several things to consider, if we decide to use it for debug purposes:
> > 
> > a) It will likely require to convert all printks to dynamic ones, as we
> > want to have all debug messages serialized.
> > 
> > Let me explain it better: if some debug messages come via the standard 
> > printk mechanism while others come via traces, we loose the capability
> > of receiving the messages at the same order that they were produced, and
> > it could be harder if not impossible to synchronize them into the right
> > order.
> > 
> > b) It may make sense to write an userspace tool similar to the rasdaemon
> > [1] to allow controlling the debug output. That tool directly reads the
> > events from the raw tracing queues, formatting the data on userspace and
> > hooking only the events that are needed. 
> > 
> > Currently, the rasdaemon has inside part of the code used by a perf
> > tool copied on it (as this code is not inside any library yet). However,
> > that code is being prepared to be used as a library. So, it should be
> > even easier to write such tool in a near future.
> > 
> > [1] https://git.fedorahosted.org/cgit/rasdaemon.git/
> > 
> > c) I don't think that tracepoints are the right mechanism for a post-mortem
> > analysis[2]. E. g. if the Kernel crashes, a printk-based mechanism will 
> > output something, but I'm not sure if doing the same is possible with traces
> > (e. g. forcing the trace messages to go to to tty).
> > 
> > You should notice that, with the dynamic_printk macros, it is possible to
> > compile the Kernel to use normal printk macros for debug macros.
> > 
> > However, if we convert the ioctl printk's to tracepoints, we may still
> > need to have a fallback printk mechanism for ioctl debug messages.
> > 
> > [2] There are actually some discussions at the RAS mailing lists about
> > how to store the tracing data and printk messages on newer hardware that
> > offer a non-volatile memory mechanism for that. So, we might actually
> > have a post-mortem mechanism for tracepoints in the future, depending on
> > the hardware. Yet, not all types of hardware will have such NVRAM.
> > 
> > Btw, it is possible to use strace to trace all ioctl's. So, the existing
> > mechanism is actually a duplicated feature, as userspace already covers it.
> > However, in practice, we opted to explicitly duplicate that feature at
> > Kernel level, for debugging purposes, because strace doesn't solve (a)
> > and (c).
> > 
> > What I'm saying is that a project to convert the debug facility into
> > tracepoints is something that:
> 
> That's not what I want to do. What I would like to avoid is duplicating
> the code to dump ioctl arguments. Perhaps tracepoints can call a specified
> function to dump the arguments? I tried to understand the tracepoint
> implementation but I got lost in a maze of macros...

As shown above, tracepoints use a completely different way to output
data than printk.

> 
> > 	- it is independent of adding some facility for performance 
> > 	  measurement (although it may share the same infrastructure);
> > 
> > 	- it will require lots of effort to change every single driver
> > 	  to use dynamic printk's;
> > 
> > 	- it may require writing a helper tool to enable just the v4l2
> > 	  traces and eventually collect them;
> > 
> > 	- it may require a fallback printk mechanism in order to debug
> > 	  kernel panic.
> > 
> >> To make it official:
> >>
> >> Nacked-by: Hans Verkuil <hans.verkuil@cisco.com>
> >>
> >> If we do tracepoints, then we do it right and for all ioctls, not in this
> >> half-baked manner.
> >>
> >> Please revert.
> > 
> > Let's not mix things. If this patch is correct and solves for performance
> > measurement, I don't see any reason to revert.
> 
> It duplicates code for dumping ioctl arguments, I would prefer a table-based
> solution if possible and I am not convinced of the usefulness of tracepoints
> here for performance measurements (at the very least I'd like to know more
> about the use-case and for which ioctls and file operations tracepoints might
> be useful).
> 
> In other words: this patch needs more discussion. I wouldn't care if this
> was in a driver, but for the v4l2 core it's too early to merge.
> 
> > Using tracepoints for debug is a separate and independent project.
> 
> I agree, but that's not what my concerns are about (and I am not sure
> whether a project like that would be desirable/necessary at all).
> 
> > Such project require lots of tests to proof that it is a viable solution,
> > several discussions and a huge time frame to convert all drivers to use
> > tracepoints too, plus some post-mortem debug logic.
> 
> Regards,
> 
> 	Hans
> 


-- 

Cheers,
Mauro

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Hans Verkuil]

On 12/11/13 13:44, Mauro Carvalho Chehab wrote:
> Em Wed, 11 Dec 2013 12:53:55 +0100
> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> 
>> Hi Mauro,
>>
>> On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
>>> Hans,
>>>
>>> Em Wed, 11 Dec 2013 08:29:58 +0100
>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>
>>>> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
>>>>> Em Sat, 23 Nov 2013 17:54:48 +0100
>>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>>
>>>>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
>>>>>>> Hi,
>>>>>>>
>>>>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>>>>>>>> Hi Wade,
>>>>>>>>
>>>>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>>>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>>>>>>>> performance measurements using standard kernel tracers.
>>>>>>>>>
>>>>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>>>>>>>> ---
>>>>>>>>>
>>>>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>>>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>>>>>>>
>>>>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>>>>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>>>>>>>
>>>>>>>> So this code basically duplicates that functionality. It would be nice to be able
>>>>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
>>>>>>>
>>>>>>> I think it would be really nice to have this kind of support for standard
>>>>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
>>>>>>> the v4l2 custom debug infrastructure.
>>>>>>>
>>>>>>> If I understand things correctly, the current tracing/profiling 
>>>>>>> infrastructure
>>>>>>> is much less invasive than inserting printks all over, which may cause 
>>>>>>> changes
>>>>>>> in control flow. I doubt the system could be reliably profiled by 
>>>>>>> enabling all
>>>>>>> those debug prints.
>>>>>>>
>>>>>>> So my vote would be to add support for standard tracers, like in other
>>>>>>> subsystems in the kernel.
>>>>>>
>>>>>> The reason for the current system is to trace which ioctls are called in
>>>>>> what order by a misbehaving application. It's very useful for that,
>>>>>> especially when trying to debug user problems.
>>>>>>
>>>>>> I don't mind switching to tracepoints as long as this functionality is
>>>>>> kept one way or another.
>>>>>
>>>>> I agree with Sylwester: we should move to tracepoints, and this is a good
>>>>> start.
>>>>
>>>> As I mentioned, I don't mind switching to tracepoints, but not in the way the
>>>> current patch does it. I certainly don't agree with you merging this patch
>>>> as-is without further discussion.
>>>
>>> Let's not mix the subjects here. There are two different demands that can be
>>> either fulfilled by the same solution or by different ones:
>>> 	1) To have a way to enable debugging all parameters passed from/to
>>> userspace;
>>> 	2) To be able to measure the driver (and core) performance while
>>> streaming.
>>>
>>> This patch's scope is to solve (2), by allowing userspace to hook the two
>>> ioctls that queues/dequeues streaming buffers.
>>>
>>> With that regards, what's wrong on this patch? I couldn't see anything bad
>>> there. It is not meant to solve (1).
>>
>> I have two problems with it: 
>>
>> 1) Right now it is just checking for two ioctls, but as soon as we add more
>> tracepoints you get another switch on the ioctl command, something I've tried
>> to avoid by creating the table. So a table-oriented implementation would be
>> much preferred.
> 
> From performance measurement PoV, I don't see any reason to add it to any
> other ioctl.

But perhaps this makes sense as well for read() and write()? Possibly poll()?

> Of course if we revisit it and other traces become needed,
> then we should use a table approach instead.
> 
>>
>> 2) It duplicates the already existing code to dump the v4l2_buffer struct.
>> Is there a way to have just one copy of that? I was hoping Wade could look
>> into that, and if not, then it is something I can explore (although finding
>> time is an issue).
> 
> Having implemented tracepoints myself, I'd say that the answer is no.
> 
> Let me give you an example.
> 
> The ras:aer_event trace is a simple tracepoint that also uses the 
> __print_flags() macro. It is implemented at include/trace/events/ras.h
> as:
> 
> #define aer_correctable_errors		\
> 	{BIT(0),	"Receiver Error"},		\
> 	{BIT(6),	"Bad TLP"},			\
> 	{BIT(7),	"Bad DLLP"},			\
> 	{BIT(8),	"RELAY_NUM Rollover"},		\
> 	{BIT(12),	"Replay Timer Timeout"},	\
> 	{BIT(13),	"Advisory Non-Fatal"}
> 
> #define aer_uncorrectable_errors		\
> 	{BIT(4),	"Data Link Protocol"},		\
> 	{BIT(12),	"Poisoned TLP"},		\
> 	{BIT(13),	"Flow Control Protocol"},	\
> 	{BIT(14),	"Completion Timeout"},		\
> 	{BIT(15),	"Completer Abort"},		\
> 	{BIT(16),	"Unexpected Completion"},	\
> 	{BIT(17),	"Receiver Overflow"},		\
> 	{BIT(18),	"Malformed TLP"},		\
> 	{BIT(19),	"ECRC"},			\
> 	{BIT(20),	"Unsupported Request"}
> 
> TRACE_EVENT(aer_event,
> 	TP_PROTO(const char *dev_name,
> 		 const u32 status,
> 		 const u8 severity),
> 
> 	TP_ARGS(dev_name, status, severity),
> 
> 	TP_STRUCT__entry(
> 		__string(	dev_name,	dev_name	)
> 		__field(	u32,		status		)
> 		__field(	u8,		severity	)
> 	),
> 
> 	TP_fast_assign(
> 		__assign_str(dev_name, dev_name);
> 		__entry->status		= status;
> 		__entry->severity	= severity;
> 	),
> 
> 	TP_printk("%s PCIe Bus Error: severity=%s, %s\n",
> 		__get_str(dev_name),
> 		__entry->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" :
> 			__entry->severity == HW_EVENT_ERR_FATAL ?
> 			"Fatal" : "Uncorrected",
> 		__entry->severity == HW_EVENT_ERR_CORRECTED ?
> 		__print_flags(__entry->status, "|", aer_correctable_errors) :
> 		__print_flags(__entry->status, "|", aer_uncorrectable_errors))
> 
> 
> Tracepoints work by having a binary ringbuffer where the data at TP_STRUCT
> is passed. In this case, it passes a string, an u32 and an u8.
> 
> The TP_printk() macro actually produces a format filenode, describing
> each field that would be filled in the ringbuffer and how to convert the
> data structure from binary to text:
> 
> # cat /sys/kernel/debug/tracing/events/ras/aer_event/format 
> name: aer_event
> ID: 877
> format:
> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
> 	field:unsigned char common_preempt_count;	offset:3;	size:1;signed:0;
> 	field:int common_pid;	offset:4;	size:4;	signed:1;
> 
> 	field:__data_loc char[] dev_name;	offset:8;	size:4;	signed:1;
> 	field:u32 status;	offset:12;	size:4;	signed:0;
> 	field:u8 severity;	offset:16;	size:1;	signed:0;
> 
> print fmt: "%s PCIe Bus Error: severity=%s, %s
> ", __get_str(dev_name), REC->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" : REC->severity == HW_EVENT_ERR_FATAL ? "Fatal" : "Uncorrected", REC->severity == HW_EVENT_ERR_CORRECTED ? __print_flags(REC->status, "|", {(1UL << (0)), "Receiver Error"}, {(1UL << (6)), "Bad TLP"}, {(1UL << (7)), "Bad DLLP"}, {(1UL << (8)), "RELAY_NUM Rollover"}, {(1UL << (12)), "Replay Timer Timeout"}, {(1UL << (13)), "Advisory Non-Fatal"}) : __print_flags(REC->status, "|", {(1UL << (4)), "Data Link Protocol"}, {(1UL << (12)), "Poisoned TLP"}, {(1UL << (13)), "Flow Control Protocol"}, {(1UL << (14)), "Completion Timeout"}, {(1UL << (15)), "Completer Abort"}, {(1UL << (16)), "Unexpected Completion"}, {(1UL << (17)), "Receiver Overflow"}, {(1UL << (18)), "Malformed TLP"}, {(1UL << (19)), "ECRC"}, {(1UL << (20)), "Unsupported Request"})
> 
> You can see that _print_flags() actually produced a lot of code inside "print fmt".
> 
> When someone reads from /sys/kernel/debug/tracing/trace, the print fmt is
> handled by the Kernel.
> 
> However, when someone uses a performance tool like perf, the binary blobs
> are read from the per-CPU raw trace filenodes:
> 	/sys/kernel/debug/tracing/per_cpu/cpu*/trace_pipe_raw
> 
> And the "print fmt" line at the format file is actually used as a hint
> for tracing userspace tool to handle it that can be used or not.
> For example, at the rasdaemon, I'm overriding all default handlers,
> using my own handler, as I want to store all events on a sqlite database:
> 
> 	https://git.fedorahosted.org/cgit/rasdaemon.git/tree/ras-aer-handler.c

OK, fair enough. So that code can't be shared. Good to know.

> 
>>
>> Bottom line as far as I am concerned: it was merged while I have outstanding
>> questions.
> 
> Well, only on this email you're letting clear what are your concerns.
> 
>> If there are good technical reasons why the two problems stated above can't
>> be easily resolved, then I will reconsider, but for now I think it is too early
>> to merge. For the record, I don't think I mentioned the first problem in my
>> original reply, it's something I noticed yesterday while looking at the patch
>> again.
>>
>>>
>>> Before this patch, all we have is (1), as a non-dynamic printk is too
>>> intrusive to be used for performance measurement. So, there's no way to
>>> measure how much time a buffer takes to be filled.
>>
>> Having tracepoints here doesn't tell you anything about that. At best it gives
>> you information about the jitter.
>>
>> How are these tracepoints supposed to be used? What information will they
>> provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
>> ioctls/fops as well? If so, which ones?
> 
> As shown above, a performance tool can add handlers for tracepoint data,
> allowing to discover, for example, if dequeue occurred on a different order
> than queue, associating each dequeued buffer to the corresponding queued
> one, and to measure the time between each queue/dequeue pairs.

I'm not really convinced about it. Which is why I would like to know a bit more
how Wade uses it.

Also: the tracepoint is placed outside the lock which will make any time
measurements even less reliable than they already are. Also, putting it
inside the lock will ensure that the traces are generated in the order
that they are serialized by the lock. In addition, the error code of the
ioctl isn't traced either. Perhaps the traces should only be done if
ret == 0 anyway?

Again, please revert, let's wait for some more background information
from Wade, think about it a bit more over the weekend and revisit it.

Regards,

	Hans

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Mauro Carvalho Chehab]

Em Wed, 11 Dec 2013 14:15:23 +0100
Hans Verkuil <hverkuil@xs4all.nl> escreveu:

> On 12/11/13 13:44, Mauro Carvalho Chehab wrote:
> > Em Wed, 11 Dec 2013 12:53:55 +0100
> > Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> > 
> >> Hi Mauro,
> >>
> >> On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
> >>> Hans,
> >>>
> >>> Em Wed, 11 Dec 2013 08:29:58 +0100
> >>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> >>>
> >>>> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
> >>>>> Em Sat, 23 Nov 2013 17:54:48 +0100
> >>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
> >>>>>
> >>>>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
> >>>>>>> Hi,
> >>>>>>>
> >>>>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
> >>>>>>>> Hi Wade,
> >>>>>>>>
> >>>>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
> >>>>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
> >>>>>>>>> performance measurements using standard kernel tracers.
> >>>>>>>>>
> >>>>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
> >>>>>>>>> ---
> >>>>>>>>>
> >>>>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
> >>>>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
> >>>>>>>>
> >>>>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
> >>>>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
> >>>>>>>>
> >>>>>>>> So this code basically duplicates that functionality. It would be nice to be able
> >>>>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
> >>>>>>>
> >>>>>>> I think it would be really nice to have this kind of support for standard
> >>>>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
> >>>>>>> the v4l2 custom debug infrastructure.
> >>>>>>>
> >>>>>>> If I understand things correctly, the current tracing/profiling 
> >>>>>>> infrastructure
> >>>>>>> is much less invasive than inserting printks all over, which may cause 
> >>>>>>> changes
> >>>>>>> in control flow. I doubt the system could be reliably profiled by 
> >>>>>>> enabling all
> >>>>>>> those debug prints.
> >>>>>>>
> >>>>>>> So my vote would be to add support for standard tracers, like in other
> >>>>>>> subsystems in the kernel.
> >>>>>>
> >>>>>> The reason for the current system is to trace which ioctls are called in
> >>>>>> what order by a misbehaving application. It's very useful for that,
> >>>>>> especially when trying to debug user problems.
> >>>>>>
> >>>>>> I don't mind switching to tracepoints as long as this functionality is
> >>>>>> kept one way or another.
> >>>>>
> >>>>> I agree with Sylwester: we should move to tracepoints, and this is a good
> >>>>> start.
> >>>>
> >>>> As I mentioned, I don't mind switching to tracepoints, but not in the way the
> >>>> current patch does it. I certainly don't agree with you merging this patch
> >>>> as-is without further discussion.
> >>>
> >>> Let's not mix the subjects here. There are two different demands that can be
> >>> either fulfilled by the same solution or by different ones:
> >>> 	1) To have a way to enable debugging all parameters passed from/to
> >>> userspace;
> >>> 	2) To be able to measure the driver (and core) performance while
> >>> streaming.
> >>>
> >>> This patch's scope is to solve (2), by allowing userspace to hook the two
> >>> ioctls that queues/dequeues streaming buffers.
> >>>
> >>> With that regards, what's wrong on this patch? I couldn't see anything bad
> >>> there. It is not meant to solve (1).
> >>
> >> I have two problems with it: 
> >>
> >> 1) Right now it is just checking for two ioctls, but as soon as we add more
> >> tracepoints you get another switch on the ioctl command, something I've tried
> >> to avoid by creating the table. So a table-oriented implementation would be
> >> much preferred.
> > 
> > From performance measurement PoV, I don't see any reason to add it to any
> > other ioctl.
> 
> But perhaps this makes sense as well for read() and write()? Possibly poll()?

Could be, but, in this case, it won't be at the ioctl table.

> > Of course if we revisit it and other traces become needed,
> > then we should use a table approach instead.
> > 
> >>
> >> 2) It duplicates the already existing code to dump the v4l2_buffer struct.
> >> Is there a way to have just one copy of that? I was hoping Wade could look
> >> into that, and if not, then it is something I can explore (although finding
> >> time is an issue).
> > 
> > Having implemented tracepoints myself, I'd say that the answer is no.
> > 
> > Let me give you an example.
> > 
> > The ras:aer_event trace is a simple tracepoint that also uses the 
> > __print_flags() macro. It is implemented at include/trace/events/ras.h
> > as:
> > 
> > #define aer_correctable_errors		\
> > 	{BIT(0),	"Receiver Error"},		\
> > 	{BIT(6),	"Bad TLP"},			\
> > 	{BIT(7),	"Bad DLLP"},			\
> > 	{BIT(8),	"RELAY_NUM Rollover"},		\
> > 	{BIT(12),	"Replay Timer Timeout"},	\
> > 	{BIT(13),	"Advisory Non-Fatal"}
> > 
> > #define aer_uncorrectable_errors		\
> > 	{BIT(4),	"Data Link Protocol"},		\
> > 	{BIT(12),	"Poisoned TLP"},		\
> > 	{BIT(13),	"Flow Control Protocol"},	\
> > 	{BIT(14),	"Completion Timeout"},		\
> > 	{BIT(15),	"Completer Abort"},		\
> > 	{BIT(16),	"Unexpected Completion"},	\
> > 	{BIT(17),	"Receiver Overflow"},		\
> > 	{BIT(18),	"Malformed TLP"},		\
> > 	{BIT(19),	"ECRC"},			\
> > 	{BIT(20),	"Unsupported Request"}
> > 
> > TRACE_EVENT(aer_event,
> > 	TP_PROTO(const char *dev_name,
> > 		 const u32 status,
> > 		 const u8 severity),
> > 
> > 	TP_ARGS(dev_name, status, severity),
> > 
> > 	TP_STRUCT__entry(
> > 		__string(	dev_name,	dev_name	)
> > 		__field(	u32,		status		)
> > 		__field(	u8,		severity	)
> > 	),
> > 
> > 	TP_fast_assign(
> > 		__assign_str(dev_name, dev_name);
> > 		__entry->status		= status;
> > 		__entry->severity	= severity;
> > 	),
> > 
> > 	TP_printk("%s PCIe Bus Error: severity=%s, %s\n",
> > 		__get_str(dev_name),
> > 		__entry->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" :
> > 			__entry->severity == HW_EVENT_ERR_FATAL ?
> > 			"Fatal" : "Uncorrected",
> > 		__entry->severity == HW_EVENT_ERR_CORRECTED ?
> > 		__print_flags(__entry->status, "|", aer_correctable_errors) :
> > 		__print_flags(__entry->status, "|", aer_uncorrectable_errors))
> > 
> > 
> > Tracepoints work by having a binary ringbuffer where the data at TP_STRUCT
> > is passed. In this case, it passes a string, an u32 and an u8.
> > 
> > The TP_printk() macro actually produces a format filenode, describing
> > each field that would be filled in the ringbuffer and how to convert the
> > data structure from binary to text:
> > 
> > # cat /sys/kernel/debug/tracing/events/ras/aer_event/format 
> > name: aer_event
> > ID: 877
> > format:
> > 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
> > 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
> > 	field:unsigned char common_preempt_count;	offset:3;	size:1;signed:0;
> > 	field:int common_pid;	offset:4;	size:4;	signed:1;
> > 
> > 	field:__data_loc char[] dev_name;	offset:8;	size:4;	signed:1;
> > 	field:u32 status;	offset:12;	size:4;	signed:0;
> > 	field:u8 severity;	offset:16;	size:1;	signed:0;
> > 
> > print fmt: "%s PCIe Bus Error: severity=%s, %s
> > ", __get_str(dev_name), REC->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" : REC->severity == HW_EVENT_ERR_FATAL ? "Fatal" : "Uncorrected", REC->severity == HW_EVENT_ERR_CORRECTED ? __print_flags(REC->status, "|", {(1UL << (0)), "Receiver Error"}, {(1UL << (6)), "Bad TLP"}, {(1UL << (7)), "Bad DLLP"}, {(1UL << (8)), "RELAY_NUM Rollover"}, {(1UL << (12)), "Replay Timer Timeout"}, {(1UL << (13)), "Advisory Non-Fatal"}) : __print_flags(REC->status, "|", {(1UL << (4)), "Data Link Protocol"}, {(1UL << (12)), "Poisoned TLP"}, {(1UL << (13)), "Flow Control Protocol"}, {(1UL << (14)), "Completion Timeout"}, {(1UL << (15)), "Completer Abort"}, {(1UL << (16)), "Unexpected Completion"}, {(1UL << (17)), "Receiver Overflow"}, {(1UL << (18)), "Malformed TLP"}, {(1UL << (19)), "ECRC"}, {(1UL << (20)), "Unsupported Request"})
> > 
> > You can see that _print_flags() actually produced a lot of code inside "print fmt".
> > 
> > When someone reads from /sys/kernel/debug/tracing/trace, the print fmt is
> > handled by the Kernel.
> > 
> > However, when someone uses a performance tool like perf, the binary blobs
> > are read from the per-CPU raw trace filenodes:
> > 	/sys/kernel/debug/tracing/per_cpu/cpu*/trace_pipe_raw
> > 
> > And the "print fmt" line at the format file is actually used as a hint
> > for tracing userspace tool to handle it that can be used or not.
> > For example, at the rasdaemon, I'm overriding all default handlers,
> > using my own handler, as I want to store all events on a sqlite database:
> > 
> > 	https://git.fedorahosted.org/cgit/rasdaemon.git/tree/ras-aer-handler.c
> 
> OK, fair enough. So that code can't be shared. Good to know.
> 
> > 
> >>
> >> Bottom line as far as I am concerned: it was merged while I have outstanding
> >> questions.
> > 
> > Well, only on this email you're letting clear what are your concerns.
> > 
> >> If there are good technical reasons why the two problems stated above can't
> >> be easily resolved, then I will reconsider, but for now I think it is too early
> >> to merge. For the record, I don't think I mentioned the first problem in my
> >> original reply, it's something I noticed yesterday while looking at the patch
> >> again.
> >>
> >>>
> >>> Before this patch, all we have is (1), as a non-dynamic printk is too
> >>> intrusive to be used for performance measurement. So, there's no way to
> >>> measure how much time a buffer takes to be filled.
> >>
> >> Having tracepoints here doesn't tell you anything about that. At best it gives
> >> you information about the jitter.
> >>
> >> How are these tracepoints supposed to be used? What information will they
> >> provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
> >> ioctls/fops as well? If so, which ones?
> > 
> > As shown above, a performance tool can add handlers for tracepoint data,
> > allowing to discover, for example, if dequeue occurred on a different order
> > than queue, associating each dequeued buffer to the corresponding queued
> > one, and to measure the time between each queue/dequeue pairs.
> 
> I'm not really convinced about it. Which is why I would like to know a bit more
> how Wade uses it.

I agree that it is good to know where this is used. I think he already
explained it at the version 1 of this patch:
	https://linuxtv.org/patch/20455/

> Also: the tracepoint is placed outside the lock which will make any time
> measurements even less reliable than they already are. Also, putting it
> inside the lock will ensure that the traces are generated in the order
> that they are serialized by the lock. In addition, the error code of the
> ioctl isn't traced either. Perhaps the traces should only be done if
> ret == 0 anyway?

Yeah, we can play with changing its position or eventually calling it twice,
one at the beginning of the handler, and another one after handling it, in
order to allow measuring how much time is spent inside the qbuf/dqbuf
handling.

> Again, please revert, let's wait for some more background information
> from Wade, think about it a bit more over the weekend and revisit it.

As you didn't comment the first patch, sent in Oct, 18, and your comment
for the second one were not clear, I understood that there were no strong
reason for not merging it.

Now I see that I was too quick on merging this patch.

Now that this was already applied, we don't need to rush reverting it,
as we are not close to submit it upstream, and it shouldn't cause any
issue for the ones not using those tracepoints.

If we don't reach any consensus, we can always drop it just before the
merge window.

Yet, having it applied allows a broader range of users to do some tests, 
helping to improve it or eventually to come to the conclusion that it
is useless.

So, I'm opting to keep it for now. I'll review this decision before
the start of the next merge window.

Regards,
Mauro

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Wade Farnsworth]

Hi Hans,

Hans Verkuil wrote:
> On 12/11/13 13:44, Mauro Carvalho Chehab wrote:
>> Em Wed, 11 Dec 2013 12:53:55 +0100
>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>
>>> Hi Mauro,
>>>
>>> On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
>>>> Hans,
>>>>
>>>> Em Wed, 11 Dec 2013 08:29:58 +0100
>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>
>>>>> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
>>>>>> Em Sat, 23 Nov 2013 17:54:48 +0100
>>>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>>>
>>>>>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>>>>>>>>> Hi Wade,
>>>>>>>>>
>>>>>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>>>>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>>>>>>>>> performance measurements using standard kernel tracers.
>>>>>>>>>>
>>>>>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>>>>>>>>> ---
>>>>>>>>>>
>>>>>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>>>>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>>>>>>>>
>>>>>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>>>>>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>>>>>>>>
>>>>>>>>> So this code basically duplicates that functionality. It would be nice to be able
>>>>>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
>>>>>>>>
>>>>>>>> I think it would be really nice to have this kind of support for standard
>>>>>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
>>>>>>>> the v4l2 custom debug infrastructure.
>>>>>>>>
>>>>>>>> If I understand things correctly, the current tracing/profiling 
>>>>>>>> infrastructure
>>>>>>>> is much less invasive than inserting printks all over, which may cause 
>>>>>>>> changes
>>>>>>>> in control flow. I doubt the system could be reliably profiled by 
>>>>>>>> enabling all
>>>>>>>> those debug prints.
>>>>>>>>
>>>>>>>> So my vote would be to add support for standard tracers, like in other
>>>>>>>> subsystems in the kernel.
>>>>>>>
>>>>>>> The reason for the current system is to trace which ioctls are called in
>>>>>>> what order by a misbehaving application. It's very useful for that,
>>>>>>> especially when trying to debug user problems.
>>>>>>>
>>>>>>> I don't mind switching to tracepoints as long as this functionality is
>>>>>>> kept one way or another.
>>>>>>
>>>>>> I agree with Sylwester: we should move to tracepoints, and this is a good
>>>>>> start.
>>>>>
>>>>> As I mentioned, I don't mind switching to tracepoints, but not in the way the
>>>>> current patch does it. I certainly don't agree with you merging this patch
>>>>> as-is without further discussion.
>>>>
>>>> Let's not mix the subjects here. There are two different demands that can be
>>>> either fulfilled by the same solution or by different ones:
>>>> 	1) To have a way to enable debugging all parameters passed from/to
>>>> userspace;
>>>> 	2) To be able to measure the driver (and core) performance while
>>>> streaming.
>>>>
>>>> This patch's scope is to solve (2), by allowing userspace to hook the two
>>>> ioctls that queues/dequeues streaming buffers.
>>>>
>>>> With that regards, what's wrong on this patch? I couldn't see anything bad
>>>> there. It is not meant to solve (1).
>>>
>>> I have two problems with it: 
>>>
>>> 1) Right now it is just checking for two ioctls, but as soon as we add more
>>> tracepoints you get another switch on the ioctl command, something I've tried
>>> to avoid by creating the table. So a table-oriented implementation would be
>>> much preferred.
>>
>> From performance measurement PoV, I don't see any reason to add it to any
>> other ioctl.
> 
> But perhaps this makes sense as well for read() and write()? Possibly poll()?
> 
>> Of course if we revisit it and other traces become needed,
>> then we should use a table approach instead.
>>
>>>
>>> 2) It duplicates the already existing code to dump the v4l2_buffer struct.
>>> Is there a way to have just one copy of that? I was hoping Wade could look
>>> into that, and if not, then it is something I can explore (although finding
>>> time is an issue).
>>
>> Having implemented tracepoints myself, I'd say that the answer is no.
>>
>> Let me give you an example.
>>
>> The ras:aer_event trace is a simple tracepoint that also uses the 
>> __print_flags() macro. It is implemented at include/trace/events/ras.h
>> as:
>>
>> #define aer_correctable_errors		\
>> 	{BIT(0),	"Receiver Error"},		\
>> 	{BIT(6),	"Bad TLP"},			\
>> 	{BIT(7),	"Bad DLLP"},			\
>> 	{BIT(8),	"RELAY_NUM Rollover"},		\
>> 	{BIT(12),	"Replay Timer Timeout"},	\
>> 	{BIT(13),	"Advisory Non-Fatal"}
>>
>> #define aer_uncorrectable_errors		\
>> 	{BIT(4),	"Data Link Protocol"},		\
>> 	{BIT(12),	"Poisoned TLP"},		\
>> 	{BIT(13),	"Flow Control Protocol"},	\
>> 	{BIT(14),	"Completion Timeout"},		\
>> 	{BIT(15),	"Completer Abort"},		\
>> 	{BIT(16),	"Unexpected Completion"},	\
>> 	{BIT(17),	"Receiver Overflow"},		\
>> 	{BIT(18),	"Malformed TLP"},		\
>> 	{BIT(19),	"ECRC"},			\
>> 	{BIT(20),	"Unsupported Request"}
>>
>> TRACE_EVENT(aer_event,
>> 	TP_PROTO(const char *dev_name,
>> 		 const u32 status,
>> 		 const u8 severity),
>>
>> 	TP_ARGS(dev_name, status, severity),
>>
>> 	TP_STRUCT__entry(
>> 		__string(	dev_name,	dev_name	)
>> 		__field(	u32,		status		)
>> 		__field(	u8,		severity	)
>> 	),
>>
>> 	TP_fast_assign(
>> 		__assign_str(dev_name, dev_name);
>> 		__entry->status		= status;
>> 		__entry->severity	= severity;
>> 	),
>>
>> 	TP_printk("%s PCIe Bus Error: severity=%s, %s\n",
>> 		__get_str(dev_name),
>> 		__entry->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" :
>> 			__entry->severity == HW_EVENT_ERR_FATAL ?
>> 			"Fatal" : "Uncorrected",
>> 		__entry->severity == HW_EVENT_ERR_CORRECTED ?
>> 		__print_flags(__entry->status, "|", aer_correctable_errors) :
>> 		__print_flags(__entry->status, "|", aer_uncorrectable_errors))
>>
>>
>> Tracepoints work by having a binary ringbuffer where the data at TP_STRUCT
>> is passed. In this case, it passes a string, an u32 and an u8.
>>
>> The TP_printk() macro actually produces a format filenode, describing
>> each field that would be filled in the ringbuffer and how to convert the
>> data structure from binary to text:
>>
>> # cat /sys/kernel/debug/tracing/events/ras/aer_event/format 
>> name: aer_event
>> ID: 877
>> format:
>> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
>> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
>> 	field:unsigned char common_preempt_count;	offset:3;	size:1;signed:0;
>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>
>> 	field:__data_loc char[] dev_name;	offset:8;	size:4;	signed:1;
>> 	field:u32 status;	offset:12;	size:4;	signed:0;
>> 	field:u8 severity;	offset:16;	size:1;	signed:0;
>>
>> print fmt: "%s PCIe Bus Error: severity=%s, %s
>> ", __get_str(dev_name), REC->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" : REC->severity == HW_EVENT_ERR_FATAL ? "Fatal" : "Uncorrected", REC->severity == HW_EVENT_ERR_CORRECTED ? __print_flags(REC->status, "|", {(1UL << (0)), "Receiver Error"}, {(1UL << (6)), "Bad TLP"}, {(1UL << (7)), "Bad DLLP"}, {(1UL << (8)), "RELAY_NUM Rollover"}, {(1UL << (12)), "Replay Timer Timeout"}, {(1UL << (13)), "Advisory Non-Fatal"}) : __print_flags(REC->status, "|", {(1UL << (4)), "Data Link Protocol"}, {(1UL << (12)), "Poisoned TLP"}, {(1UL << (13)), "Flow Control Protocol"}, {(1UL << (14)), "Completion Timeout"}, {(1UL << (15)), "Completer Abort"}, {(1UL << (16)), "Unexpected Completion"}, {(1UL << (17)), "Receiver Overflow"}, {(1UL << (18)), "Malformed TLP"}, {(1UL << (19)), "ECRC"}, {(1UL << (20)), "Unsupported Request"})
>>
>> You can see that _print_flags() actually produced a lot of code inside "print fmt".
>>
>> When someone reads from /sys/kernel/debug/tracing/trace, the print fmt is
>> handled by the Kernel.
>>
>> However, when someone uses a performance tool like perf, the binary blobs
>> are read from the per-CPU raw trace filenodes:
>> 	/sys/kernel/debug/tracing/per_cpu/cpu*/trace_pipe_raw
>>
>> And the "print fmt" line at the format file is actually used as a hint
>> for tracing userspace tool to handle it that can be used or not.
>> For example, at the rasdaemon, I'm overriding all default handlers,
>> using my own handler, as I want to store all events on a sqlite database:
>>
>> 	https://git.fedorahosted.org/cgit/rasdaemon.git/tree/ras-aer-handler.c
> 
> OK, fair enough. So that code can't be shared. Good to know.
> 
>>
>>>
>>> Bottom line as far as I am concerned: it was merged while I have outstanding
>>> questions.
>>
>> Well, only on this email you're letting clear what are your concerns.
>>
>>> If there are good technical reasons why the two problems stated above can't
>>> be easily resolved, then I will reconsider, but for now I think it is too early
>>> to merge. For the record, I don't think I mentioned the first problem in my
>>> original reply, it's something I noticed yesterday while looking at the patch
>>> again.
>>>
>>>>
>>>> Before this patch, all we have is (1), as a non-dynamic printk is too
>>>> intrusive to be used for performance measurement. So, there's no way to
>>>> measure how much time a buffer takes to be filled.
>>>
>>> Having tracepoints here doesn't tell you anything about that. At best it gives
>>> you information about the jitter.
>>>
>>> How are these tracepoints supposed to be used? What information will they
>>> provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
>>> ioctls/fops as well? If so, which ones?
>>
>> As shown above, a performance tool can add handlers for tracepoint data,
>> allowing to discover, for example, if dequeue occurred on a different order
>> than queue, associating each dequeued buffer to the corresponding queued
>> one, and to measure the time between each queue/dequeue pairs.
> 
> I'm not really convinced about it. Which is why I would like to know a bit more
> how Wade uses it.

Put simply, we have an internal tool that can do some analysis of LTTng
formatted traces, and we'd like to use it to do some very simple
performance analyses of some V4L2 devices.  Our analyses really only
need to check queue/dequeue events, primarily for the reason Mauro
stated, measuring the time between such pairs.  Therefore, this is in no
way meant to be an exhaustive implementation, but it certainly could be
a starting point for such.

> 
> Also: the tracepoint is placed outside the lock which will make any time
> measurements even less reliable than they already are. Also, putting it
> inside the lock will ensure that the traces are generated in the order
> that they are serialized by the lock. In addition, the error code of the
> ioctl isn't traced either. Perhaps the traces should only be done if
> ret == 0 anyway?

I fully admit that my implementation may not be 100% correct, which is
part of the reason why I posted this as an RFC in the first place.

Moving this code inside the lock and adding the return value to the
trace should not be a problem.  If there are other specific things I
need to change to improve the patch, I would happy to do so.

Thanks for the feedback.

Regards,

Wade

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Hans Verkuil]

On 12/11/2013 03:53 PM, Wade Farnsworth wrote:
> Hi Hans,
> 
> Hans Verkuil wrote:
>> On 12/11/13 13:44, Mauro Carvalho Chehab wrote:
>>> Em Wed, 11 Dec 2013 12:53:55 +0100
>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>
>>>> Hi Mauro,
>>>>
>>>> On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
>>>>> Hans,
>>>>>
>>>>> Em Wed, 11 Dec 2013 08:29:58 +0100
>>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>>
>>>>>> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
>>>>>>> Em Sat, 23 Nov 2013 17:54:48 +0100
>>>>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>>>>
>>>>>>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
>>>>>>>>> Hi,
>>>>>>>>>
>>>>>>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>>>>>>>>>> Hi Wade,
>>>>>>>>>>
>>>>>>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>>>>>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>>>>>>>>>> performance measurements using standard kernel tracers.
>>>>>>>>>>>
>>>>>>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>>>>>>>>>> ---
>>>>>>>>>>>
>>>>>>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>>>>>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>>>>>>>>>
>>>>>>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>>>>>>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>>>>>>>>>
>>>>>>>>>> So this code basically duplicates that functionality. It would be nice to be able
>>>>>>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
>>>>>>>>>
>>>>>>>>> I think it would be really nice to have this kind of support for standard
>>>>>>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
>>>>>>>>> the v4l2 custom debug infrastructure.
>>>>>>>>>
>>>>>>>>> If I understand things correctly, the current tracing/profiling 
>>>>>>>>> infrastructure
>>>>>>>>> is much less invasive than inserting printks all over, which may cause 
>>>>>>>>> changes
>>>>>>>>> in control flow. I doubt the system could be reliably profiled by 
>>>>>>>>> enabling all
>>>>>>>>> those debug prints.
>>>>>>>>>
>>>>>>>>> So my vote would be to add support for standard tracers, like in other
>>>>>>>>> subsystems in the kernel.
>>>>>>>>
>>>>>>>> The reason for the current system is to trace which ioctls are called in
>>>>>>>> what order by a misbehaving application. It's very useful for that,
>>>>>>>> especially when trying to debug user problems.
>>>>>>>>
>>>>>>>> I don't mind switching to tracepoints as long as this functionality is
>>>>>>>> kept one way or another.
>>>>>>>
>>>>>>> I agree with Sylwester: we should move to tracepoints, and this is a good
>>>>>>> start.
>>>>>>
>>>>>> As I mentioned, I don't mind switching to tracepoints, but not in the way the
>>>>>> current patch does it. I certainly don't agree with you merging this patch
>>>>>> as-is without further discussion.
>>>>>
>>>>> Let's not mix the subjects here. There are two different demands that can be
>>>>> either fulfilled by the same solution or by different ones:
>>>>> 	1) To have a way to enable debugging all parameters passed from/to
>>>>> userspace;
>>>>> 	2) To be able to measure the driver (and core) performance while
>>>>> streaming.
>>>>>
>>>>> This patch's scope is to solve (2), by allowing userspace to hook the two
>>>>> ioctls that queues/dequeues streaming buffers.
>>>>>
>>>>> With that regards, what's wrong on this patch? I couldn't see anything bad
>>>>> there. It is not meant to solve (1).
>>>>
>>>> I have two problems with it: 
>>>>
>>>> 1) Right now it is just checking for two ioctls, but as soon as we add more
>>>> tracepoints you get another switch on the ioctl command, something I've tried
>>>> to avoid by creating the table. So a table-oriented implementation would be
>>>> much preferred.
>>>
>>> From performance measurement PoV, I don't see any reason to add it to any
>>> other ioctl.
>>
>> But perhaps this makes sense as well for read() and write()? Possibly poll()?
>>
>>> Of course if we revisit it and other traces become needed,
>>> then we should use a table approach instead.
>>>
>>>>
>>>> 2) It duplicates the already existing code to dump the v4l2_buffer struct.
>>>> Is there a way to have just one copy of that? I was hoping Wade could look
>>>> into that, and if not, then it is something I can explore (although finding
>>>> time is an issue).
>>>
>>> Having implemented tracepoints myself, I'd say that the answer is no.
>>>
>>> Let me give you an example.
>>>
>>> The ras:aer_event trace is a simple tracepoint that also uses the 
>>> __print_flags() macro. It is implemented at include/trace/events/ras.h
>>> as:
>>>
>>> #define aer_correctable_errors		\
>>> 	{BIT(0),	"Receiver Error"},		\
>>> 	{BIT(6),	"Bad TLP"},			\
>>> 	{BIT(7),	"Bad DLLP"},			\
>>> 	{BIT(8),	"RELAY_NUM Rollover"},		\
>>> 	{BIT(12),	"Replay Timer Timeout"},	\
>>> 	{BIT(13),	"Advisory Non-Fatal"}
>>>
>>> #define aer_uncorrectable_errors		\
>>> 	{BIT(4),	"Data Link Protocol"},		\
>>> 	{BIT(12),	"Poisoned TLP"},		\
>>> 	{BIT(13),	"Flow Control Protocol"},	\
>>> 	{BIT(14),	"Completion Timeout"},		\
>>> 	{BIT(15),	"Completer Abort"},		\
>>> 	{BIT(16),	"Unexpected Completion"},	\
>>> 	{BIT(17),	"Receiver Overflow"},		\
>>> 	{BIT(18),	"Malformed TLP"},		\
>>> 	{BIT(19),	"ECRC"},			\
>>> 	{BIT(20),	"Unsupported Request"}
>>>
>>> TRACE_EVENT(aer_event,
>>> 	TP_PROTO(const char *dev_name,
>>> 		 const u32 status,
>>> 		 const u8 severity),
>>>
>>> 	TP_ARGS(dev_name, status, severity),
>>>
>>> 	TP_STRUCT__entry(
>>> 		__string(	dev_name,	dev_name	)
>>> 		__field(	u32,		status		)
>>> 		__field(	u8,		severity	)
>>> 	),
>>>
>>> 	TP_fast_assign(
>>> 		__assign_str(dev_name, dev_name);
>>> 		__entry->status		= status;
>>> 		__entry->severity	= severity;
>>> 	),
>>>
>>> 	TP_printk("%s PCIe Bus Error: severity=%s, %s\n",
>>> 		__get_str(dev_name),
>>> 		__entry->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" :
>>> 			__entry->severity == HW_EVENT_ERR_FATAL ?
>>> 			"Fatal" : "Uncorrected",
>>> 		__entry->severity == HW_EVENT_ERR_CORRECTED ?
>>> 		__print_flags(__entry->status, "|", aer_correctable_errors) :
>>> 		__print_flags(__entry->status, "|", aer_uncorrectable_errors))
>>>
>>>
>>> Tracepoints work by having a binary ringbuffer where the data at TP_STRUCT
>>> is passed. In this case, it passes a string, an u32 and an u8.
>>>
>>> The TP_printk() macro actually produces a format filenode, describing
>>> each field that would be filled in the ringbuffer and how to convert the
>>> data structure from binary to text:
>>>
>>> # cat /sys/kernel/debug/tracing/events/ras/aer_event/format 
>>> name: aer_event
>>> ID: 877
>>> format:
>>> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
>>> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
>>> 	field:unsigned char common_preempt_count;	offset:3;	size:1;signed:0;
>>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>>
>>> 	field:__data_loc char[] dev_name;	offset:8;	size:4;	signed:1;
>>> 	field:u32 status;	offset:12;	size:4;	signed:0;
>>> 	field:u8 severity;	offset:16;	size:1;	signed:0;
>>>
>>> print fmt: "%s PCIe Bus Error: severity=%s, %s
>>> ", __get_str(dev_name), REC->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" : REC->severity == HW_EVENT_ERR_FATAL ? "Fatal" : "Uncorrected", REC->severity == HW_EVENT_ERR_CORRECTED ? __print_flags(REC->status, "|", {(1UL << (0)), "Receiver Error"}, {(1UL << (6)), "Bad TLP"}, {(1UL << (7)), "Bad DLLP"}, {(1UL << (8)), "RELAY_NUM Rollover"}, {(1UL << (12)), "Replay Timer Timeout"}, {(1UL << (13)), "Advisory Non-Fatal"}) : __print_flags(REC->status, "|", {(1UL << (4)), "Data Link Protocol"}, {(1UL << (12)), "Poisoned TLP"}, {(1UL << (13)), "Flow Control Protocol"}, {(1UL << (14)), "Completion Timeout"}, {(1UL << (15)), "Completer Abort"}, {(1UL << (16)), "Unexpected Completion"}, {(1UL << (17)), "Receiver Overflow"}, {(1UL << (18)), "Malformed TLP"}, {(1UL << (19)), "ECRC"}, {(1UL << (20)), "Unsupported Request"})
>>>
>>> You can see that _print_flags() actually produced a lot of code inside "print fmt".
>>>
>>> When someone reads from /sys/kernel/debug/tracing/trace, the print fmt is
>>> handled by the Kernel.
>>>
>>> However, when someone uses a performance tool like perf, the binary blobs
>>> are read from the per-CPU raw trace filenodes:
>>> 	/sys/kernel/debug/tracing/per_cpu/cpu*/trace_pipe_raw
>>>
>>> And the "print fmt" line at the format file is actually used as a hint
>>> for tracing userspace tool to handle it that can be used or not.
>>> For example, at the rasdaemon, I'm overriding all default handlers,
>>> using my own handler, as I want to store all events on a sqlite database:
>>>
>>> 	https://git.fedorahosted.org/cgit/rasdaemon.git/tree/ras-aer-handler.c
>>
>> OK, fair enough. So that code can't be shared. Good to know.
>>
>>>
>>>>
>>>> Bottom line as far as I am concerned: it was merged while I have outstanding
>>>> questions.
>>>
>>> Well, only on this email you're letting clear what are your concerns.
>>>
>>>> If there are good technical reasons why the two problems stated above can't
>>>> be easily resolved, then I will reconsider, but for now I think it is too early
>>>> to merge. For the record, I don't think I mentioned the first problem in my
>>>> original reply, it's something I noticed yesterday while looking at the patch
>>>> again.
>>>>
>>>>>
>>>>> Before this patch, all we have is (1), as a non-dynamic printk is too
>>>>> intrusive to be used for performance measurement. So, there's no way to
>>>>> measure how much time a buffer takes to be filled.
>>>>
>>>> Having tracepoints here doesn't tell you anything about that. At best it gives
>>>> you information about the jitter.
>>>>
>>>> How are these tracepoints supposed to be used? What information will they
>>>> provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
>>>> ioctls/fops as well? If so, which ones?
>>>
>>> As shown above, a performance tool can add handlers for tracepoint data,
>>> allowing to discover, for example, if dequeue occurred on a different order
>>> than queue, associating each dequeued buffer to the corresponding queued
>>> one, and to measure the time between each queue/dequeue pairs.
>>
>> I'm not really convinced about it. Which is why I would like to know a bit more
>> how Wade uses it.
> 
> Put simply, we have an internal tool that can do some analysis of LTTng
> formatted traces, and we'd like to use it to do some very simple
> performance analyses of some V4L2 devices.  Our analyses really only
> need to check queue/dequeue events, primarily for the reason Mauro
> stated, measuring the time between such pairs.  Therefore, this is in no
> way meant to be an exhaustive implementation, but it certainly could be
> a starting point for such.
> 
>>
>> Also: the tracepoint is placed outside the lock which will make any time
>> measurements even less reliable than they already are. Also, putting it
>> inside the lock will ensure that the traces are generated in the order
>> that they are serialized by the lock. In addition, the error code of the
>> ioctl isn't traced either. Perhaps the traces should only be done if
>> ret == 0 anyway?
> 
> I fully admit that my implementation may not be 100% correct, which is
> part of the reason why I posted this as an RFC in the first place.
> 
> Moving this code inside the lock and adding the return value to the
> trace should not be a problem.  If there are other specific things I
> need to change to improve the patch, I would happy to do so.

Thanks Wade!

I plan on taking a closer look tomorrow or Monday (probably tomorrow) and
I might write a patch myself moving things around.

One question: would it make sense to only do the trace if the (d)qbuf
call was successful? I don't really see much purpose in doing the trace
if an error occurred, certainly not from a performance PoV.

But I don't have a strong opinion on this, so if you prefer to always
trace it, then that's not a problem.

Regards,

	Hans

Re: [PATCH] v4l2-dev: Add tracepoints for QBUF and DQBUF

[Wade Farnsworth]

Hans Verkuil wrote:
> On 12/11/2013 03:53 PM, Wade Farnsworth wrote:
>> Hi Hans,
>>
>> Hans Verkuil wrote:
>>> On 12/11/13 13:44, Mauro Carvalho Chehab wrote:
>>>> Em Wed, 11 Dec 2013 12:53:55 +0100
>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>
>>>>> Hi Mauro,
>>>>>
>>>>> On 12/11/13 11:44, Mauro Carvalho Chehab wrote:
>>>>>> Hans,
>>>>>>
>>>>>> Em Wed, 11 Dec 2013 08:29:58 +0100
>>>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>>>
>>>>>>> On 12/10/2013 09:53 PM, Mauro Carvalho Chehab wrote:
>>>>>>>> Em Sat, 23 Nov 2013 17:54:48 +0100
>>>>>>>> Hans Verkuil <hverkuil@xs4all.nl> escreveu:
>>>>>>>>
>>>>>>>>> On 11/23/2013 05:30 PM, Sylwester Nawrocki wrote:
>>>>>>>>>> Hi,
>>>>>>>>>>
>>>>>>>>>> On 11/23/2013 12:25 PM, Hans Verkuil wrote:
>>>>>>>>>>> Hi Wade,
>>>>>>>>>>>
>>>>>>>>>>> On 11/22/2013 08:48 PM, Wade Farnsworth wrote:
>>>>>>>>>>>> Add tracepoints to the QBUF and DQBUF ioctls to enable rudimentary
>>>>>>>>>>>> performance measurements using standard kernel tracers.
>>>>>>>>>>>>
>>>>>>>>>>>> Signed-off-by: Wade Farnsworth<wade_farnsworth@mentor.com>
>>>>>>>>>>>> ---
>>>>>>>>>>>>
>>>>>>>>>>>> This is the update to the RFC patch I posted a few weeks back.  I've added
>>>>>>>>>>>> several bits of metadata to the tracepoint output per Mauro's suggestion.
>>>>>>>>>>>
>>>>>>>>>>> I don't like this. All v4l2 ioctls can already be traced by doing e.g.
>>>>>>>>>>> echo 1 (or echo 2)>/sys/class/video4linux/video0/debug.
>>>>>>>>>>>
>>>>>>>>>>> So this code basically duplicates that functionality. It would be nice to be able
>>>>>>>>>>> to tie in the existing tracing code (v4l2-ioctl.c) into tracepoints.
>>>>>>>>>>
>>>>>>>>>> I think it would be really nice to have this kind of support for standard
>>>>>>>>>> traces at the v4l2 subsystem. Presumably it could even gradually replace
>>>>>>>>>> the v4l2 custom debug infrastructure.
>>>>>>>>>>
>>>>>>>>>> If I understand things correctly, the current tracing/profiling 
>>>>>>>>>> infrastructure
>>>>>>>>>> is much less invasive than inserting printks all over, which may cause 
>>>>>>>>>> changes
>>>>>>>>>> in control flow. I doubt the system could be reliably profiled by 
>>>>>>>>>> enabling all
>>>>>>>>>> those debug prints.
>>>>>>>>>>
>>>>>>>>>> So my vote would be to add support for standard tracers, like in other
>>>>>>>>>> subsystems in the kernel.
>>>>>>>>>
>>>>>>>>> The reason for the current system is to trace which ioctls are called in
>>>>>>>>> what order by a misbehaving application. It's very useful for that,
>>>>>>>>> especially when trying to debug user problems.
>>>>>>>>>
>>>>>>>>> I don't mind switching to tracepoints as long as this functionality is
>>>>>>>>> kept one way or another.
>>>>>>>>
>>>>>>>> I agree with Sylwester: we should move to tracepoints, and this is a good
>>>>>>>> start.
>>>>>>>
>>>>>>> As I mentioned, I don't mind switching to tracepoints, but not in the way the
>>>>>>> current patch does it. I certainly don't agree with you merging this patch
>>>>>>> as-is without further discussion.
>>>>>>
>>>>>> Let's not mix the subjects here. There are two different demands that can be
>>>>>> either fulfilled by the same solution or by different ones:
>>>>>> 	1) To have a way to enable debugging all parameters passed from/to
>>>>>> userspace;
>>>>>> 	2) To be able to measure the driver (and core) performance while
>>>>>> streaming.
>>>>>>
>>>>>> This patch's scope is to solve (2), by allowing userspace to hook the two
>>>>>> ioctls that queues/dequeues streaming buffers.
>>>>>>
>>>>>> With that regards, what's wrong on this patch? I couldn't see anything bad
>>>>>> there. It is not meant to solve (1).
>>>>>
>>>>> I have two problems with it: 
>>>>>
>>>>> 1) Right now it is just checking for two ioctls, but as soon as we add more
>>>>> tracepoints you get another switch on the ioctl command, something I've tried
>>>>> to avoid by creating the table. So a table-oriented implementation would be
>>>>> much preferred.
>>>>
>>>> From performance measurement PoV, I don't see any reason to add it to any
>>>> other ioctl.
>>>
>>> But perhaps this makes sense as well for read() and write()? Possibly poll()?
>>>
>>>> Of course if we revisit it and other traces become needed,
>>>> then we should use a table approach instead.
>>>>
>>>>>
>>>>> 2) It duplicates the already existing code to dump the v4l2_buffer struct.
>>>>> Is there a way to have just one copy of that? I was hoping Wade could look
>>>>> into that, and if not, then it is something I can explore (although finding
>>>>> time is an issue).
>>>>
>>>> Having implemented tracepoints myself, I'd say that the answer is no.
>>>>
>>>> Let me give you an example.
>>>>
>>>> The ras:aer_event trace is a simple tracepoint that also uses the 
>>>> __print_flags() macro. It is implemented at include/trace/events/ras.h
>>>> as:
>>>>
>>>> #define aer_correctable_errors		\
>>>> 	{BIT(0),	"Receiver Error"},		\
>>>> 	{BIT(6),	"Bad TLP"},			\
>>>> 	{BIT(7),	"Bad DLLP"},			\
>>>> 	{BIT(8),	"RELAY_NUM Rollover"},		\
>>>> 	{BIT(12),	"Replay Timer Timeout"},	\
>>>> 	{BIT(13),	"Advisory Non-Fatal"}
>>>>
>>>> #define aer_uncorrectable_errors		\
>>>> 	{BIT(4),	"Data Link Protocol"},		\
>>>> 	{BIT(12),	"Poisoned TLP"},		\
>>>> 	{BIT(13),	"Flow Control Protocol"},	\
>>>> 	{BIT(14),	"Completion Timeout"},		\
>>>> 	{BIT(15),	"Completer Abort"},		\
>>>> 	{BIT(16),	"Unexpected Completion"},	\
>>>> 	{BIT(17),	"Receiver Overflow"},		\
>>>> 	{BIT(18),	"Malformed TLP"},		\
>>>> 	{BIT(19),	"ECRC"},			\
>>>> 	{BIT(20),	"Unsupported Request"}
>>>>
>>>> TRACE_EVENT(aer_event,
>>>> 	TP_PROTO(const char *dev_name,
>>>> 		 const u32 status,
>>>> 		 const u8 severity),
>>>>
>>>> 	TP_ARGS(dev_name, status, severity),
>>>>
>>>> 	TP_STRUCT__entry(
>>>> 		__string(	dev_name,	dev_name	)
>>>> 		__field(	u32,		status		)
>>>> 		__field(	u8,		severity	)
>>>> 	),
>>>>
>>>> 	TP_fast_assign(
>>>> 		__assign_str(dev_name, dev_name);
>>>> 		__entry->status		= status;
>>>> 		__entry->severity	= severity;
>>>> 	),
>>>>
>>>> 	TP_printk("%s PCIe Bus Error: severity=%s, %s\n",
>>>> 		__get_str(dev_name),
>>>> 		__entry->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" :
>>>> 			__entry->severity == HW_EVENT_ERR_FATAL ?
>>>> 			"Fatal" : "Uncorrected",
>>>> 		__entry->severity == HW_EVENT_ERR_CORRECTED ?
>>>> 		__print_flags(__entry->status, "|", aer_correctable_errors) :
>>>> 		__print_flags(__entry->status, "|", aer_uncorrectable_errors))
>>>>
>>>>
>>>> Tracepoints work by having a binary ringbuffer where the data at TP_STRUCT
>>>> is passed. In this case, it passes a string, an u32 and an u8.
>>>>
>>>> The TP_printk() macro actually produces a format filenode, describing
>>>> each field that would be filled in the ringbuffer and how to convert the
>>>> data structure from binary to text:
>>>>
>>>> # cat /sys/kernel/debug/tracing/events/ras/aer_event/format 
>>>> name: aer_event
>>>> ID: 877
>>>> format:
>>>> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
>>>> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
>>>> 	field:unsigned char common_preempt_count;	offset:3;	size:1;signed:0;
>>>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>>>
>>>> 	field:__data_loc char[] dev_name;	offset:8;	size:4;	signed:1;
>>>> 	field:u32 status;	offset:12;	size:4;	signed:0;
>>>> 	field:u8 severity;	offset:16;	size:1;	signed:0;
>>>>
>>>> print fmt: "%s PCIe Bus Error: severity=%s, %s
>>>> ", __get_str(dev_name), REC->severity == HW_EVENT_ERR_CORRECTED ? "Corrected" : REC->severity == HW_EVENT_ERR_FATAL ? "Fatal" : "Uncorrected", REC->severity == HW_EVENT_ERR_CORRECTED ? __print_flags(REC->status, "|", {(1UL << (0)), "Receiver Error"}, {(1UL << (6)), "Bad TLP"}, {(1UL << (7)), "Bad DLLP"}, {(1UL << (8)), "RELAY_NUM Rollover"}, {(1UL << (12)), "Replay Timer Timeout"}, {(1UL << (13)), "Advisory Non-Fatal"}) : __print_flags(REC->status, "|", {(1UL << (4)), "Data Link Protocol"}, {(1UL << (12)), "Poisoned TLP"}, {(1UL << (13)), "Flow Control Protocol"}, {(1UL << (14)), "Completion Timeout"}, {(1UL << (15)), "Completer Abort"}, {(1UL << (16)), "Unexpected Completion"}, {(1UL << (17)), "Receiver Overflow"}, {(1UL << (18)), "Malformed TLP"}, {(1UL << (19)), "ECRC"}, {(1UL << (20)), "Unsupported Request"})
>>>>
>>>> You can see that _print_flags() actually produced a lot of code inside "print fmt".
>>>>
>>>> When someone reads from /sys/kernel/debug/tracing/trace, the print fmt is
>>>> handled by the Kernel.
>>>>
>>>> However, when someone uses a performance tool like perf, the binary blobs
>>>> are read from the per-CPU raw trace filenodes:
>>>> 	/sys/kernel/debug/tracing/per_cpu/cpu*/trace_pipe_raw
>>>>
>>>> And the "print fmt" line at the format file is actually used as a hint
>>>> for tracing userspace tool to handle it that can be used or not.
>>>> For example, at the rasdaemon, I'm overriding all default handlers,
>>>> using my own handler, as I want to store all events on a sqlite database:
>>>>
>>>> 	https://git.fedorahosted.org/cgit/rasdaemon.git/tree/ras-aer-handler.c
>>>
>>> OK, fair enough. So that code can't be shared. Good to know.
>>>
>>>>
>>>>>
>>>>> Bottom line as far as I am concerned: it was merged while I have outstanding
>>>>> questions.
>>>>
>>>> Well, only on this email you're letting clear what are your concerns.
>>>>
>>>>> If there are good technical reasons why the two problems stated above can't
>>>>> be easily resolved, then I will reconsider, but for now I think it is too early
>>>>> to merge. For the record, I don't think I mentioned the first problem in my
>>>>> original reply, it's something I noticed yesterday while looking at the patch
>>>>> again.
>>>>>
>>>>>>
>>>>>> Before this patch, all we have is (1), as a non-dynamic printk is too
>>>>>> intrusive to be used for performance measurement. So, there's no way to
>>>>>> measure how much time a buffer takes to be filled.
>>>>>
>>>>> Having tracepoints here doesn't tell you anything about that. At best it gives
>>>>> you information about the jitter.
>>>>>
>>>>> How are these tracepoints supposed to be used? What information will they
>>>>> provide? Are tracepoints expected to be limited to QBUF/DQBUF? Or other
>>>>> ioctls/fops as well? If so, which ones?
>>>>
>>>> As shown above, a performance tool can add handlers for tracepoint data,
>>>> allowing to discover, for example, if dequeue occurred on a different order
>>>> than queue, associating each dequeued buffer to the corresponding queued
>>>> one, and to measure the time between each queue/dequeue pairs.
>>>
>>> I'm not really convinced about it. Which is why I would like to know a bit more
>>> how Wade uses it.
>>
>> Put simply, we have an internal tool that can do some analysis of LTTng
>> formatted traces, and we'd like to use it to do some very simple
>> performance analyses of some V4L2 devices.  Our analyses really only
>> need to check queue/dequeue events, primarily for the reason Mauro
>> stated, measuring the time between such pairs.  Therefore, this is in no
>> way meant to be an exhaustive implementation, but it certainly could be
>> a starting point for such.
>>
>>>
>>> Also: the tracepoint is placed outside the lock which will make any time
>>> measurements even less reliable than they already are. Also, putting it
>>> inside the lock will ensure that the traces are generated in the order
>>> that they are serialized by the lock. In addition, the error code of the
>>> ioctl isn't traced either. Perhaps the traces should only be done if
>>> ret == 0 anyway?
>>
>> I fully admit that my implementation may not be 100% correct, which is
>> part of the reason why I posted this as an RFC in the first place.
>>
>> Moving this code inside the lock and adding the return value to the
>> trace should not be a problem.  If there are other specific things I
>> need to change to improve the patch, I would happy to do so.
> 
> Thanks Wade!
> 
> I plan on taking a closer look tomorrow or Monday (probably tomorrow) and
> I might write a patch myself moving things around.

That would be great!

> 
> One question: would it make sense to only do the trace if the (d)qbuf
> call was successful? I don't really see much purpose in doing the trace
> if an error occurred, certainly not from a performance PoV.
> 
> But I don't have a strong opinion on this, so if you prefer to always
> trace it, then that's not a problem.
> 

For our purposes it would work either way.  The analysis should not
include failed (d)qbufs, so whether they are dropped at trace time, or
the error code is read by the tool, then dropped, it would not make much
difference.

If you prefer to drop them at trace time, that's fine by me.

Thanks again,

-Wade