Add the ability to view response codes as well.
I renamed the trace event from cros_ec_cmd to cros_ec_request and added
a cros_ec_response.
Example:
$ echo 1 > /sys/kernel/debug/tracing/events/cros_ec/enable
$ cat /sys/kernel/debug/tracing/trace
cros_ec_request: version: 1, command: EC_CMD_CONSOLE_READ
cros_ec_response: version: 1, command: EC_CMD_CONSOLE_READ, result: EC_RES_SUCCESS, rc: 0
cros_ec_request: version: 0, command: EC_CMD_USB_PD_POWER_INFO
cros_ec_response: version: 0, command: EC_CMD_USB_PD_POWER_INFO, result: EC_RES_SUCCESS, rc: 16
Signed-off-by: Raul E Rangel <[email protected]>
---
drivers/platform/chrome/cros_ec_proto.c | 7 +++++-
drivers/platform/chrome/cros_ec_trace.c | 24 +++++++++++++++++++
drivers/platform/chrome/cros_ec_trace.h | 32 +++++++++++++++++++++++--
3 files changed, 60 insertions(+), 3 deletions(-)
diff --git a/drivers/platform/chrome/cros_ec_proto.c b/drivers/platform/chrome/cros_ec_proto.c
index bd485ce98a42..ef2229047e0f 100644
--- a/drivers/platform/chrome/cros_ec_proto.c
+++ b/drivers/platform/chrome/cros_ec_proto.c
@@ -54,7 +54,7 @@ static int send_command(struct cros_ec_device *ec_dev,
int ret;
int (*xfer_fxn)(struct cros_ec_device *ec, struct cros_ec_command *msg);
- trace_cros_ec_cmd(msg);
+ trace_cros_ec_request(msg);
if (ec_dev->proto_version > 2)
xfer_fxn = ec_dev->pkt_xfer;
@@ -73,6 +73,8 @@ static int send_command(struct cros_ec_device *ec_dev,
}
ret = (*xfer_fxn)(ec_dev, msg);
+
+ trace_cros_ec_response(msg, ret);
if (msg->result == EC_RES_IN_PROGRESS) {
int i;
struct cros_ec_command *status_msg;
@@ -95,7 +97,10 @@ static int send_command(struct cros_ec_device *ec_dev,
for (i = 0; i < EC_COMMAND_RETRIES; i++) {
usleep_range(10000, 11000);
+ trace_cros_ec_request(status_msg);
ret = (*xfer_fxn)(ec_dev, status_msg);
+ trace_cros_ec_response(status_msg, ret);
+
if (ret == -EAGAIN)
continue;
if (ret < 0)
diff --git a/drivers/platform/chrome/cros_ec_trace.c b/drivers/platform/chrome/cros_ec_trace.c
index 6f80ff4532ae..28eb94d99ba2 100644
--- a/drivers/platform/chrome/cros_ec_trace.c
+++ b/drivers/platform/chrome/cros_ec_trace.c
@@ -120,5 +120,29 @@
TRACE_SYMBOL(EC_CMD_PD_GET_LOG_ENTRY), \
TRACE_SYMBOL(EC_CMD_USB_PD_MUX_INFO)
+// See enum ec_status
+#define EC_RESULT \
+ TRACE_SYMBOL(EC_RES_SUCCESS), \
+ TRACE_SYMBOL(EC_RES_INVALID_COMMAND), \
+ TRACE_SYMBOL(EC_RES_ERROR), \
+ TRACE_SYMBOL(EC_RES_INVALID_PARAM), \
+ TRACE_SYMBOL(EC_RES_ACCESS_DENIED), \
+ TRACE_SYMBOL(EC_RES_INVALID_RESPONSE), \
+ TRACE_SYMBOL(EC_RES_INVALID_VERSION), \
+ TRACE_SYMBOL(EC_RES_INVALID_CHECKSUM), \
+ TRACE_SYMBOL(EC_RES_IN_PROGRESS), \
+ TRACE_SYMBOL(EC_RES_UNAVAILABLE), \
+ TRACE_SYMBOL(EC_RES_TIMEOUT), \
+ TRACE_SYMBOL(EC_RES_OVERFLOW), \
+ TRACE_SYMBOL(EC_RES_INVALID_HEADER), \
+ TRACE_SYMBOL(EC_RES_REQUEST_TRUNCATED), \
+ TRACE_SYMBOL(EC_RES_RESPONSE_TOO_BIG), \
+ TRACE_SYMBOL(EC_RES_BUS_ERROR), \
+ TRACE_SYMBOL(EC_RES_BUSY), \
+ TRACE_SYMBOL(EC_RES_INVALID_HEADER_VERSION), \
+ TRACE_SYMBOL(EC_RES_INVALID_HEADER_CRC), \
+ TRACE_SYMBOL(EC_RES_INVALID_DATA_CRC), \
+ TRACE_SYMBOL(EC_RES_DUP_UNAVAILABLE)
+
#define CREATE_TRACE_POINTS
#include "cros_ec_trace.h"
diff --git a/drivers/platform/chrome/cros_ec_trace.h b/drivers/platform/chrome/cros_ec_trace.h
index 0dd4df30fa89..853eeaaac9da 100644
--- a/drivers/platform/chrome/cros_ec_trace.h
+++ b/drivers/platform/chrome/cros_ec_trace.h
@@ -18,7 +18,7 @@
#include <linux/tracepoint.h>
-DECLARE_EVENT_CLASS(cros_ec_cmd_class,
+DECLARE_EVENT_CLASS(cros_ec_request_class,
TP_PROTO(struct cros_ec_command *cmd),
TP_ARGS(cmd),
TP_STRUCT__entry(
@@ -34,11 +34,39 @@ DECLARE_EVENT_CLASS(cros_ec_cmd_class,
);
-DEFINE_EVENT(cros_ec_cmd_class, cros_ec_cmd,
+DEFINE_EVENT(cros_ec_request_class, cros_ec_request,
TP_PROTO(struct cros_ec_command *cmd),
TP_ARGS(cmd)
);
+DECLARE_EVENT_CLASS(cros_ec_response_class,
+ TP_PROTO(struct cros_ec_command *cmd, int rc),
+ TP_ARGS(cmd, rc),
+ TP_STRUCT__entry(
+ __field(uint32_t, version)
+ __field(uint32_t, command)
+ __field(uint32_t, result)
+ __field(int, rc)
+ ),
+ TP_fast_assign(
+ __entry->version = cmd->version;
+ __entry->command = cmd->command;
+ __entry->result = cmd->result;
+ __entry->rc = rc;
+ ),
+ TP_printk("version: %u, command: %s, result: %s, rc: %d",
+ __entry->version,
+ __print_symbolic(__entry->command, EC_CMDS),
+ __print_symbolic(__entry->result, EC_RESULT),
+ __entry->rc)
+);
+
+
+DEFINE_EVENT(cros_ec_response_class, cros_ec_response,
+ TP_PROTO(struct cros_ec_command *cmd, int rc),
+ TP_ARGS(cmd, rc)
+);
+
#endif /* _CROS_EC_TRACE_H_ */
--
2.24.0.432.g9d3f5f5b63-goog
On Mon, Nov 25, 2019 at 8:45 AM Enric Balletbo i Serra
<[email protected]> wrote:
>
> Hi Raul,
>
> Many tanks for sending this patch upstream, some few comments below.
>
> On 21/11/19 19:55, Raul E Rangel wrote:
> > Add the ability to view response codes as well.
> >
> > I renamed the trace event from cros_ec_cmd to cros_ec_request and added
> > a cros_ec_response.
> >
> > Example:
> > $ echo 1 > /sys/kernel/debug/tracing/events/cros_ec/enable
> > $ cat /sys/kernel/debug/tracing/trace
> >
> > cros_ec_request: version: 1, command: EC_CMD_CONSOLE_READ
> > cros_ec_response: version: 1, command: EC_CMD_CONSOLE_READ, result: EC_RES_SUCCESS, rc: 0
>
> I don't see the advantage of have two traces, one for the request and another
> one for the response. Do you expect get stuck between them?
It might if there is a bug in xfer_fxn, we miss an interrupt, or some
kind of communication problem on the bus (early bring up issues). It's
also possible to compute the latency of a transaction by having both.
The mmc subsystem has both mmc_request_start and mmc_request_done. If
you feel strongly, I can record just the response.
>
> What about just move the trace_cros_ec_cmd after the xfer_fnx call and add the
> results?
>
> Thanks,
> Enric
>
> > cros_ec_request: version: 0, command: EC_CMD_USB_PD_POWER_INFO
> > cros_ec_response: version: 0, command: EC_CMD_USB_PD_POWER_INFO, result: EC_RES_SUCCESS, rc: 16
> >
> > Signed-off-by: Raul E Rangel <[email protected]>
> > ---
> >
> > drivers/platform/chrome/cros_ec_proto.c | 7 +++++-
> > drivers/platform/chrome/cros_ec_trace.c | 24 +++++++++++++++++++
> > drivers/platform/chrome/cros_ec_trace.h | 32 +++++++++++++++++++++++--
> > 3 files changed, 60 insertions(+), 3 deletions(-)
> >
> > diff --git a/drivers/platform/chrome/cros_ec_proto.c b/drivers/platform/chrome/cros_ec_proto.c
> > index bd485ce98a42..ef2229047e0f 100644
> > --- a/drivers/platform/chrome/cros_ec_proto.c
> > +++ b/drivers/platform/chrome/cros_ec_proto.c
> > @@ -54,7 +54,7 @@ static int send_command(struct cros_ec_device *ec_dev,
> > int ret;
> > int (*xfer_fxn)(struct cros_ec_device *ec, struct cros_ec_command *msg);
> >
> > - trace_cros_ec_cmd(msg);
> > + trace_cros_ec_request(msg);
> >
> > if (ec_dev->proto_version > 2)
> > xfer_fxn = ec_dev->pkt_xfer;
> > @@ -73,6 +73,8 @@ static int send_command(struct cros_ec_device *ec_dev,
> > }
> >
> > ret = (*xfer_fxn)(ec_dev, msg);
> > +
> > + trace_cros_ec_response(msg, ret);
> > if (msg->result == EC_RES_IN_PROGRESS) {
> > int i;
> > struct cros_ec_command *status_msg;
> > @@ -95,7 +97,10 @@ static int send_command(struct cros_ec_device *ec_dev,
> > for (i = 0; i < EC_COMMAND_RETRIES; i++) {
> > usleep_range(10000, 11000);
> >
> > + trace_cros_ec_request(status_msg);
> > ret = (*xfer_fxn)(ec_dev, status_msg);
> > + trace_cros_ec_response(status_msg, ret);
> > +
> > if (ret == -EAGAIN)
> > continue;
> > if (ret < 0)
> > diff --git a/drivers/platform/chrome/cros_ec_trace.c b/drivers/platform/chrome/cros_ec_trace.c
> > index 6f80ff4532ae..28eb94d99ba2 100644
> > --- a/drivers/platform/chrome/cros_ec_trace.c
> > +++ b/drivers/platform/chrome/cros_ec_trace.c
> > @@ -120,5 +120,29 @@
> > TRACE_SYMBOL(EC_CMD_PD_GET_LOG_ENTRY), \
> > TRACE_SYMBOL(EC_CMD_USB_PD_MUX_INFO)
> >
> > +// See enum ec_status
>
> Use the C comment style, please.
I used // because that was the comment format used above `#define
EC_CMDS`. Do you want me to change that as well?
Thanks
Hi Raul,
Many tanks for sending this patch upstream, some few comments below.
On 21/11/19 19:55, Raul E Rangel wrote:
> Add the ability to view response codes as well.
>
> I renamed the trace event from cros_ec_cmd to cros_ec_request and added
> a cros_ec_response.
>
> Example:
> $ echo 1 > /sys/kernel/debug/tracing/events/cros_ec/enable
> $ cat /sys/kernel/debug/tracing/trace
>
> cros_ec_request: version: 1, command: EC_CMD_CONSOLE_READ
> cros_ec_response: version: 1, command: EC_CMD_CONSOLE_READ, result: EC_RES_SUCCESS, rc: 0
I don't see the advantage of have two traces, one for the request and another
one for the response. Do you expect get stuck between them?
What about just move the trace_cros_ec_cmd after the xfer_fnx call and add the
results?
Thanks,
Enric
> cros_ec_request: version: 0, command: EC_CMD_USB_PD_POWER_INFO
> cros_ec_response: version: 0, command: EC_CMD_USB_PD_POWER_INFO, result: EC_RES_SUCCESS, rc: 16
>
> Signed-off-by: Raul E Rangel <[email protected]>
> ---
>
> drivers/platform/chrome/cros_ec_proto.c | 7 +++++-
> drivers/platform/chrome/cros_ec_trace.c | 24 +++++++++++++++++++
> drivers/platform/chrome/cros_ec_trace.h | 32 +++++++++++++++++++++++--
> 3 files changed, 60 insertions(+), 3 deletions(-)
>
> diff --git a/drivers/platform/chrome/cros_ec_proto.c b/drivers/platform/chrome/cros_ec_proto.c
> index bd485ce98a42..ef2229047e0f 100644
> --- a/drivers/platform/chrome/cros_ec_proto.c
> +++ b/drivers/platform/chrome/cros_ec_proto.c
> @@ -54,7 +54,7 @@ static int send_command(struct cros_ec_device *ec_dev,
> int ret;
> int (*xfer_fxn)(struct cros_ec_device *ec, struct cros_ec_command *msg);
>
> - trace_cros_ec_cmd(msg);
> + trace_cros_ec_request(msg);
>
> if (ec_dev->proto_version > 2)
> xfer_fxn = ec_dev->pkt_xfer;
> @@ -73,6 +73,8 @@ static int send_command(struct cros_ec_device *ec_dev,
> }
>
> ret = (*xfer_fxn)(ec_dev, msg);
> +
> + trace_cros_ec_response(msg, ret);
> if (msg->result == EC_RES_IN_PROGRESS) {
> int i;
> struct cros_ec_command *status_msg;
> @@ -95,7 +97,10 @@ static int send_command(struct cros_ec_device *ec_dev,
> for (i = 0; i < EC_COMMAND_RETRIES; i++) {
> usleep_range(10000, 11000);
>
> + trace_cros_ec_request(status_msg);
> ret = (*xfer_fxn)(ec_dev, status_msg);
> + trace_cros_ec_response(status_msg, ret);
> +
> if (ret == -EAGAIN)
> continue;
> if (ret < 0)
> diff --git a/drivers/platform/chrome/cros_ec_trace.c b/drivers/platform/chrome/cros_ec_trace.c
> index 6f80ff4532ae..28eb94d99ba2 100644
> --- a/drivers/platform/chrome/cros_ec_trace.c
> +++ b/drivers/platform/chrome/cros_ec_trace.c
> @@ -120,5 +120,29 @@
> TRACE_SYMBOL(EC_CMD_PD_GET_LOG_ENTRY), \
> TRACE_SYMBOL(EC_CMD_USB_PD_MUX_INFO)
>
> +// See enum ec_status
Use the C comment style, please.
> +#define EC_RESULT \
> + TRACE_SYMBOL(EC_RES_SUCCESS), \
> + TRACE_SYMBOL(EC_RES_INVALID_COMMAND), \
> + TRACE_SYMBOL(EC_RES_ERROR), \
> + TRACE_SYMBOL(EC_RES_INVALID_PARAM), \
> + TRACE_SYMBOL(EC_RES_ACCESS_DENIED), \
> + TRACE_SYMBOL(EC_RES_INVALID_RESPONSE), \
> + TRACE_SYMBOL(EC_RES_INVALID_VERSION), \
> + TRACE_SYMBOL(EC_RES_INVALID_CHECKSUM), \
> + TRACE_SYMBOL(EC_RES_IN_PROGRESS), \
> + TRACE_SYMBOL(EC_RES_UNAVAILABLE), \
> + TRACE_SYMBOL(EC_RES_TIMEOUT), \
> + TRACE_SYMBOL(EC_RES_OVERFLOW), \
> + TRACE_SYMBOL(EC_RES_INVALID_HEADER), \
> + TRACE_SYMBOL(EC_RES_REQUEST_TRUNCATED), \
> + TRACE_SYMBOL(EC_RES_RESPONSE_TOO_BIG), \
> + TRACE_SYMBOL(EC_RES_BUS_ERROR), \
> + TRACE_SYMBOL(EC_RES_BUSY), \
> + TRACE_SYMBOL(EC_RES_INVALID_HEADER_VERSION), \
> + TRACE_SYMBOL(EC_RES_INVALID_HEADER_CRC), \
> + TRACE_SYMBOL(EC_RES_INVALID_DATA_CRC), \
> + TRACE_SYMBOL(EC_RES_DUP_UNAVAILABLE)
> +
> #define CREATE_TRACE_POINTS
> #include "cros_ec_trace.h"
> diff --git a/drivers/platform/chrome/cros_ec_trace.h b/drivers/platform/chrome/cros_ec_trace.h
> index 0dd4df30fa89..853eeaaac9da 100644
> --- a/drivers/platform/chrome/cros_ec_trace.h
> +++ b/drivers/platform/chrome/cros_ec_trace.h
> @@ -18,7 +18,7 @@
>
> #include <linux/tracepoint.h>
>
> -DECLARE_EVENT_CLASS(cros_ec_cmd_class,
> +DECLARE_EVENT_CLASS(cros_ec_request_class,
> TP_PROTO(struct cros_ec_command *cmd),
> TP_ARGS(cmd),
> TP_STRUCT__entry(
> @@ -34,11 +34,39 @@ DECLARE_EVENT_CLASS(cros_ec_cmd_class,
> );
>
>
> -DEFINE_EVENT(cros_ec_cmd_class, cros_ec_cmd,
> +DEFINE_EVENT(cros_ec_request_class, cros_ec_request,
> TP_PROTO(struct cros_ec_command *cmd),
> TP_ARGS(cmd)
> );
>
> +DECLARE_EVENT_CLASS(cros_ec_response_class,
> + TP_PROTO(struct cros_ec_command *cmd, int rc),
> + TP_ARGS(cmd, rc),
> + TP_STRUCT__entry(
> + __field(uint32_t, version)
> + __field(uint32_t, command)
> + __field(uint32_t, result)
> + __field(int, rc)
> + ),
> + TP_fast_assign(
> + __entry->version = cmd->version;
> + __entry->command = cmd->command;
> + __entry->result = cmd->result;
> + __entry->rc = rc;
> + ),
> + TP_printk("version: %u, command: %s, result: %s, rc: %d",
> + __entry->version,
> + __print_symbolic(__entry->command, EC_CMDS),
> + __print_symbolic(__entry->result, EC_RESULT),
> + __entry->rc)
> +);
> +
> +
> +DEFINE_EVENT(cros_ec_response_class, cros_ec_response,
> + TP_PROTO(struct cros_ec_command *cmd, int rc),
> + TP_ARGS(cmd, rc)
> +);
> +
>
> #endif /* _CROS_EC_TRACE_H_ */
>
>
Hi Raul,
On 25/11/19 17:49, Raul Rangel wrote:
> On Mon, Nov 25, 2019 at 8:45 AM Enric Balletbo i Serra
> <[email protected]> wrote:
>>
>> Hi Raul,
>>
>> Many tanks for sending this patch upstream, some few comments below.
>>
>> On 21/11/19 19:55, Raul E Rangel wrote:
>>> Add the ability to view response codes as well.
>>>
>>> I renamed the trace event from cros_ec_cmd to cros_ec_request and added
>>> a cros_ec_response.
>>>
>>> Example:
>>> $ echo 1 > /sys/kernel/debug/tracing/events/cros_ec/enable
>>> $ cat /sys/kernel/debug/tracing/trace
>>>
>>> cros_ec_request: version: 1, command: EC_CMD_CONSOLE_READ
>>> cros_ec_response: version: 1, command: EC_CMD_CONSOLE_READ, result: EC_RES_SUCCESS, rc: 0
>>
>> I don't see the advantage of have two traces, one for the request and another
>> one for the response. Do you expect get stuck between them?
>
> It might if there is a bug in xfer_fxn, we miss an interrupt, or some
> kind of communication problem on the bus (early bring up issues). It's
> also possible to compute the latency of a transaction by having both.
> The mmc subsystem has both mmc_request_start and mmc_request_done. If
> you feel strongly, I can record just the response.
That's a good reason, I am fine with having both. Can we follow the same naming
as used in mmc though?
trace_cros_ec_request_start
trace_cros_ec_request_done
>>
>> What about just move the trace_cros_ec_cmd after the xfer_fnx call and add the
>> results?
>>
>> Thanks,
>> Enric
>>
>>> cros_ec_request: version: 0, command: EC_CMD_USB_PD_POWER_INFO
>>> cros_ec_response: version: 0, command: EC_CMD_USB_PD_POWER_INFO, result: EC_RES_SUCCESS, rc: 16
Could I suggest the following changes?
s/result/ec result/
s/rc/retval/
>>>
>>> Signed-off-by: Raul E Rangel <[email protected]>
>>> ---
>>>
>>> drivers/platform/chrome/cros_ec_proto.c | 7 +++++-
>>> drivers/platform/chrome/cros_ec_trace.c | 24 +++++++++++++++++++
>>> drivers/platform/chrome/cros_ec_trace.h | 32 +++++++++++++++++++++++--
>>> 3 files changed, 60 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/drivers/platform/chrome/cros_ec_proto.c b/drivers/platform/chrome/cros_ec_proto.c
>>> index bd485ce98a42..ef2229047e0f 100644
>>> --- a/drivers/platform/chrome/cros_ec_proto.c
>>> +++ b/drivers/platform/chrome/cros_ec_proto.c
>>> @@ -54,7 +54,7 @@ static int send_command(struct cros_ec_device *ec_dev,
>>> int ret;
>>> int (*xfer_fxn)(struct cros_ec_device *ec, struct cros_ec_command *msg);
>>>
>>> - trace_cros_ec_cmd(msg);
>>> + trace_cros_ec_request(msg);
>>>
>>> if (ec_dev->proto_version > 2)
>>> xfer_fxn = ec_dev->pkt_xfer;
>>> @@ -73,6 +73,8 @@ static int send_command(struct cros_ec_device *ec_dev,
>>> }
>>>
>>> ret = (*xfer_fxn)(ec_dev, msg);
>>> +
>>> + trace_cros_ec_response(msg, ret);
>>> if (msg->result == EC_RES_IN_PROGRESS) {
>>> int i;
>>> struct cros_ec_command *status_msg;
>>> @@ -95,7 +97,10 @@ static int send_command(struct cros_ec_device *ec_dev,
>>> for (i = 0; i < EC_COMMAND_RETRIES; i++) {
>>> usleep_range(10000, 11000);
>>>
>>> + trace_cros_ec_request(status_msg);
>>> ret = (*xfer_fxn)(ec_dev, status_msg);
>>> + trace_cros_ec_response(status_msg, ret);
>>> +
>>> if (ret == -EAGAIN)
>>> continue;
>>> if (ret < 0)
>>> diff --git a/drivers/platform/chrome/cros_ec_trace.c b/drivers/platform/chrome/cros_ec_trace.c
>>> index 6f80ff4532ae..28eb94d99ba2 100644
>>> --- a/drivers/platform/chrome/cros_ec_trace.c
>>> +++ b/drivers/platform/chrome/cros_ec_trace.c
>>> @@ -120,5 +120,29 @@
>>> TRACE_SYMBOL(EC_CMD_PD_GET_LOG_ENTRY), \
>>> TRACE_SYMBOL(EC_CMD_USB_PD_MUX_INFO)
>>>
>>> +// See enum ec_status
>>
>> Use the C comment style, please.
> I used // because that was the comment format used above `#define
> EC_CMDS`. Do you want me to change that as well?
>
Yes, use C-style by default. The reason why it is used the C++ style above is
because contains '*/' in the script that broke the C comment.
Thanks,
Enric
> Thanks
>