tee: optee: add invoke_fn tracepoints

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 <[email protected]>

---

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

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 <[email protected]>

---

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

drivers/tee/optee/call.c +4 -0

index 780d7c4fd756..0da6fe50f1af 100644
@@ -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) {
                        /*

drivers/tee/optee/optee_trace.h new file +8 -0

new file mode 100644
index 000000000000..7c954eefa4bf
@@ -0,0 +1,67 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * optee trace points
+ *
+ * Copyright (C) 2021 Synaptics Incorporated
+ * Author: Jisheng Zhang <[email protected]>
+ */
+

drivers/tee/optee/optee_trace.h new file +49 -1

+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

Hi Jisheng,

Quoted 62 lines · 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 <[email protected]>

---

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

drivers/tee/optee/call.c +4 -0

index 780d7c4fd756..0da6fe50f1af 100644
@@ -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) {
                        /*

drivers/tee/optee/optee_trace.h new file +13 -0

new file mode 100644
index 000000000000..7c954eefa4bf
@@ -0,0 +1,67 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * optee trace points
+ *
+ * Copyright (C) 2021 Synaptics Incorporated
+ * Author: Jisheng Zhang <[email protected]>
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM optee
+
+#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_OPTEE_H

drivers/tee/optee/optee_trace.h line 18

Quoted 5 lines

drivers/tee/optee/optee_trace.h new file +5 -0

+
+#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

Quoted 52 lines

drivers/tee/optee/optee_trace.h new file +49 -1

+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

Quoted 2 lines · On Tue, 23 Feb 2021 08:59:22 +0100 Jens Wiklander wrote:

Hi Jisheng,

Hi Jens,

Quoted 21 lines

Quoted 18 lines · 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 <[email protected]>

---

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

Quoted 19 lines

Quoted 19 lines

drivers/tee/optee/optee_trace.h new file +13 -0

new file mode 100644
index 000000000000..7c954eefa4bf
@@ -0,0 +1,67 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * optee trace points
+ *
+ * Copyright (C) 2021 Synaptics Incorporated
+ * Author: Jisheng Zhang <[email protected]>
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM optee
+
+#if !defined(_TRACE_OPTEE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_OPTEE_H

Quoted 8 lines

drivers/tee/optee/optee_trace.h line 18

Quoted 5 lines

drivers/tee/optee/optee_trace.h new file +5 -0

+
+#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:

drivers/tee/optee/optee_trace.h new file +2 -0

+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:

(quoted diff) +1 -0

+	TP_STRUCT__entry(

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

(quoted diff) +1 -0

+	TP_fast_assign(

CHECK: Alignment should match open parenthesis
#89: FILE: drivers/tee/optee/optee_trace.h:41:

drivers/tee/optee/optee_trace.h new file +2 -0

+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:

(quoted diff) +1 -0

+	TP_STRUCT__entry(

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

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

Quoted 6 lines · On Tue, 23 Feb 2021 14:11:24 +0100 Jens Wiklander <[email protected]>…

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.

Quoted 23 lines

CHECK: Alignment should match open parenthesis
#68: FILE: drivers/tee/optee/optee_trace.h:20:

drivers/tee/optee/optee_trace.h new file +2 -0

+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:

(quoted diff) +1 -0

+	TP_STRUCT__entry(

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

(quoted diff) +1 -0

+	TP_fast_assign(

CHECK: Alignment should match open parenthesis
#89: FILE: drivers/tee/optee/optee_trace.h:41:

drivers/tee/optee/optee_trace.h new file +2 -0

+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:

(quoted diff) +1 -0

+	TP_STRUCT__entry(

Review

Quoted 3 lines

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

(quoted diff) +1 -0

+	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.

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 <[email protected]>

Quoted 5 lines · 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 <[email protected]>

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.

Quoted 13 lines · Guenter Roeck

Quoted 5 lines · 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 <[email protected]>

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

Quoted 7 lines

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.

Quoted 10 lines · On Wed, 24 Mar 2021 07:48:53 -0700 Guenter Roeck <[email protected]> wrote:

Quoted 9 lines · Guenter Roeck

Quoted 5 lines · 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 <[email protected]>

arm64:defconfig:

Quoted 10 lines

Quoted 10 lines

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.

Quoted 4 lines

Quoted 1 line

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

Quoted 14 lines · On Wed, 24 Mar 2021 10:53:13 -0400 Steven Rostedt <[email protected]> wrote:

Quoted 10 lines · On Wed, 24 Mar 2021 07:48:53 -0700 Guenter Roeck <[email protected]> wrote:

Quoted 9 lines · Guenter Roeck

Quoted 5 lines · 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 <[email protected]>

arm64:defconfig:

Quoted 10 lines

Quoted 10 lines

Quoted 10 lines

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.