[PATCH] tee: optee: add invoke_fn tracepoints

[PATCH] tee: optee: add invoke_fn tracepoints

[Jisheng Zhang]

Add tracepoints to retrieve information about the invoke_fn. This would
help to measure how many invoke_fn are triggered and how long it takes
to complete one invoke_fn call.

Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
---

Since v1:
 - add BUILD_BUG_ON() macro usage to make sure that the size of what is being
   copied, is not smaller than the amount being copied. Thank Steve.
 - move optee_trace.h to keep include headers sorted

 drivers/tee/optee/call.c        |  4 ++
 drivers/tee/optee/optee_trace.h | 67 +++++++++++++++++++++++++++++++++
 2 files changed, 71 insertions(+)
 create mode 100644 drivers/tee/optee/optee_trace.h

diff --git a/drivers/tee/optee/call.c b/drivers/tee/optee/call.c
index 780d7c4fd756..0da6fe50f1af 100644
--- a/drivers/tee/optee/call.c
+++ b/drivers/tee/optee/call.c
@@ -14,6 +14,8 @@
 #include <linux/uaccess.h>
 #include "optee_private.h"
 #include "optee_smc.h"
+#define CREATE_TRACE_POINTS
+#include "optee_trace.h"
 
 struct optee_call_waiter {
 	struct list_head list_node;
@@ -138,9 +140,11 @@ u32 optee_do_call_with_arg(struct tee_context *ctx, phys_addr_t parg)
 	while (true) {
 		struct arm_smccc_res res;
 
+		trace_optee_invoke_fn_begin(&param);
 		optee->invoke_fn(param.a0, param.a1, param.a2, param.a3,
 				 param.a4, param.a5, param.a6, param.a7,
 				 &res);
+		trace_optee_invoke_fn_end(&param, &res);
 
 		if (res.a0 == OPTEE_SMC_RETURN_ETHREAD_LIMIT) {
 			/*
diff --git a/drivers/tee/optee/optee_trace.h b/drivers/tee/optee/optee_trace.h
new file mode 100644
index 000000000000..7c954eefa4bf
--- /dev/null
+++ b/drivers/tee/optee/optee_trace.h
@@ -0,0 +1,67 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * optee trace points
+ *
+ * Copyright (C) 2021 Synaptics Incorporated
+ * Author: Jisheng Zhang <jszhang@kernel.org>
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM optee
+
+#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_OPTEE_H
+
+#include <linux/arm-smccc.h>
+#include <linux/tracepoint.h>
+#include "optee_private.h"
+
+TRACE_EVENT(optee_invoke_fn_begin,
+	TP_PROTO(struct optee_rpc_param *param),
+	TP_ARGS(param),
+
+	TP_STRUCT__entry(
+		__field(void *, param)
+		__array(u32, args, 8)
+	),
+
+	TP_fast_assign(
+		__entry->param = param;
+		BUILD_BUG_ON(sizeof(*param) < sizeof(__entry->args));
+		memcpy(__entry->args, param, sizeof(__entry->args));
+	),
+
+	TP_printk("param=%p (%x, %x, %x, %x, %x, %x, %x, %x)", __entry->param,
+		  __entry->args[0], __entry->args[1], __entry->args[2],
+		  __entry->args[3], __entry->args[4], __entry->args[5],
+		  __entry->args[6], __entry->args[7])
+);
+
+TRACE_EVENT(optee_invoke_fn_end,
+	TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
+	TP_ARGS(param, res),
+
+	TP_STRUCT__entry(
+		__field(void *, param)
+		__array(unsigned long, rets, 4)
+	),
+
+	TP_fast_assign(
+		__entry->param = param;
+		BUILD_BUG_ON(sizeof(*res) < sizeof(__entry->rets));
+		memcpy(__entry->rets, res, sizeof(__entry->rets));
+	),
+
+	TP_printk("param=%p ret (%lx, %lx, %lx, %lx)", __entry->param,
+		  __entry->rets[0], __entry->rets[1], __entry->rets[2],
+		  __entry->rets[3])
+);
+#endif /* _TRACE_OPTEE_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE optee_trace
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.30.0

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Steven Rostedt]

On Wed, 10 Feb 2021 14:44:09 +0800
Jisheng Zhang <Jisheng.Zhang@synaptics.com> wrote:

> Add tracepoints to retrieve information about the invoke_fn. This would
> help to measure how many invoke_fn are triggered and how long it takes
> to complete one invoke_fn call.
> 
> Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> ---
> 
> Since v1:
>  - add BUILD_BUG_ON() macro usage to make sure that the size of what is being
>    copied, is not smaller than the amount being copied. Thank Steve.
>  - move optee_trace.h to keep include headers sorted

From a tracing point of view:

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Jens Wiklander]

Hi Jisheng,

On Wed, Feb 10, 2021 at 7:44 AM Jisheng Zhang
<Jisheng.Zhang@synaptics.com> wrote:
>
> Add tracepoints to retrieve information about the invoke_fn. This would
> help to measure how many invoke_fn are triggered and how long it takes
> to complete one invoke_fn call.
>
> Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> ---
>
> Since v1:
>  - add BUILD_BUG_ON() macro usage to make sure that the size of what is being
>    copied, is not smaller than the amount being copied. Thank Steve.
>  - move optee_trace.h to keep include headers sorted
>
>  drivers/tee/optee/call.c        |  4 ++
>  drivers/tee/optee/optee_trace.h | 67 +++++++++++++++++++++++++++++++++
>  2 files changed, 71 insertions(+)
>  create mode 100644 drivers/tee/optee/optee_trace.h
>
> diff --git a/drivers/tee/optee/call.c b/drivers/tee/optee/call.c
> index 780d7c4fd756..0da6fe50f1af 100644
> --- a/drivers/tee/optee/call.c
> +++ b/drivers/tee/optee/call.c
> @@ -14,6 +14,8 @@
>  #include <linux/uaccess.h>
>  #include "optee_private.h"
>  #include "optee_smc.h"
> +#define CREATE_TRACE_POINTS
> +#include "optee_trace.h"
>
>  struct optee_call_waiter {
>         struct list_head list_node;
> @@ -138,9 +140,11 @@ u32 optee_do_call_with_arg(struct tee_context *ctx, phys_addr_t parg)
>         while (true) {
>                 struct arm_smccc_res res;
>
> +               trace_optee_invoke_fn_begin(&param);
>                 optee->invoke_fn(param.a0, param.a1, param.a2, param.a3,
>                                  param.a4, param.a5, param.a6, param.a7,
>                                  &res);
> +               trace_optee_invoke_fn_end(&param, &res);
>
>                 if (res.a0 == OPTEE_SMC_RETURN_ETHREAD_LIMIT) {
>                         /*
> diff --git a/drivers/tee/optee/optee_trace.h b/drivers/tee/optee/optee_trace.h
> new file mode 100644
> index 000000000000..7c954eefa4bf
> --- /dev/null
> +++ b/drivers/tee/optee/optee_trace.h
> @@ -0,0 +1,67 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +/*
> + * optee trace points
> + *
> + * Copyright (C) 2021 Synaptics Incorporated
> + * Author: Jisheng Zhang <jszhang@kernel.org>
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM optee
> +
> +#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_OPTEE_H
> +
> +#include <linux/arm-smccc.h>
> +#include <linux/tracepoint.h>
> +#include "optee_private.h"
> +

Checkpatch has some complaints below. Is that something that could be
fixed or is this so far from regular C-syntax that we don't care?

Thanks,
Jens

> +TRACE_EVENT(optee_invoke_fn_begin,
> +       TP_PROTO(struct optee_rpc_param *param),
> +       TP_ARGS(param),
> +
> +       TP_STRUCT__entry(
> +               __field(void *, param)
> +               __array(u32, args, 8)
> +       ),
> +
> +       TP_fast_assign(
> +               __entry->param = param;
> +               BUILD_BUG_ON(sizeof(*param) < sizeof(__entry->args));
> +               memcpy(__entry->args, param, sizeof(__entry->args));
> +       ),
> +
> +       TP_printk("param=%p (%x, %x, %x, %x, %x, %x, %x, %x)", __entry->param,
> +                 __entry->args[0], __entry->args[1], __entry->args[2],
> +                 __entry->args[3], __entry->args[4], __entry->args[5],
> +                 __entry->args[6], __entry->args[7])
> +);
> +
> +TRACE_EVENT(optee_invoke_fn_end,
> +       TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
> +       TP_ARGS(param, res),
> +
> +       TP_STRUCT__entry(
> +               __field(void *, param)
> +               __array(unsigned long, rets, 4)
> +       ),
> +
> +       TP_fast_assign(
> +               __entry->param = param;
> +               BUILD_BUG_ON(sizeof(*res) < sizeof(__entry->rets));
> +               memcpy(__entry->rets, res, sizeof(__entry->rets));
> +       ),
> +
> +       TP_printk("param=%p ret (%lx, %lx, %lx, %lx)", __entry->param,
> +                 __entry->rets[0], __entry->rets[1], __entry->rets[2],
> +                 __entry->rets[3])
> +);
> +#endif /* _TRACE_OPTEE_H */
> +
> +#undef TRACE_INCLUDE_PATH
> +#define TRACE_INCLUDE_PATH .
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_FILE optee_trace
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> --
> 2.30.0
>

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Jisheng Zhang]

On Tue, 23 Feb 2021 08:59:22 +0100 Jens Wiklander wrote:


> 
> Hi Jisheng,

Hi Jens,

> 
> On Wed, Feb 10, 2021 at 7:44 AM Jisheng Zhang
> <Jisheng.Zhang@synaptics.com> wrote:
> >
> > Add tracepoints to retrieve information about the invoke_fn. This would
> > help to measure how many invoke_fn are triggered and how long it takes
> > to complete one invoke_fn call.
> >
> > Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> > ---
> >
> > Since v1:
> >  - add BUILD_BUG_ON() macro usage to make sure that the size of what is being
> >    copied, is not smaller than the amount being copied. Thank Steve.
> >  - move optee_trace.h to keep include headers sorted
> >
> >  drivers/tee/optee/call.c        |  4 ++
> >  drivers/tee/optee/optee_trace.h | 67 +++++++++++++++++++++++++++++++++
> >  2 files changed, 71 insertions(+)
> >  create mode 100644 drivers/tee/optee/optee_trace.h
> >
> > diff --git a/drivers/tee/optee/call.c b/drivers/tee/optee/call.c
> > index 780d7c4fd756..0da6fe50f1af 100644
> > --- a/drivers/tee/optee/call.c
> > +++ b/drivers/tee/optee/call.c
> > @@ -14,6 +14,8 @@
> >  #include <linux/uaccess.h>
> >  #include "optee_private.h"
> >  #include "optee_smc.h"
> > +#define CREATE_TRACE_POINTS
> > +#include "optee_trace.h"
> >
> >  struct optee_call_waiter {
> >         struct list_head list_node;
> > @@ -138,9 +140,11 @@ u32 optee_do_call_with_arg(struct tee_context *ctx, phys_addr_t parg)
> >         while (true) {
> >                 struct arm_smccc_res res;
> >
> > +               trace_optee_invoke_fn_begin(&param);
> >                 optee->invoke_fn(param.a0, param.a1, param.a2, param.a3,
> >                                  param.a4, param.a5, param.a6, param.a7,
> >                                  &res);
> > +               trace_optee_invoke_fn_end(&param, &res);
> >
> >                 if (res.a0 == OPTEE_SMC_RETURN_ETHREAD_LIMIT) {
> >                         /*
> > diff --git a/drivers/tee/optee/optee_trace.h b/drivers/tee/optee/optee_trace.h
> > new file mode 100644
> > index 000000000000..7c954eefa4bf
> > --- /dev/null
> > +++ b/drivers/tee/optee/optee_trace.h
> > @@ -0,0 +1,67 @@
> > +/* SPDX-License-Identifier: GPL-2.0 */
> > +/*
> > + * optee trace points
> > + *
> > + * Copyright (C) 2021 Synaptics Incorporated
> > + * Author: Jisheng Zhang <jszhang@kernel.org>
> > + */
> > +
> > +#undef TRACE_SYSTEM
> > +#define TRACE_SYSTEM optee
> > +
> > +#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
> > +#define _TRACE_OPTEE_H
> > +
> > +#include <linux/arm-smccc.h>
> > +#include <linux/tracepoint.h>
> > +#include "optee_private.h"
> > +  
> 
> Checkpatch has some complaints below. Is that something that could be
> fixed or is this so far from regular C-syntax that we don't care?

I tried ./scripts/checkpatch.pl in Linus tree to check the patch, there's
no any error, and except the "MAINTAINERS need updating" warning, there's
no other warnings.

git log  -- scripts/checkpatch.pl
shows the latest checkpatch.pl is at commit 62137364e3e8afcc745846c5c67cacf943149073

I'm not sure what happened.

Thanks

> 
> Thanks,
> Jens
> 
> > +TRACE_EVENT(optee_invoke_fn_begin,
> > +       TP_PROTO(struct optee_rpc_param *param),
> > +       TP_ARGS(param),
> > +
> > +       TP_STRUCT__entry(
> > +               __field(void *, param)
> > +               __array(u32, args, 8)
> > +       ),
> > +
> > +       TP_fast_assign(
> > +               __entry->param = param;
> > +               BUILD_BUG_ON(sizeof(*param) < sizeof(__entry->args));
> > +               memcpy(__entry->args, param, sizeof(__entry->args));
> > +       ),
> > +
> > +       TP_printk("param=%p (%x, %x, %x, %x, %x, %x, %x, %x)", __entry->param,
> > +                 __entry->args[0], __entry->args[1], __entry->args[2],
> > +                 __entry->args[3], __entry->args[4], __entry->args[5],
> > +                 __entry->args[6], __entry->args[7])
> > +);
> > +
> > +TRACE_EVENT(optee_invoke_fn_end,
> > +       TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
> > +       TP_ARGS(param, res),
> > +
> > +       TP_STRUCT__entry(
> > +               __field(void *, param)
> > +               __array(unsigned long, rets, 4)
> > +       ),
> > +
> > +       TP_fast_assign(
> > +               __entry->param = param;
> > +               BUILD_BUG_ON(sizeof(*res) < sizeof(__entry->rets));
> > +               memcpy(__entry->rets, res, sizeof(__entry->rets));
> > +       ),
> > +
> > +       TP_printk("param=%p ret (%lx, %lx, %lx, %lx)", __entry->param,
> > +                 __entry->rets[0], __entry->rets[1], __entry->rets[2],
> > +                 __entry->rets[3])
> > +);
> > +#endif /* _TRACE_OPTEE_H */
> > +
> > +#undef TRACE_INCLUDE_PATH
> > +#define TRACE_INCLUDE_PATH .
> > +#undef TRACE_INCLUDE_FILE
> > +#define TRACE_INCLUDE_FILE optee_trace
> > +
> > +/* This part must be outside protection */
> > +#include <trace/define_trace.h>
> > --
> > 2.30.0
> >  

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Jens Wiklander]

On Tue, Feb 23, 2021 at 06:40:26PM +0800, Jisheng Zhang wrote:
> On Tue, 23 Feb 2021 08:59:22 +0100 Jens Wiklander wrote:
> 
> 
> > 
> > Hi Jisheng,
> 
> Hi Jens,
> 
> > 
> > On Wed, Feb 10, 2021 at 7:44 AM Jisheng Zhang
> > <Jisheng.Zhang@synaptics.com> wrote:
> > >
> > > Add tracepoints to retrieve information about the invoke_fn. This would
> > > help to measure how many invoke_fn are triggered and how long it takes
> > > to complete one invoke_fn call.
> > >
> > > Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> > > ---
> > >
> > > Since v1:
> > >  - add BUILD_BUG_ON() macro usage to make sure that the size of what is being
> > >    copied, is not smaller than the amount being copied. Thank Steve.
> > >  - move optee_trace.h to keep include headers sorted
> > >
> > >  drivers/tee/optee/call.c        |  4 ++
> > >  drivers/tee/optee/optee_trace.h | 67 +++++++++++++++++++++++++++++++++
> > >  2 files changed, 71 insertions(+)
> > >  create mode 100644 drivers/tee/optee/optee_trace.h
> > >
[snip]
> > > diff --git a/drivers/tee/optee/optee_trace.h b/drivers/tee/optee/optee_trace.h
> > > new file mode 100644
> > > index 000000000000..7c954eefa4bf
> > > --- /dev/null
> > > +++ b/drivers/tee/optee/optee_trace.h
> > > @@ -0,0 +1,67 @@
> > > +/* SPDX-License-Identifier: GPL-2.0 */
> > > +/*
> > > + * optee trace points
> > > + *
> > > + * Copyright (C) 2021 Synaptics Incorporated
> > > + * Author: Jisheng Zhang <jszhang@kernel.org>
> > > + */
> > > +
> > > +#undef TRACE_SYSTEM
> > > +#define TRACE_SYSTEM optee
> > > +
> > > +#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
> > > +#define _TRACE_OPTEE_H
> > > +
> > > +#include <linux/arm-smccc.h>
> > > +#include <linux/tracepoint.h>
> > > +#include "optee_private.h"
> > > +  
> > 
> > Checkpatch has some complaints below. Is that something that could be
> > fixed or is this so far from regular C-syntax that we don't care?
> 
> I tried ./scripts/checkpatch.pl in Linus tree to check the patch, there's
> no any error, and except the "MAINTAINERS need updating" warning, there's
> no other warnings.
> 
> git log  -- scripts/checkpatch.pl
> shows the latest checkpatch.pl is at commit 62137364e3e8afcc745846c5c67cacf943149073
> 
> I'm not sure what happened.

I used the -strict option.

./scripts/checkpatch.pl -strict 0001-tee-optee-add-invoke_fn-tracepoints.patch
WARNING: added, moved or deleted file(s), does MAINTAINERS need updating?
#44: 
new file mode 100644

CHECK: Alignment should match open parenthesis
#68: FILE: drivers/tee/optee/optee_trace.h:20:
+TRACE_EVENT(optee_invoke_fn_begin,
+	TP_PROTO(struct optee_rpc_param *param),

CHECK: Lines should not end with a '('
#71: FILE: drivers/tee/optee/optee_trace.h:23:
+	TP_STRUCT__entry(

CHECK: Lines should not end with a '('
#76: FILE: drivers/tee/optee/optee_trace.h:28:
+	TP_fast_assign(

CHECK: Alignment should match open parenthesis
#89: FILE: drivers/tee/optee/optee_trace.h:41:
+TRACE_EVENT(optee_invoke_fn_end,
+	TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),

CHECK: Lines should not end with a '('
#92: FILE: drivers/tee/optee/optee_trace.h:44:
+	TP_STRUCT__entry(

CHECK: Lines should not end with a '('
#97: FILE: drivers/tee/optee/optee_trace.h:49:
+	TP_fast_assign(

total: 0 errors, 1 warnings, 6 checks, 86 lines checked

Thanks,
Jens

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Steven Rostedt]

On Tue, 23 Feb 2021 14:11:24 +0100
Jens Wiklander <jens.wiklander@linaro.org> wrote:

> I used the -strict option.
> 
> ./scripts/checkpatch.pl -strict 0001-tee-optee-add-invoke_fn-tracepoints.patch
> WARNING: added, moved or deleted file(s), does MAINTAINERS need updating?
> #44: 
> new file mode 100644

The above is just asking for someone to take maintainership of the new file.

> 
> CHECK: Alignment should match open parenthesis
> #68: FILE: drivers/tee/optee/optee_trace.h:20:
> +TRACE_EVENT(optee_invoke_fn_begin,
> +	TP_PROTO(struct optee_rpc_param *param),
> 
> CHECK: Lines should not end with a '('
> #71: FILE: drivers/tee/optee/optee_trace.h:23:
> +	TP_STRUCT__entry(
> 
> CHECK: Lines should not end with a '('
> #76: FILE: drivers/tee/optee/optee_trace.h:28:
> +	TP_fast_assign(
> 
> CHECK: Alignment should match open parenthesis
> #89: FILE: drivers/tee/optee/optee_trace.h:41:
> +TRACE_EVENT(optee_invoke_fn_end,
> +	TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
> 
> CHECK: Lines should not end with a '('
> #92: FILE: drivers/tee/optee/optee_trace.h:44:
> +	TP_STRUCT__entry(
> 
> CHECK: Lines should not end with a '('
> #97: FILE: drivers/tee/optee/optee_trace.h:49:
> +	TP_fast_assign(

The TRACE_EVENT() macro is "special", and checkpatch notoriously stumbles
over it. I usually recommend that people ignore the checkpatch warnings on
TRACE_EVENT() macros.

-- Steve


> 
> total: 0 errors, 1 warnings, 6 checks, 86 lines checked

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Jens Wiklander]

On Tue, Feb 23, 2021 at 09:19:36AM -0500, Steven Rostedt wrote:
> On Tue, 23 Feb 2021 14:11:24 +0100
> Jens Wiklander <jens.wiklander@linaro.org> wrote:
> 
> > I used the -strict option.
> > 
> > ./scripts/checkpatch.pl -strict 0001-tee-optee-add-invoke_fn-tracepoints.patch
> > WARNING: added, moved or deleted file(s), does MAINTAINERS need updating?
> > #44: 
> > new file mode 100644
> 
> The above is just asking for someone to take maintainership of the new file.
> 
> > 
> > CHECK: Alignment should match open parenthesis
> > #68: FILE: drivers/tee/optee/optee_trace.h:20:
> > +TRACE_EVENT(optee_invoke_fn_begin,
> > +	TP_PROTO(struct optee_rpc_param *param),
> > 
> > CHECK: Lines should not end with a '('
> > #71: FILE: drivers/tee/optee/optee_trace.h:23:
> > +	TP_STRUCT__entry(
> > 
> > CHECK: Lines should not end with a '('
> > #76: FILE: drivers/tee/optee/optee_trace.h:28:
> > +	TP_fast_assign(
> > 
> > CHECK: Alignment should match open parenthesis
> > #89: FILE: drivers/tee/optee/optee_trace.h:41:
> > +TRACE_EVENT(optee_invoke_fn_end,
> > +	TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
> > 
> > CHECK: Lines should not end with a '('
> > #92: FILE: drivers/tee/optee/optee_trace.h:44:
> > +	TP_STRUCT__entry(
> > 
> > CHECK: Lines should not end with a '('
> > #97: FILE: drivers/tee/optee/optee_trace.h:49:
> > +	TP_fast_assign(
> 
> The TRACE_EVENT() macro is "special", and checkpatch notoriously stumbles
> over it. I usually recommend that people ignore the checkpatch warnings on
> TRACE_EVENT() macros.

Makes sense. I'll pick this up as it is.

Thanks,
Jens

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Guenter Roeck]

On Wed, Feb 10, 2021 at 02:44:09PM +0800, Jisheng Zhang wrote:
> Add tracepoints to retrieve information about the invoke_fn. This would
> help to measure how many invoke_fn are triggered and how long it takes
> to complete one invoke_fn call.
> 
> Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>

arm64:defconfig:

make-arm64 -j drivers/tee/optee/call.o
  CALL    scripts/atomic/check-atomics.sh
  CALL    scripts/checksyscalls.sh
  CC      drivers/tee/optee/call.o
In file included from drivers/tee/optee/optee_trace.h:67,
                 from drivers/tee/optee/call.c:18:
./include/trace/define_trace.h:95:42: fatal error: ./optee_trace.h: No such file or directory
   95 | #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
      |                                          ^
compilation terminated.

Guenter

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Guenter Roeck]

On Wed, Mar 24, 2021 at 07:34:07AM -0700, Guenter Roeck wrote:
> On Wed, Feb 10, 2021 at 02:44:09PM +0800, Jisheng Zhang wrote:
> > Add tracepoints to retrieve information about the invoke_fn. This would
> > help to measure how many invoke_fn are triggered and how long it takes
> > to complete one invoke_fn call.
> > 
> > Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> 
> arm64:defconfig:
> 
> make-arm64 -j drivers/tee/optee/call.o
>   CALL    scripts/atomic/check-atomics.sh
>   CALL    scripts/checksyscalls.sh
>   CC      drivers/tee/optee/call.o
> In file included from drivers/tee/optee/optee_trace.h:67,
>                  from drivers/tee/optee/call.c:18:
> ./include/trace/define_trace.h:95:42: fatal error: ./optee_trace.h: No such file or directory
>    95 | #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
>       |                                          ^
> compilation terminated.
> 

The problem also affects arm:imx_v6_v7_defconfig.

Guenter

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Steven Rostedt]

On Wed, 24 Mar 2021 07:48:53 -0700
Guenter Roeck <linux@roeck-us.net> wrote:

> On Wed, Mar 24, 2021 at 07:34:07AM -0700, Guenter Roeck wrote:
> > On Wed, Feb 10, 2021 at 02:44:09PM +0800, Jisheng Zhang wrote:  
> > > Add tracepoints to retrieve information about the invoke_fn. This would
> > > help to measure how many invoke_fn are triggered and how long it takes
> > > to complete one invoke_fn call.
> > > 
> > > Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>  
> > 
> > arm64:defconfig:
> > 
> > make-arm64 -j drivers/tee/optee/call.o
> >   CALL    scripts/atomic/check-atomics.sh
> >   CALL    scripts/checksyscalls.sh
> >   CC      drivers/tee/optee/call.o
> > In file included from drivers/tee/optee/optee_trace.h:67,
> >                  from drivers/tee/optee/call.c:18:
> > ./include/trace/define_trace.h:95:42: fatal error: ./optee_trace.h: No such file or directory
> >    95 | #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> >       |                                          ^
> > compilation terminated.
> >   
> 
> The problem also affects arm:imx_v6_v7_defconfig.
> 

I think it affects everything. The problem is that the
drivers/tee/optee/Makefile needs to be updated with:

CFLAGS_call.o := -I$(src)

otherwise the compiler wont know how to find the path to optee_tree.h.

This is described in:

   samples/trace_events/Makefile

-- Steve

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Jisheng Zhang]

On Wed, 24 Mar 2021 10:53:13 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:


> 
> On Wed, 24 Mar 2021 07:48:53 -0700
> Guenter Roeck <linux@roeck-us.net> wrote:
> 
> > On Wed, Mar 24, 2021 at 07:34:07AM -0700, Guenter Roeck wrote:  
> > > On Wed, Feb 10, 2021 at 02:44:09PM +0800, Jisheng Zhang wrote:  
> > > > Add tracepoints to retrieve information about the invoke_fn. This would
> > > > help to measure how many invoke_fn are triggered and how long it takes
> > > > to complete one invoke_fn call.
> > > >
> > > > Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>  
> > >
> > > arm64:defconfig:
> > >
> > > make-arm64 -j drivers/tee/optee/call.o
> > >   CALL    scripts/atomic/check-atomics.sh
> > >   CALL    scripts/checksyscalls.sh
> > >   CC      drivers/tee/optee/call.o
> > > In file included from drivers/tee/optee/optee_trace.h:67,
> > >                  from drivers/tee/optee/call.c:18:
> > > ./include/trace/define_trace.h:95:42: fatal error: ./optee_trace.h: No such file or directory
> > >    95 | #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> > >       |                                          ^
> > > compilation terminated.

Interesting, I always build linux kernel with "O=", didn't see such build error
and IIRC, we didn't receive any lkp robot build error report.

My steps are:

mkdir /tmp/test

make ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- O=/tmp/test defconfig

make ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- O=/tmp/test drivers/tee/optee/

Today, I tried to build the linux kernel w/o "O=...", I reproduced this error!
This is the first time I saw "O=" make a different behavior.

I'll send out a patch to fix it.

Thanks

> > >  
> >
> > The problem also affects arm:imx_v6_v7_defconfig.
> >  
> 
> I think it affects everything. The problem is that the
> drivers/tee/optee/Makefile needs to be updated with:
> 
> CFLAGS_call.o := -I$(src)
> 
> otherwise the compiler wont know how to find the path to optee_tree.h.
> 
> This is described in:
> 
>    samples/trace_events/Makefile

Thank Steven for pointing this out.

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Jens Wiklander]

On Thu, Mar 25, 2021 at 3:50 AM Jisheng Zhang
<Jisheng.Zhang@synaptics.com> wrote:
>
> On Wed, 24 Mar 2021 10:53:13 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
>
> >
> > On Wed, 24 Mar 2021 07:48:53 -0700
> > Guenter Roeck <linux@roeck-us.net> wrote:
> >
> > > On Wed, Mar 24, 2021 at 07:34:07AM -0700, Guenter Roeck wrote:
> > > > On Wed, Feb 10, 2021 at 02:44:09PM +0800, Jisheng Zhang wrote:
> > > > > Add tracepoints to retrieve information about the invoke_fn. This would
> > > > > help to measure how many invoke_fn are triggered and how long it takes
> > > > > to complete one invoke_fn call.
> > > > >
> > > > > Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> > > >
> > > > arm64:defconfig:
> > > >
> > > > make-arm64 -j drivers/tee/optee/call.o
> > > >   CALL    scripts/atomic/check-atomics.sh
> > > >   CALL    scripts/checksyscalls.sh
> > > >   CC      drivers/tee/optee/call.o
> > > > In file included from drivers/tee/optee/optee_trace.h:67,
> > > >                  from drivers/tee/optee/call.c:18:
> > > > ./include/trace/define_trace.h:95:42: fatal error: ./optee_trace.h: No such file or directory
> > > >    95 | #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> > > >       |                                          ^
> > > > compilation terminated.
>
> Interesting, I always build linux kernel with "O=", didn't see such build error
> and IIRC, we didn't receive any lkp robot build error report.
>
> My steps are:
>
> mkdir /tmp/test
>
> make ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- O=/tmp/test defconfig
>
> make ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- O=/tmp/test drivers/tee/optee/
>
> Today, I tried to build the linux kernel w/o "O=...", I reproduced this error!
> This is the first time I saw "O=" make a different behavior.

I'm also compiling with O=... and couldn't understand what was going
on. Thanks for saving me from digging any deeper.

>
> I'll send out a patch to fix it.

Thanks,
Jens

Re: [PATCH] tee: optee: add invoke_fn tracepoints

[Steven Rostedt]

On Tue, 9 Feb 2021 19:02:15 +0800
Jisheng Zhang <Jisheng.Zhang@synaptics.com> wrote:

> Add tracepoints to retrieve information about the invoke_fn. This would
> help to measure how many invoke_fn are triggered and how long it takes
> to complete one invoke_fn call.
> 
> Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
> ---
>  drivers/tee/optee/call.c        |  4 ++
>  drivers/tee/optee/optee_trace.h | 65 +++++++++++++++++++++++++++++++++
>  2 files changed, 69 insertions(+)
>  create mode 100644 drivers/tee/optee/optee_trace.h
> 
> diff --git a/drivers/tee/optee/call.c b/drivers/tee/optee/call.c
> index 780d7c4fd756..9dbab10e7ac3 100644
> --- a/drivers/tee/optee/call.c
> +++ b/drivers/tee/optee/call.c
> @@ -12,6 +12,8 @@
>  #include <linux/tee_drv.h>
>  #include <linux/types.h>
>  #include <linux/uaccess.h>
> +#define CREATE_TRACE_POINTS
> +#include "optee_trace.h"
>  #include "optee_private.h"
>  #include "optee_smc.h"
>  
> @@ -138,9 +140,11 @@ u32 optee_do_call_with_arg(struct tee_context *ctx, phys_addr_t parg)
>  	while (true) {
>  		struct arm_smccc_res res;
>  
> +		trace_optee_invoke_fn_begin(&param);
>  		optee->invoke_fn(param.a0, param.a1, param.a2, param.a3,
>  				 param.a4, param.a5, param.a6, param.a7,
>  				 &res);
> +		trace_optee_invoke_fn_end(&param, &res);
>  
>  		if (res.a0 == OPTEE_SMC_RETURN_ETHREAD_LIMIT) {
>  			/*
> diff --git a/drivers/tee/optee/optee_trace.h b/drivers/tee/optee/optee_trace.h
> new file mode 100644
> index 000000000000..f209df7004c2
> --- /dev/null
> +++ b/drivers/tee/optee/optee_trace.h
> @@ -0,0 +1,65 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +/*
> + * optee trace points
> + *
> + * Copyright (C) 2021 Synaptics Incorporated
> + * Author: Jisheng Zhang <jszhang@kernel.org>
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM optee
> +
> +#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_OPTEE_H
> +
> +#include <linux/arm-smccc.h>
> +#include <linux/tracepoint.h>
> +#include "optee_private.h"
> +
> +TRACE_EVENT(optee_invoke_fn_begin,
> +	TP_PROTO(struct optee_rpc_param *param),
> +	TP_ARGS(param),
> +
> +	TP_STRUCT__entry(
> +		__field(void *, param)
> +		__array(u32, args, 8)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->param = param;
> +		memcpy(__entry->args, param, sizeof(__entry->args));

I wonder if you should add a:

		BUILD_BUG_ON(sizeof(param) < sizeof(__entry->args));

here.

> +	),
> +
> +	TP_printk("param=%p (%x, %x, %x, %x, %x, %x, %x, %x)", __entry->param,
> +		  __entry->args[0], __entry->args[1], __entry->args[2],
> +		  __entry->args[3], __entry->args[4], __entry->args[5],
> +		  __entry->args[6], __entry->args[7])
> +);
> +
> +TRACE_EVENT(optee_invoke_fn_end,
> +	TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
> +	TP_ARGS(param, res),
> +
> +	TP_STRUCT__entry(
> +		__field(void *, param)
> +		__array(unsigned long, rets, 4)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->param = param;
> +		memcpy(__entry->rets, res, sizeof(__entry->rets));

and a:

		BUILD_BUG_ON(sizeof(res) < sizeof(__entry->rets));

here

Just to make sure that the size of what is being copied, is not smaller
than the amount being copied.

-- Steve

> +	),
> +
> +	TP_printk("param=%p ret (%lx, %lx, %lx, %lx)", __entry->param,
> +		  __entry->rets[0], __entry->rets[1], __entry->rets[2],
> +		  __entry->rets[3])
> +);
> +#endif /* _TRACE_OPTEE_H */
> +
> +#undef TRACE_INCLUDE_PATH
> +#define TRACE_INCLUDE_PATH .
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_FILE optee_trace
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>

[PATCH] tee: optee: add invoke_fn tracepoints

[Jisheng Zhang]

Add tracepoints to retrieve information about the invoke_fn. This would
help to measure how many invoke_fn are triggered and how long it takes
to complete one invoke_fn call.

Signed-off-by: Jisheng Zhang <Jisheng.Zhang@synaptics.com>
---
 drivers/tee/optee/call.c        |  4 ++
 drivers/tee/optee/optee_trace.h | 65 +++++++++++++++++++++++++++++++++
 2 files changed, 69 insertions(+)
 create mode 100644 drivers/tee/optee/optee_trace.h

diff --git a/drivers/tee/optee/call.c b/drivers/tee/optee/call.c
index 780d7c4fd756..9dbab10e7ac3 100644
--- a/drivers/tee/optee/call.c
+++ b/drivers/tee/optee/call.c
@@ -12,6 +12,8 @@
 #include <linux/tee_drv.h>
 #include <linux/types.h>
 #include <linux/uaccess.h>
+#define CREATE_TRACE_POINTS
+#include "optee_trace.h"
 #include "optee_private.h"
 #include "optee_smc.h"
 
@@ -138,9 +140,11 @@ u32 optee_do_call_with_arg(struct tee_context *ctx, phys_addr_t parg)
 	while (true) {
 		struct arm_smccc_res res;
 
+		trace_optee_invoke_fn_begin(&param);
 		optee->invoke_fn(param.a0, param.a1, param.a2, param.a3,
 				 param.a4, param.a5, param.a6, param.a7,
 				 &res);
+		trace_optee_invoke_fn_end(&param, &res);
 
 		if (res.a0 == OPTEE_SMC_RETURN_ETHREAD_LIMIT) {
 			/*
diff --git a/drivers/tee/optee/optee_trace.h b/drivers/tee/optee/optee_trace.h
new file mode 100644
index 000000000000..f209df7004c2
--- /dev/null
+++ b/drivers/tee/optee/optee_trace.h
@@ -0,0 +1,65 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * optee trace points
+ *
+ * Copyright (C) 2021 Synaptics Incorporated
+ * Author: Jisheng Zhang <jszhang@kernel.org>
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM optee
+
+#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_OPTEE_H
+
+#include <linux/arm-smccc.h>
+#include <linux/tracepoint.h>
+#include "optee_private.h"
+
+TRACE_EVENT(optee_invoke_fn_begin,
+	TP_PROTO(struct optee_rpc_param *param),
+	TP_ARGS(param),
+
+	TP_STRUCT__entry(
+		__field(void *, param)
+		__array(u32, args, 8)
+	),
+
+	TP_fast_assign(
+		__entry->param = param;
+		memcpy(__entry->args, param, sizeof(__entry->args));
+	),
+
+	TP_printk("param=%p (%x, %x, %x, %x, %x, %x, %x, %x)", __entry->param,
+		  __entry->args[0], __entry->args[1], __entry->args[2],
+		  __entry->args[3], __entry->args[4], __entry->args[5],
+		  __entry->args[6], __entry->args[7])
+);
+
+TRACE_EVENT(optee_invoke_fn_end,
+	TP_PROTO(struct optee_rpc_param *param, struct arm_smccc_res *res),
+	TP_ARGS(param, res),
+
+	TP_STRUCT__entry(
+		__field(void *, param)
+		__array(unsigned long, rets, 4)
+	),
+
+	TP_fast_assign(
+		__entry->param = param;
+		memcpy(__entry->rets, res, sizeof(__entry->rets));
+	),
+
+	TP_printk("param=%p ret (%lx, %lx, %lx, %lx)", __entry->param,
+		  __entry->rets[0], __entry->rets[1], __entry->rets[2],
+		  __entry->rets[3])
+);
+#endif /* _TRACE_OPTEE_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE optee_trace
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
-- 
2.30.0