diff mbox

[1/2] Add TRACE_EVENTs in pwc_isoc_handler()

Message ID 20180617143625.32133-1-matwey@sai.msu.ru (mailing list archive)
State New, archived
Headers show

Commit Message

Matwey V. Kornilov June 17, 2018, 2:36 p.m. UTC 
Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru>
---
 drivers/media/usb/pwc/pwc-if.c |  7 +++++++
 include/trace/events/pwc.h     | 45 ++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 52 insertions(+)
 create mode 100644 include/trace/events/pwc.h

Comments

Steven Rostedt June 18, 2018, 6:58 p.m. UTC | #1 
On Sun, 17 Jun 2018 17:36:24 +0300
"Matwey V. Kornilov" <matwey@sai.msu.ru> wrote:

I would prefer a change log here that would explain why these
tracepoints are being added.


> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru>
> ---
>  drivers/media/usb/pwc/pwc-if.c |  7 +++++++
>  include/trace/events/pwc.h     | 45 ++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 52 insertions(+)
>  create mode 100644 include/trace/events/pwc.h
> 
> diff --git a/drivers/media/usb/pwc/pwc-if.c b/drivers/media/usb/pwc/pwc-if.c
> index 54b036d39c5b..5775d1f60668 100644
> --- a/drivers/media/usb/pwc/pwc-if.c
> +++ b/drivers/media/usb/pwc/pwc-if.c
> @@ -57,6 +57,9 @@
>     - Pham Thanh Nam: webcam snapshot button as an event input device
>  */
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/pwc.h>
> +
>  #include <linux/errno.h>
>  #include <linux/init.h>
>  #include <linux/mm.h>
> @@ -260,6 +263,8 @@ static void pwc_isoc_handler(struct urb *urb)
>  	int i, fst, flen;
>  	unsigned char *iso_buf = NULL;
>  
> +	trace_pwc_handler_enter(urb);
> +
>  	if (urb->status == -ENOENT || urb->status == -ECONNRESET ||
>  	    urb->status == -ESHUTDOWN) {
>  		PWC_DEBUG_OPEN("URB (%p) unlinked %ssynchronously.\n",

Looks like if this is hit, we will return from the function without
calling trace_pwc_handler_exit().

> @@ -347,6 +352,8 @@ static void pwc_isoc_handler(struct urb *urb)
>  		pdev->vlast_packet_size = flen;
>  	}
>  
> +	trace_pwc_handler_exit(urb);
> +
>  handler_end:

Why not add the tracepoint after handler_end. In fact, why not add some
exit status to the trace event? I would think that would be useful as
well.


>  	i = usb_submit_urb(urb, GFP_ATOMIC);
>  	if (i != 0)
> diff --git a/include/trace/events/pwc.h b/include/trace/events/pwc.h
> new file mode 100644
> index 000000000000..b13d2118bb7a
> --- /dev/null
> +++ b/include/trace/events/pwc.h
> @@ -0,0 +1,45 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +#if !defined(_TRACE_PWC_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_PWC_H
> +
> +#include <linux/usb.h>
> +#include <linux/tracepoint.h>
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM pwc
> +
> +TRACE_EVENT(pwc_handler_enter,
> +	TP_PROTO(struct urb *urb),
> +	TP_ARGS(urb),
> +	TP_STRUCT__entry(
> +		__field(struct urb*, urb)
> +		__field(int, urb__status)
> +		__field(u32, urb__actual_length)
> +	),
> +	TP_fast_assign(
> +		__entry->urb = urb;
> +		__entry->urb__status = urb->status;
> +		__entry->urb__actual_length = urb->actual_length;

Is there any other data that may be interesting to record here?

-- Steve

> +	),
> +	TP_printk("urb=%p (status=%d actual_length=%u)",
> +		__entry->urb,
> +		__entry->urb__status,
> +		__entry->urb__actual_length)
> +);
> +
> +TRACE_EVENT(pwc_handler_exit,
> +	TP_PROTO(struct urb *urb),
> +	TP_ARGS(urb),
> +	TP_STRUCT__entry(
> +		__field(struct urb*, urb)
> +	),
> +	TP_fast_assign(
> +		__entry->urb = urb;
> +	),
> +	TP_printk("urb=%p", __entry->urb)
> +);
> +
> +#endif /* _TRACE_PWC_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
Matwey V. Kornilov June 19, 2018, 4:23 p.m. UTC | #2 
Hi Steven,

Thank you for valuable comments.

This is for measuring performance of URB completion callback inside PWC driver.
What do you think about moving events to __usb_hcd_giveback_urb() in
order to make this more generic? Like the following:

        local_irq_save(flags);
// trace urb complete enter
        urb->complete(urb);
// trace urb complete exit
        local_irq_restore(flags);


2018-06-18 21:58 GMT+03:00 Steven Rostedt <rostedt@goodmis.org>:
> On Sun, 17 Jun 2018 17:36:24 +0300
> "Matwey V. Kornilov" <matwey@sai.msu.ru> wrote:
>
> I would prefer a change log here that would explain why these
> tracepoints are being added.
>
>
>> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru>
>> ---
>>  drivers/media/usb/pwc/pwc-if.c |  7 +++++++
>>  include/trace/events/pwc.h     | 45 ++++++++++++++++++++++++++++++++++++++++++
>>  2 files changed, 52 insertions(+)
>>  create mode 100644 include/trace/events/pwc.h
>>
>> diff --git a/drivers/media/usb/pwc/pwc-if.c b/drivers/media/usb/pwc/pwc-if.c
>> index 54b036d39c5b..5775d1f60668 100644
>> --- a/drivers/media/usb/pwc/pwc-if.c
>> +++ b/drivers/media/usb/pwc/pwc-if.c
>> @@ -57,6 +57,9 @@
>>     - Pham Thanh Nam: webcam snapshot button as an event input device
>>  */
>>
>> +#define CREATE_TRACE_POINTS
>> +#include <trace/events/pwc.h>
>> +
>>  #include <linux/errno.h>
>>  #include <linux/init.h>
>>  #include <linux/mm.h>
>> @@ -260,6 +263,8 @@ static void pwc_isoc_handler(struct urb *urb)
>>       int i, fst, flen;
>>       unsigned char *iso_buf = NULL;
>>
>> +     trace_pwc_handler_enter(urb);
>> +
>>       if (urb->status == -ENOENT || urb->status == -ECONNRESET ||
>>           urb->status == -ESHUTDOWN) {
>>               PWC_DEBUG_OPEN("URB (%p) unlinked %ssynchronously.\n",
>
> Looks like if this is hit, we will return from the function without
> calling trace_pwc_handler_exit().
>
>> @@ -347,6 +352,8 @@ static void pwc_isoc_handler(struct urb *urb)
>>               pdev->vlast_packet_size = flen;
>>       }
>>
>> +     trace_pwc_handler_exit(urb);
>> +
>>  handler_end:
>
> Why not add the tracepoint after handler_end. In fact, why not add some
> exit status to the trace event? I would think that would be useful as
> well.
>
>
>>       i = usb_submit_urb(urb, GFP_ATOMIC);
>>       if (i != 0)
>> diff --git a/include/trace/events/pwc.h b/include/trace/events/pwc.h
>> new file mode 100644
>> index 000000000000..b13d2118bb7a
>> --- /dev/null
>> +++ b/include/trace/events/pwc.h
>> @@ -0,0 +1,45 @@
>> +/* SPDX-License-Identifier: GPL-2.0 */
>> +#if !defined(_TRACE_PWC_H) || defined(TRACE_HEADER_MULTI_READ)
>> +#define _TRACE_PWC_H
>> +
>> +#include <linux/usb.h>
>> +#include <linux/tracepoint.h>
>> +
>> +#undef TRACE_SYSTEM
>> +#define TRACE_SYSTEM pwc
>> +
>> +TRACE_EVENT(pwc_handler_enter,
>> +     TP_PROTO(struct urb *urb),
>> +     TP_ARGS(urb),
>> +     TP_STRUCT__entry(
>> +             __field(struct urb*, urb)
>> +             __field(int, urb__status)
>> +             __field(u32, urb__actual_length)
>> +     ),
>> +     TP_fast_assign(
>> +             __entry->urb = urb;
>> +             __entry->urb__status = urb->status;
>> +             __entry->urb__actual_length = urb->actual_length;
>
> Is there any other data that may be interesting to record here?
>
> -- Steve
>
>> +     ),
>> +     TP_printk("urb=%p (status=%d actual_length=%u)",
>> +             __entry->urb,
>> +             __entry->urb__status,
>> +             __entry->urb__actual_length)
>> +);
>> +
>> +TRACE_EVENT(pwc_handler_exit,
>> +     TP_PROTO(struct urb *urb),
>> +     TP_ARGS(urb),
>> +     TP_STRUCT__entry(
>> +             __field(struct urb*, urb)
>> +     ),
>> +     TP_fast_assign(
>> +             __entry->urb = urb;
>> +     ),
>> +     TP_printk("urb=%p", __entry->urb)
>> +);
>> +
>> +#endif /* _TRACE_PWC_H */
>> +
>> +/* This part must be outside protection */
>> +#include <trace/define_trace.h>
>
Steven Rostedt June 19, 2018, 4:33 p.m. UTC | #3 
On Tue, 19 Jun 2018 19:23:04 +0300
"Matwey V. Kornilov" <matwey@sai.msu.ru> wrote:

> Hi Steven,
> 
> Thank you for valuable comments.
> 
> This is for measuring performance of URB completion callback inside PWC driver.
> What do you think about moving events to __usb_hcd_giveback_urb() in
> order to make this more generic? Like the following:
> 
>         local_irq_save(flags);
> // trace urb complete enter
>         urb->complete(urb);
> // trace urb complete exit
>         local_irq_restore(flags);
> 
> 

If that can work for you, I'm fine with that. Trace events may be
cheap, but they do come with some cost. I'd like to have all trace
events be as valuable as possible, and limit the "special case" ones.

-- Steve
Matwey V. Kornilov June 20, 2018, 8:05 a.m. UTC | #4 
2018-06-19 19:33 GMT+03:00 Steven Rostedt <rostedt@goodmis.org>:
> On Tue, 19 Jun 2018 19:23:04 +0300
> "Matwey V. Kornilov" <matwey@sai.msu.ru> wrote:
>
>> Hi Steven,
>>
>> Thank you for valuable comments.
>>
>> This is for measuring performance of URB completion callback inside PWC driver.
>> What do you think about moving events to __usb_hcd_giveback_urb() in
>> order to make this more generic? Like the following:
>>
>>         local_irq_save(flags);
>> // trace urb complete enter
>>         urb->complete(urb);
>> // trace urb complete exit
>>         local_irq_restore(flags);
>>
>>
>
> If that can work for you, I'm fine with that. Trace events may be
> cheap, but they do come with some cost. I'd like to have all trace
> events be as valuable as possible, and limit the "special case" ones.

What is the cost for events? I suppose one conditional check when
trace is disabled? There is already similar debugging stuff related to
usbmon in __usb_hcd_giveback_urb(), so I don't think that another
conditional check will hurt performance dramatically there. When
discussing second patch in this series I see that the issue that it is
intended to resolve may be common to other USB media drivers.


>
> -- Steve
>
Steven Rostedt June 20, 2018, 1:09 p.m. UTC | #5 
On Wed, 20 Jun 2018 11:05:51 +0300
"Matwey V. Kornilov" <matwey@sai.msu.ru> wrote:


> > If that can work for you, I'm fine with that. Trace events may be
> > cheap, but they do come with some cost. I'd like to have all trace
> > events be as valuable as possible, and limit the "special case" ones.  
> 
> What is the cost for events? I suppose one conditional check when
> trace is disabled? There is already similar debugging stuff related to
> usbmon in __usb_hcd_giveback_urb(), so I don't think that another
> conditional check will hurt performance dramatically there. When
> discussing second patch in this series I see that the issue that it is
> intended to resolve may be common to other USB media drivers.

The cost isn't just about performance. In fact, the performance
overhead of trace events is pretty negligible. The cost I'm worried
about is bloat. Each event can take up to 5K of memory. That can add up
quickly when we add a bunch of events without thinking about that cost.

-- Steve
diff mbox

Patch

diff --git a/drivers/media/usb/pwc/pwc-if.c b/drivers/media/usb/pwc/pwc-if.c
index 54b036d39c5b..5775d1f60668 100644
--- a/drivers/media/usb/pwc/pwc-if.c
+++ b/drivers/media/usb/pwc/pwc-if.c
@@ -57,6 +57,9 @@ 
    - Pham Thanh Nam: webcam snapshot button as an event input device
 */
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/pwc.h>
+
 #include <linux/errno.h>
 #include <linux/init.h>
 #include <linux/mm.h>
@@ -260,6 +263,8 @@  static void pwc_isoc_handler(struct urb *urb)
 	int i, fst, flen;
 	unsigned char *iso_buf = NULL;
 
+	trace_pwc_handler_enter(urb);
+
 	if (urb->status == -ENOENT || urb->status == -ECONNRESET ||
 	    urb->status == -ESHUTDOWN) {
 		PWC_DEBUG_OPEN("URB (%p) unlinked %ssynchronously.\n",
@@ -347,6 +352,8 @@  static void pwc_isoc_handler(struct urb *urb)
 		pdev->vlast_packet_size = flen;
 	}
 
+	trace_pwc_handler_exit(urb);
+
 handler_end:
 	i = usb_submit_urb(urb, GFP_ATOMIC);
 	if (i != 0)
diff --git a/include/trace/events/pwc.h b/include/trace/events/pwc.h
new file mode 100644
index 000000000000..b13d2118bb7a
--- /dev/null
+++ b/include/trace/events/pwc.h
@@ -0,0 +1,45 @@ 
+/* SPDX-License-Identifier: GPL-2.0 */
+#if !defined(_TRACE_PWC_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PWC_H
+
+#include <linux/usb.h>
+#include <linux/tracepoint.h>
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM pwc
+
+TRACE_EVENT(pwc_handler_enter,
+	TP_PROTO(struct urb *urb),
+	TP_ARGS(urb),
+	TP_STRUCT__entry(
+		__field(struct urb*, urb)
+		__field(int, urb__status)
+		__field(u32, urb__actual_length)
+	),
+	TP_fast_assign(
+		__entry->urb = urb;
+		__entry->urb__status = urb->status;
+		__entry->urb__actual_length = urb->actual_length;
+	),
+	TP_printk("urb=%p (status=%d actual_length=%u)",
+		__entry->urb,
+		__entry->urb__status,
+		__entry->urb__actual_length)
+);
+
+TRACE_EVENT(pwc_handler_exit,
+	TP_PROTO(struct urb *urb),
+	TP_ARGS(urb),
+	TP_STRUCT__entry(
+		__field(struct urb*, urb)
+	),
+	TP_fast_assign(
+		__entry->urb = urb;
+	),
+	TP_printk("urb=%p", __entry->urb)
+);
+
+#endif /* _TRACE_PWC_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>