[PATCH] spmi: add command tracepoints for SPMI

[PATCH] spmi: add command tracepoints for SPMI

[Ankit Gupta]

Add tracepoints to retrieve information about read, write
and non-data commands. For performance measurement support
tracepoints are added at the beginning and at the end of
transfers. Following is a list showing the new tracepoint
events. The "cmd" parameter here represents the opcode, SID,
and full 16-bit address.

spmi_write_begin: cmd and data buffer.
spmi_write_end  : cmd and return value.
spmi_read_begin : cmd.
spmi_read_end   : cmd, return value and data buffer.
spmi_cmd        : cmd.

The reason that cmd appears at both the beginning and at
the end event is that SPMI drivers can request commands
concurrently. cmd helps in matching the corresponding
events.

SPMI tracepoints can be enabled like:

echo 1 >/sys/kernel/debug/tracing/events/spmi/enable

and will dump messages that can be viewed in
/sys/kernel/debug/tracing/trace that look like:

... spmi_read_begin: opc=56 sid=00 addr=0x0000
... spmi_read_end: opc=56 sid=00 addr=0x0000 ret=0 len=02 buf=0x[01-40]
... spmi_write_begin: opc=48 sid=00 addr=0x0000 len=3 buf=0x[ff-ff-ff]

Signed-off-by: Ankit Gupta <ankgupta@codeaurora.org>
Signed-off-by: Gilad Avidov <gavidov@codeaurora.org>
Suggested-by: Sagar Dharia <sdharia@codeaurora.org>
---
 drivers/spmi/spmi.c         |  22 ++++++-
 include/trace/events/spmi.h | 136 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 155 insertions(+), 3 deletions(-)
 create mode 100644 include/trace/events/spmi.h

diff --git a/drivers/spmi/spmi.c b/drivers/spmi/spmi.c
index 1d92f51..36fe010 100644
--- a/drivers/spmi/spmi.c
+++ b/drivers/spmi/spmi.c
@@ -21,6 +21,8 @@
 #include <linux/pm_runtime.h>
 
 #include <dt-bindings/spmi/spmi.h>
+#define CREATE_TRACE_POINTS
+#include <trace/events/spmi.h>
 
 static DEFINE_IDA(ctrl_ida);
 
@@ -95,28 +97,42 @@ EXPORT_SYMBOL_GPL(spmi_device_remove);
 static inline int
 spmi_cmd(struct spmi_controller *ctrl, u8 opcode, u8 sid)
 {
+	int ret;
+
 	if (!ctrl || !ctrl->cmd || ctrl->dev.type != &spmi_ctrl_type)
 		return -EINVAL;
 
-	return ctrl->cmd(ctrl, opcode, sid);
+	ret = ctrl->cmd(ctrl, opcode, sid);
+	trace_spmi_cmd(opcode, sid, ret);
+	return ret;
 }
 
 static inline int spmi_read_cmd(struct spmi_controller *ctrl, u8 opcode,
 				u8 sid, u16 addr, u8 *buf, size_t len)
 {
+	int ret;
+
 	if (!ctrl || !ctrl->read_cmd || ctrl->dev.type != &spmi_ctrl_type)
 		return -EINVAL;
 
-	return ctrl->read_cmd(ctrl, opcode, sid, addr, buf, len);
+	trace_spmi_read_begin(opcode, sid, addr);
+	ret = ctrl->read_cmd(ctrl, opcode, sid, addr, buf, len);
+	trace_spmi_read_end(opcode, sid, addr, ret, len, buf);
+	return ret;
 }
 
 static inline int spmi_write_cmd(struct spmi_controller *ctrl, u8 opcode,
 				 u8 sid, u16 addr, const u8 *buf, size_t len)
 {
+	int ret;
+
 	if (!ctrl || !ctrl->write_cmd || ctrl->dev.type != &spmi_ctrl_type)
 		return -EINVAL;
 
-	return ctrl->write_cmd(ctrl, opcode, sid, addr, buf, len);
+	trace_spmi_write_begin(opcode, sid, addr, len, buf);
+	ret = ctrl->write_cmd(ctrl, opcode, sid, addr, buf, len);
+	trace_spmi_write_end(opcode, sid, addr, ret);
+	return ret;
 }
 
 /**
diff --git a/include/trace/events/spmi.h b/include/trace/events/spmi.h
new file mode 100644
index 0000000..241fd1e
--- /dev/null
+++ b/include/trace/events/spmi.h
@@ -0,0 +1,136 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM spmi
+
+#if !defined(_TRACE_SPMI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SPMI_H
+
+#include <linux/spmi.h>
+#include <linux/tracepoint.h>
+
+/*
+ * drivers/spmi/spmi.c
+ */
+
+TRACE_EVENT(spmi_write_begin,
+	TP_PROTO(u8 opcode, u8 sid, u16 addr, u8 len, const u8 *buf),
+	TP_ARGS(opcode, sid, addr, len, buf),
+
+	TP_STRUCT__entry(
+		__field		( u8,         opcode    )
+		__field		( u8,         sid       )
+		__field		( u16,        addr      )
+		__field		( u8,         len       )
+		__dynamic_array	( u8,   buf,  len + 1   )
+	),
+
+	TP_fast_assign(
+		__entry->opcode = opcode;
+		__entry->sid    = sid;
+		__entry->addr   = addr;
+		__entry->len    = len + 1;
+		memcpy(__get_dynamic_array(buf), buf, len + 1);
+	),
+
+	TP_printk("opc=%d sid=%02d addr=0x%04x len=%d buf=0x[%*phD]",
+		  (int)__entry->opcode, (int)__entry->sid,
+		  (int)__entry->addr, (int)__entry->len,
+		  (int)__entry->len, __get_dynamic_array(buf))
+);
+
+TRACE_EVENT(spmi_write_end,
+	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret),
+	TP_ARGS(opcode, sid, addr, ret),
+
+	TP_STRUCT__entry(
+		__field		( u8,         opcode    )
+		__field		( u8,         sid       )
+		__field		( u16,        addr      )
+		__field		( int,        ret       )
+	),
+
+	TP_fast_assign(
+		__entry->opcode = opcode;
+		__entry->sid    = sid;
+		__entry->addr   = addr;
+		__entry->ret    = ret;
+	),
+
+	TP_printk("opc=%d sid=%02d addr=0x%04x ret=%d",
+		  (int)__entry->opcode, (int)__entry->sid,
+		  (int)__entry->addr, __entry->ret)
+);
+
+TRACE_EVENT(spmi_read_begin,
+	TP_PROTO(u8 opcode, u8 sid, u16 addr),
+	TP_ARGS(opcode, sid, addr),
+
+	TP_STRUCT__entry(
+		__field		( u8,         opcode    )
+		__field		( u8,         sid       )
+		__field		( u16,        addr      )
+	),
+
+	TP_fast_assign(
+		__entry->opcode = opcode;
+		__entry->sid    = sid;
+		__entry->addr   = addr;
+	),
+
+	TP_printk("opc=%d sid=%02d addr=0x%04x",
+		  (int)__entry->opcode, (int)__entry->sid,
+		  (int)__entry->addr)
+);
+
+TRACE_EVENT(spmi_read_end,
+	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret, u8 len,
+		 const u8 *buf),
+	TP_ARGS(opcode, sid, addr, ret, len, buf),
+
+	TP_STRUCT__entry(
+		__field		( u8,         opcode    )
+		__field		( u8,         sid       )
+		__field		( u16,        addr      )
+		__field		( int,        ret       )
+		__field		( u8,         len       )
+		__dynamic_array	( u8,   buf,  len + 1   )
+	),
+
+	TP_fast_assign(
+		__entry->opcode = opcode;
+		__entry->sid    = sid;
+		__entry->addr   = addr;
+		__entry->ret    = ret;
+		__entry->len    = len + 1;
+		memcpy(__get_dynamic_array(buf), buf, len + 1);
+	),
+
+	TP_printk("opc=%d sid=%02d addr=0x%04x ret=%d len=%02d buf=0x[%*phD]",
+		  (int)__entry->opcode, (int)__entry->sid,
+		  (int)__entry->addr, __entry->ret, (int)__entry->len,
+		  (int)__entry->len, __get_dynamic_array(buf))
+);
+
+TRACE_EVENT(spmi_cmd,
+	TP_PROTO(u8 opcode, u8 sid, int ret),
+	TP_ARGS(opcode, sid, ret),
+
+	TP_STRUCT__entry(
+		__field		( u8,         opcode    )
+		__field		( u8,         sid       )
+		__field		( int,        ret       )
+	),
+
+	TP_fast_assign(
+		__entry->opcode = opcode;
+		__entry->sid    = sid;
+		__entry->ret    = ret;
+	),
+
+	TP_printk("opc=%d sid=%02d ret=%d", (int)__entry->opcode,
+		  (int)__entry->sid, ret)
+);
+
+#endif /* _TRACE_SPMI_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
1.8.5.2

Re: [PATCH] spmi: add command tracepoints for SPMI

[Stephen Boyd]

+Steven Rostedt

On 05/18/15 14:51, Ankit Gupta wrote:
> Add tracepoints to retrieve information about read, write
> and non-data commands. For performance measurement support
> tracepoints are added at the beginning and at the end of
> transfers. Following is a list showing the new tracepoint
> events. The "cmd" parameter here represents the opcode, SID,
> and full 16-bit address.
>
> spmi_write_begin: cmd and data buffer.
> spmi_write_end  : cmd and return value.
> spmi_read_begin : cmd.
> spmi_read_end   : cmd, return value and data buffer.
> spmi_cmd        : cmd.
>
> The reason that cmd appears at both the beginning and at
> the end event is that SPMI drivers can request commands
> concurrently. cmd helps in matching the corresponding
> events.
>
> SPMI tracepoints can be enabled like:
>
> echo 1 >/sys/kernel/debug/tracing/events/spmi/enable
>
> and will dump messages that can be viewed in
> /sys/kernel/debug/tracing/trace that look like:
>
> ... spmi_read_begin: opc=56 sid=00 addr=0x0000
> ... spmi_read_end: opc=56 sid=00 addr=0x0000 ret=0 len=02 buf=0x[01-40]
> ... spmi_write_begin: opc=48 sid=00 addr=0x0000 len=3 buf=0x[ff-ff-ff]
>
> Signed-off-by: Ankit Gupta <ankgupta@codeaurora.org>
> Signed-off-by: Gilad Avidov <gavidov@codeaurora.org>
> Suggested-by: Sagar Dharia <sdharia@codeaurora.org>
> ---

Your Signed-off-by should be last.

>  drivers/spmi/spmi.c         |  22 ++++++-
>  include/trace/events/spmi.h | 136 ++++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 155 insertions(+), 3 deletions(-)
>  create mode 100644 include/trace/events/spmi.h
>
> diff --git a/drivers/spmi/spmi.c b/drivers/spmi/spmi.c
> index 1d92f51..36fe010 100644
> --- a/drivers/spmi/spmi.c
> +++ b/drivers/spmi/spmi.c
> @@ -21,6 +21,8 @@
>  #include <linux/pm_runtime.h>
>  
>  #include <dt-bindings/spmi/spmi.h>
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/spmi.h>
>  
>  static DEFINE_IDA(ctrl_ida);
>  
> @@ -95,28 +97,42 @@ EXPORT_SYMBOL_GPL(spmi_device_remove);
>  static inline int
>  spmi_cmd(struct spmi_controller *ctrl, u8 opcode, u8 sid)
>  {
> +	int ret;
> +
>  	if (!ctrl || !ctrl->cmd || ctrl->dev.type != &spmi_ctrl_type)
>  		return -EINVAL;
>  
> -	return ctrl->cmd(ctrl, opcode, sid);
> +	ret = ctrl->cmd(ctrl, opcode, sid);
> +	trace_spmi_cmd(opcode, sid, ret);
> +	return ret;
>  }
>  
>  static inline int spmi_read_cmd(struct spmi_controller *ctrl, u8 opcode,
>  				u8 sid, u16 addr, u8 *buf, size_t len)
>  {
> +	int ret;
> +
>  	if (!ctrl || !ctrl->read_cmd || ctrl->dev.type != &spmi_ctrl_type)
>  		return -EINVAL;
>  
> -	return ctrl->read_cmd(ctrl, opcode, sid, addr, buf, len);
> +	trace_spmi_read_begin(opcode, sid, addr);
> +	ret = ctrl->read_cmd(ctrl, opcode, sid, addr, buf, len);
> +	trace_spmi_read_end(opcode, sid, addr, ret, len, buf);
> +	return ret;
>  }
>  
>  static inline int spmi_write_cmd(struct spmi_controller *ctrl, u8 opcode,
>  				 u8 sid, u16 addr, const u8 *buf, size_t len)
>  {
> +	int ret;
> +
>  	if (!ctrl || !ctrl->write_cmd || ctrl->dev.type != &spmi_ctrl_type)
>  		return -EINVAL;
>  
> -	return ctrl->write_cmd(ctrl, opcode, sid, addr, buf, len);
> +	trace_spmi_write_begin(opcode, sid, addr, len, buf);
> +	ret = ctrl->write_cmd(ctrl, opcode, sid, addr, buf, len);
> +	trace_spmi_write_end(opcode, sid, addr, ret);
> +	return ret;
>  }
>  
>  /**
> diff --git a/include/trace/events/spmi.h b/include/trace/events/spmi.h
> new file mode 100644
> index 0000000..241fd1e
> --- /dev/null
> +++ b/include/trace/events/spmi.h
> @@ -0,0 +1,136 @@
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM spmi
> +
> +#if !defined(_TRACE_SPMI_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_SPMI_H
> +
> +#include <linux/spmi.h>
> +#include <linux/tracepoint.h>
> +
> +/*
> + * drivers/spmi/spmi.c
> + */
> +
> +TRACE_EVENT(spmi_write_begin,
> +	TP_PROTO(u8 opcode, u8 sid, u16 addr, u8 len, const u8 *buf),
> +	TP_ARGS(opcode, sid, addr, len, buf),
> +
> +	TP_STRUCT__entry(
> +		__field		( u8,         opcode    )
> +		__field		( u8,         sid       )
> +		__field		( u16,        addr      )
> +		__field		( u8,         len       )
> +		__dynamic_array	( u8,   buf,  len + 1   )
> +	),
> +
> +	TP_fast_assign(
> +		__entry->opcode = opcode;
> +		__entry->sid    = sid;
> +		__entry->addr   = addr;
> +		__entry->len    = len + 1;
> +		memcpy(__get_dynamic_array(buf), buf, len + 1);
> +	),
> +
> +	TP_printk("opc=%d sid=%02d addr=0x%04x len=%d buf=0x[%*phD]",
> +		  (int)__entry->opcode, (int)__entry->sid,
> +		  (int)__entry->addr, (int)__entry->len,
> +		  (int)__entry->len, __get_dynamic_array(buf))
> +);
> +
> +TRACE_EVENT(spmi_write_end,
> +	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret),
> +	TP_ARGS(opcode, sid, addr, ret),
> +
> +	TP_STRUCT__entry(
> +		__field		( u8,         opcode    )
> +		__field		( u8,         sid       )
> +		__field		( u16,        addr      )
> +		__field		( int,        ret       )
> +	),
> +
> +	TP_fast_assign(
> +		__entry->opcode = opcode;
> +		__entry->sid    = sid;
> +		__entry->addr   = addr;
> +		__entry->ret    = ret;
> +	),
> +
> +	TP_printk("opc=%d sid=%02d addr=0x%04x ret=%d",
> +		  (int)__entry->opcode, (int)__entry->sid,
> +		  (int)__entry->addr, __entry->ret)
> +);
> +
> +TRACE_EVENT(spmi_read_begin,
> +	TP_PROTO(u8 opcode, u8 sid, u16 addr),
> +	TP_ARGS(opcode, sid, addr),
> +
> +	TP_STRUCT__entry(
> +		__field		( u8,         opcode    )
> +		__field		( u8,         sid       )
> +		__field		( u16,        addr      )
> +	),
> +
> +	TP_fast_assign(
> +		__entry->opcode = opcode;
> +		__entry->sid    = sid;
> +		__entry->addr   = addr;
> +	),
> +
> +	TP_printk("opc=%d sid=%02d addr=0x%04x",
> +		  (int)__entry->opcode, (int)__entry->sid,
> +		  (int)__entry->addr)
> +);
> +
> +TRACE_EVENT(spmi_read_end,
> +	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret, u8 len,

Should "len" be size_t instead of u8? It would at least match the
implementation of spmi_controller::read_cmd(). Same comment for the
write side.

-Stephen

> +		 const u8 *buf),
> +	TP_ARGS(opcode, sid, addr, ret, len, buf),
> +
> +	TP_STRUCT__entry(
> +		__field		( u8,         opcode    )
> +		__field		( u8,         sid       )
> +		__field		( u16,        addr      )
> +		__field		( int,        ret       )
> +		__field		( u8,         len       )
> +		__dynamic_array	( u8,   buf,  len + 1   )
> +	),
> +
> +	TP_fast_assign(
> +		__entry->opcode = opcode;
> +		__entry->sid    = sid;
> +		__entry->addr   = addr;
> +		__entry->ret    = ret;
> +		__entry->len    = len + 1;
> +		memcpy(__get_dynamic_array(buf), buf, len + 1);
> +	),
> +
> +	TP_printk("opc=%d sid=%02d addr=0x%04x ret=%d len=%02d buf=0x[%*phD]",
> +		  (int)__entry->opcode, (int)__entry->sid,
> +		  (int)__entry->addr, __entry->ret, (int)__entry->len,
> +		  (int)__entry->len, __get_dynamic_array(buf))
> +);
> +
> +TRACE_EVENT(spmi_cmd,
> +	TP_PROTO(u8 opcode, u8 sid, int ret),
> +	TP_ARGS(opcode, sid, ret),
> +
> +	TP_STRUCT__entry(
> +		__field		( u8,         opcode    )
> +		__field		( u8,         sid       )
> +		__field		( int,        ret       )
> +	),
> +
> +	TP_fast_assign(
> +		__entry->opcode = opcode;
> +		__entry->sid    = sid;
> +		__entry->ret    = ret;
> +	),
> +
> +	TP_printk("opc=%d sid=%02d ret=%d", (int)__entry->opcode,
> +		  (int)__entry->sid, ret)
> +);
> +
> +#endif /* _TRACE_SPMI_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>


-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH] spmi: add command tracepoints for SPMI

[Steven Rostedt]

On Tue, 19 May 2015 17:36:41 -0700
Stephen Boyd <sboyd@codeaurora.org> wrote:

> +Steven Rostedt
> 
> On 05/18/15 14:51, Ankit Gupta wrote:
> > Add tracepoints to retrieve information about read, write
> > and non-data commands. For performance measurement support
> > tracepoints are added at the beginning and at the end of
> > transfers. Following is a list showing the new tracepoint
> > events. The "cmd" parameter here represents the opcode, SID,
> > and full 16-bit address.
> >
> > spmi_write_begin: cmd and data buffer.
> > spmi_write_end  : cmd and return value.
> > spmi_read_begin : cmd.
> > spmi_read_end   : cmd, return value and data buffer.
> > spmi_cmd        : cmd.
> >
> > The reason that cmd appears at both the beginning and at
> > the end event is that SPMI drivers can request commands
> > concurrently. cmd helps in matching the corresponding
> > events.
> >
> > SPMI tracepoints can be enabled like:
> >
> > echo 1 >/sys/kernel/debug/tracing/events/spmi/enable
> >
> > and will dump messages that can be viewed in
> > /sys/kernel/debug/tracing/trace that look like:
> >
> > ... spmi_read_begin: opc=56 sid=00 addr=0x0000
> > ... spmi_read_end: opc=56 sid=00 addr=0x0000 ret=0 len=02 buf=0x[01-40]
> > ... spmi_write_begin: opc=48 sid=00 addr=0x0000 len=3 buf=0x[ff-ff-ff]
> >
> > Signed-off-by: Ankit Gupta <ankgupta@codeaurora.org>
> > Signed-off-by: Gilad Avidov <gavidov@codeaurora.org>
> > Suggested-by: Sagar Dharia <sdharia@codeaurora.org>
> > ---
> 
> Your Signed-off-by should be last.
> 

The tracing part looks fine to me. For that:

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [PATCH] spmi: add command tracepoints for SPMI

[Ankit Gupta]

On Tue, 19 May 2015 17:36:41 -0700
Stephen Boyd <sboyd@codeaurora.org> wrote:

> +Steven Rostedt
> 
> On 05/18/15 14:51, Ankit Gupta wrote:
> > Add tracepoints to retrieve information about read, write
> > and non-data commands. For performance measurement support
> > tracepoints are added at the beginning and at the end of
> > transfers. Following is a list showing the new tracepoint
> > events. The "cmd" parameter here represents the opcode, SID,
> > and full 16-bit address.
> >
> > spmi_write_begin: cmd and data buffer.
> > spmi_write_end  : cmd and return value.
> > spmi_read_begin : cmd.
> > spmi_read_end   : cmd, return value and data buffer.
> > spmi_cmd        : cmd.
> >
> > The reason that cmd appears at both the beginning and at
> > the end event is that SPMI drivers can request commands
> > concurrently. cmd helps in matching the corresponding
> > events.
> >
> > SPMI tracepoints can be enabled like:
> >
> > echo 1 >/sys/kernel/debug/tracing/events/spmi/enable
> >
> > and will dump messages that can be viewed in
> > /sys/kernel/debug/tracing/trace that look like:
> >
> > ... spmi_read_begin: opc=56 sid=00 addr=0x0000
> > ... spmi_read_end: opc=56 sid=00 addr=0x0000 ret=0 len=02
> > buf=0x[01-40] ... spmi_write_begin: opc=48 sid=00 addr=0x0000 len=3
> > buf=0x[ff-ff-ff]
> >
> > Signed-off-by: Ankit Gupta <ankgupta@codeaurora.org>
> > Signed-off-by: Gilad Avidov <gavidov@codeaurora.org>
> > Suggested-by: Sagar Dharia <sdharia@codeaurora.org>
> > ---
> 
> Your Signed-off-by should be last.
Will change that.
> 
> >  drivers/spmi/spmi.c         |  22 ++++++-
> >  include/trace/events/spmi.h | 136
> > ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 155
> > insertions(+), 3 deletions(-) create mode 100644
> > include/trace/events/spmi.h
> >
> > diff --git a/drivers/spmi/spmi.c b/drivers/spmi/spmi.c
> > index 1d92f51..36fe010 100644
> > --- a/drivers/spmi/spmi.c
> > +++ b/drivers/spmi/spmi.c
> > @@ -21,6 +21,8 @@
> >  #include <linux/pm_runtime.h>
> >  
> >  #include <dt-bindings/spmi/spmi.h>
> > +#define CREATE_TRACE_POINTS
> > +#include <trace/events/spmi.h>
> >  
> >  static DEFINE_IDA(ctrl_ida);
> >  
> > @@ -95,28 +97,42 @@ EXPORT_SYMBOL_GPL(spmi_device_remove);
> >  static inline int
> >  spmi_cmd(struct spmi_controller *ctrl, u8 opcode, u8 sid)
> >  {
> > +	int ret;
> > +
> >  	if (!ctrl || !ctrl->cmd || ctrl->dev.type !=
> > &spmi_ctrl_type) return -EINVAL;
> >  
> > -	return ctrl->cmd(ctrl, opcode, sid);
> > +	ret = ctrl->cmd(ctrl, opcode, sid);
> > +	trace_spmi_cmd(opcode, sid, ret);
> > +	return ret;
> >  }
> >  
> >  static inline int spmi_read_cmd(struct spmi_controller *ctrl, u8
> > opcode, u8 sid, u16 addr, u8 *buf, size_t len)
> >  {
> > +	int ret;
> > +
> >  	if (!ctrl || !ctrl->read_cmd || ctrl->dev.type !=
> > &spmi_ctrl_type) return -EINVAL;
> >  
> > -	return ctrl->read_cmd(ctrl, opcode, sid, addr, buf, len);
> > +	trace_spmi_read_begin(opcode, sid, addr);
> > +	ret = ctrl->read_cmd(ctrl, opcode, sid, addr, buf, len);
> > +	trace_spmi_read_end(opcode, sid, addr, ret, len, buf);
> > +	return ret;
> >  }
> >  
> >  static inline int spmi_write_cmd(struct spmi_controller *ctrl, u8
> > opcode, u8 sid, u16 addr, const u8 *buf, size_t len)
> >  {
> > +	int ret;
> > +
> >  	if (!ctrl || !ctrl->write_cmd || ctrl->dev.type !=
> > &spmi_ctrl_type) return -EINVAL;
> >  
> > -	return ctrl->write_cmd(ctrl, opcode, sid, addr, buf, len);
> > +	trace_spmi_write_begin(opcode, sid, addr, len, buf);
> > +	ret = ctrl->write_cmd(ctrl, opcode, sid, addr, buf, len);
> > +	trace_spmi_write_end(opcode, sid, addr, ret);
> > +	return ret;
> >  }
> >  
> >  /**
> > diff --git a/include/trace/events/spmi.h
> > b/include/trace/events/spmi.h new file mode 100644
> > index 0000000..241fd1e
> > --- /dev/null
> > +++ b/include/trace/events/spmi.h
> > @@ -0,0 +1,136 @@
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM spmi
> > +
> > +#if !defined(_TRACE_SPMI_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_SPMI_H
> > +
> > +#include <linux/spmi.h>
> > +#include <linux/tracepoint.h>
> > +
> > +/*
> > + * drivers/spmi/spmi.c
> > + */
> > +
> > +TRACE_EVENT(spmi_write_begin,
> > +	TP_PROTO(u8 opcode, u8 sid, u16 addr, u8 len, const u8
> > *buf),
> > +	TP_ARGS(opcode, sid, addr, len, buf),
> > +
> > +	TP_STRUCT__entry(
> > +		__field		( u8,         opcode    )
> > +		__field		( u8,         sid       )
> > +		__field		( u16,        addr      )
> > +		__field		( u8,         len       )
> > +		__dynamic_array	( u8,   buf,  len + 1   )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->opcode = opcode;
> > +		__entry->sid    = sid;
> > +		__entry->addr   = addr;
> > +		__entry->len    = len + 1;
> > +		memcpy(__get_dynamic_array(buf), buf, len + 1);
> > +	),
> > +
> > +	TP_printk("opc=%d sid=%02d addr=0x%04x len=%d
> > buf=0x[%*phD]",
> > +		  (int)__entry->opcode, (int)__entry->sid,
> > +		  (int)__entry->addr, (int)__entry->len,
> > +		  (int)__entry->len, __get_dynamic_array(buf))
> > +);
> > +
> > +TRACE_EVENT(spmi_write_end,
> > +	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret),
> > +	TP_ARGS(opcode, sid, addr, ret),
> > +
> > +	TP_STRUCT__entry(
> > +		__field		( u8,         opcode    )
> > +		__field		( u8,         sid       )
> > +		__field		( u16,        addr      )
> > +		__field		( int,        ret       )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->opcode = opcode;
> > +		__entry->sid    = sid;
> > +		__entry->addr   = addr;
> > +		__entry->ret    = ret;
> > +	),
> > +
> > +	TP_printk("opc=%d sid=%02d addr=0x%04x ret=%d",
> > +		  (int)__entry->opcode, (int)__entry->sid,
> > +		  (int)__entry->addr, __entry->ret)
> > +);
> > +
> > +TRACE_EVENT(spmi_read_begin,
> > +	TP_PROTO(u8 opcode, u8 sid, u16 addr),
> > +	TP_ARGS(opcode, sid, addr),
> > +
> > +	TP_STRUCT__entry(
> > +		__field		( u8,         opcode    )
> > +		__field		( u8,         sid       )
> > +		__field		( u16,        addr      )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->opcode = opcode;
> > +		__entry->sid    = sid;
> > +		__entry->addr   = addr;
> > +	),
> > +
> > +	TP_printk("opc=%d sid=%02d addr=0x%04x",
> > +		  (int)__entry->opcode, (int)__entry->sid,
> > +		  (int)__entry->addr)
> > +);
> > +
> > +TRACE_EVENT(spmi_read_end,
> > +	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret, u8 len,
> 
> Should "len" be size_t instead of u8? It would at least match the
> implementation of spmi_controller::read_cmd(). Same comment for the
> write side.
> 
> -Stephen

I see no reason to spend to 4-8 bytes when spmi spec allows for maximum
buffer size of 16. Do you suggest changing the API of read_cmd()?
> 
> > +		 const u8 *buf),
> > +	TP_ARGS(opcode, sid, addr, ret, len, buf),
> > +
> > +	TP_STRUCT__entry(
> > +		__field		( u8,         opcode    )
> > +		__field		( u8,         sid       )
> > +		__field		( u16,        addr      )
> > +		__field		( int,        ret       )
> > +		__field		( u8,         len       )
> > +		__dynamic_array	( u8,   buf,  len + 1   )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->opcode = opcode;
> > +		__entry->sid    = sid;
> > +		__entry->addr   = addr;
> > +		__entry->ret    = ret;
> > +		__entry->len    = len + 1;
> > +		memcpy(__get_dynamic_array(buf), buf, len + 1);
> > +	),
> > +
> > +	TP_printk("opc=%d sid=%02d addr=0x%04x ret=%d len=%02d
> > buf=0x[%*phD]",
> > +		  (int)__entry->opcode, (int)__entry->sid,
> > +		  (int)__entry->addr, __entry->ret,
> > (int)__entry->len,
> > +		  (int)__entry->len, __get_dynamic_array(buf))
> > +);
> > +
> > +TRACE_EVENT(spmi_cmd,
> > +	TP_PROTO(u8 opcode, u8 sid, int ret),
> > +	TP_ARGS(opcode, sid, ret),
> > +
> > +	TP_STRUCT__entry(
> > +		__field		( u8,         opcode    )
> > +		__field		( u8,         sid       )
> > +		__field		( int,        ret       )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		__entry->opcode = opcode;
> > +		__entry->sid    = sid;
> > +		__entry->ret    = ret;
> > +	),
> > +
> > +	TP_printk("opc=%d sid=%02d ret=%d", (int)__entry->opcode,
> > +		  (int)__entry->sid, ret)
> > +);
> > +
> > +#endif /* _TRACE_SPMI_H */
> > +
> > +/* This part must be outside protection */
> > +#include <trace/define_trace.h>
> 
> 
Thanks,
Ankit

Re: [PATCH] spmi: add command tracepoints for SPMI

[Stephen Boyd]

On 05/20, Ankit Gupta wrote:
> On Tue, 19 May 2015 17:36:41 -0700
> Stephen Boyd <sboyd@codeaurora.org> wrote:
> > On 05/18/15 14:51, Ankit Gupta wrote:
> > > +
> > > +TRACE_EVENT(spmi_read_end,
> > > +	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret, u8 len,
> > 
> > Should "len" be size_t instead of u8? It would at least match the
> > implementation of spmi_controller::read_cmd(). Same comment for the
> > write side.
> > 
> > -Stephen
> 
> I see no reason to spend to 4-8 bytes when spmi spec allows for maximum
> buffer size of 16. Do you suggest changing the API of read_cmd()?
> > 

Is that a maximum buffer size of 16 bytes? I'd prefer consistency
with the API that's being traced, that's all. Changing it to u8
to save a few bytes probably doesn't make any difference if the
architecture passes function arguments in CPU registers which are
32 or 64 bits wide or if the function can be inlined enough by
the compiler to where the len parameter is kept in a register.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH] spmi: add command tracepoints for SPMI

[Steven Rostedt]

On Wed, 20 May 2015 11:29:55 -0700
Stephen Boyd <sboyd@codeaurora.org> wrote:


> > I see no reason to spend to 4-8 bytes when spmi spec allows for maximum
> > buffer size of 16. Do you suggest changing the API of read_cmd()?
> > > 
> 
> Is that a maximum buffer size of 16 bytes? I'd prefer consistency
> with the API that's being traced, that's all. Changing it to u8
> to save a few bytes probably doesn't make any difference if the
> architecture passes function arguments in CPU registers which are
> 32 or 64 bits wide or if the function can be inlined enough by
> the compiler to where the len parameter is kept in a register.
> 


I believe the worry is about wasting bytes in the ring buffer if not
necessary. But we do that in other tracepoints, so it's really up to
the maintainer.

-- Steve

Re: [PATCH] spmi: add command tracepoints for SPMI

[Stephen Boyd]

On 05/20/15 11:58, Steven Rostedt wrote:
> On Wed, 20 May 2015 11:29:55 -0700
> Stephen Boyd <sboyd@codeaurora.org> wrote:
>
>
>>> I see no reason to spend to 4-8 bytes when spmi spec allows for maximum
>>> buffer size of 16. Do you suggest changing the API of read_cmd()?
>> Is that a maximum buffer size of 16 bytes? I'd prefer consistency
>> with the API that's being traced, that's all. Changing it to u8
>> to save a few bytes probably doesn't make any difference if the
>> architecture passes function arguments in CPU registers which are
>> 32 or 64 bits wide or if the function can be inlined enough by
>> the compiler to where the len parameter is kept in a register.
>>
>
> I believe the worry is about wasting bytes in the ring buffer if not
> necessary. But we do that in other tracepoints, so it's really up to
> the maintainer.

Ah ok. Fair enough.

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH] spmi: add command tracepoints for SPMI

[Stephen Boyd]

On 05/18/15 14:51, Ankit Gupta wrote:
> Add tracepoints to retrieve information about read, write
> and non-data commands. For performance measurement support
> tracepoints are added at the beginning and at the end of
> transfers. Following is a list showing the new tracepoint
> events. The "cmd" parameter here represents the opcode, SID,
> and full 16-bit address.
>
> spmi_write_begin: cmd and data buffer.
> spmi_write_end  : cmd and return value.
> spmi_read_begin : cmd.
> spmi_read_end   : cmd, return value and data buffer.
> spmi_cmd        : cmd.
>
> The reason that cmd appears at both the beginning and at
> the end event is that SPMI drivers can request commands
> concurrently. cmd helps in matching the corresponding
> events.
>
> SPMI tracepoints can be enabled like:
>
> echo 1 >/sys/kernel/debug/tracing/events/spmi/enable
>
> and will dump messages that can be viewed in
> /sys/kernel/debug/tracing/trace that look like:
>
> ... spmi_read_begin: opc=56 sid=00 addr=0x0000
> ... spmi_read_end: opc=56 sid=00 addr=0x0000 ret=0 len=02 buf=0x[01-40]
> ... spmi_write_begin: opc=48 sid=00 addr=0x0000 len=3 buf=0x[ff-ff-ff]
>
> Signed-off-by: Ankit Gupta <ankgupta@codeaurora.org>
> Signed-off-by: Gilad Avidov <gavidov@codeaurora.org>
> Suggested-by: Sagar Dharia <sdharia@codeaurora.org>
> ---

Assuming you fix sign-off-chain:

Reviewed-by: Stephen Boyd <sboyd@codeaurora.org>

-- 
Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
a Linux Foundation Collaborative Project

Re: [PATCH] spmi: add command tracepoints for SPMI

[Ankit Gupta]

> On 05/20, Ankit Gupta wrote:
>> On Tue, 19 May 2015 17:36:41 -0700
>> Stephen Boyd <sboyd@codeaurora.org> wrote:
>> > On 05/18/15 14:51, Ankit Gupta wrote:
>> > > +
>> > > +TRACE_EVENT(spmi_read_end,
>> > > +	TP_PROTO(u8 opcode, u8 sid, u16 addr, int ret, u8 len,
>> >
>> > Should "len" be size_t instead of u8? It would at least match the
>> > implementation of spmi_controller::read_cmd(). Same comment for the
>> > write side.
>> >
>> > -Stephen
>>
>> I see no reason to spend to 4-8 bytes when spmi spec allows for maximum
>> buffer size of 16. Do you suggest changing the API of read_cmd()?
>> >
>
> Is that a maximum buffer size of 16 bytes? I'd prefer consistency
> with the API that's being traced, that's all. Changing it to u8
> to save a few bytes probably doesn't make any difference if the
> architecture passes function arguments in CPU registers which are
> 32 or 64 bits wide or if the function can be inlined enough by
> the compiler to where the len parameter is kept in a register.
>
Thanks Stephen for your comments. Will change it to size_t.
> --
> Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
> a Linux Foundation Collaborative Project
>

Re: [PATCH] spmi: add command tracepoints for SPMI

[Ankit Gupta]

> On 05/18/15 14:51, Ankit Gupta wrote:
>> Add tracepoints to retrieve information about read, write
>> and non-data commands. For performance measurement support
>> tracepoints are added at the beginning and at the end of
>> transfers. Following is a list showing the new tracepoint
>> events. The "cmd" parameter here represents the opcode, SID,
>> and full 16-bit address.
>>
>> spmi_write_begin: cmd and data buffer.
>> spmi_write_end  : cmd and return value.
>> spmi_read_begin : cmd.
>> spmi_read_end   : cmd, return value and data buffer.
>> spmi_cmd        : cmd.
>>
>> The reason that cmd appears at both the beginning and at
>> the end event is that SPMI drivers can request commands
>> concurrently. cmd helps in matching the corresponding
>> events.
>>
>> SPMI tracepoints can be enabled like:
>>
>> echo 1 >/sys/kernel/debug/tracing/events/spmi/enable
>>
>> and will dump messages that can be viewed in
>> /sys/kernel/debug/tracing/trace that look like:
>>
>> ... spmi_read_begin: opc=56 sid=00 addr=0x0000
>> ... spmi_read_end: opc=56 sid=00 addr=0x0000 ret=0 len=02 buf=0x[01-40]
>> ... spmi_write_begin: opc=48 sid=00 addr=0x0000 len=3 buf=0x[ff-ff-ff]
>>
>> Signed-off-by: Ankit Gupta <ankgupta@codeaurora.org>
>> Signed-off-by: Gilad Avidov <gavidov@codeaurora.org>
>> Suggested-by: Sagar Dharia <sdharia@codeaurora.org>
>> ---
>
> Assuming you fix sign-off-chain:
>
> Reviewed-by: Stephen Boyd <sboyd@codeaurora.org>

Sorry, Missed your this email, will upload a new patch with just change of
sign-off order.

Thanks
>
> --
> Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum,
> a Linux Foundation Collaborative Project
>
>