ftrace: Add function execution time support #3117

b49020 · 2019-07-04T09:37:11Z

This patch-set adds function execution time support and is in continuation of PR: #3080 with comments incorporated. So after this patch-set function graph would look something like:

              | __ta_entry() {
              |  __utee_entry() {
     1.168 us |   ta_header_get_session();
     1.392 us |   __utee_to_param();
              |   TA_InvokeCommandEntryPoint() {
              |    ta_entry_params_access_rights() {
    31.392 us |     TEE_CheckMemoryAccessRights();
    28.176 us |     TEE_CheckMemoryAccessRights();
   173.984 us |    }
   202.448 us |   }
     1.152 us |   __utee_from_param();
              |   ta_header_save_params() {
      .656 us |    memset();
     5.488 us |   }
   275.824 us |  }
   281.424 us | }

Looking forward to your valuable feedback/comments.

Regards,
Sumit

jenswi-linaro · 2019-07-08T08:09:32Z

Comment for "ftrace: Add function execution time support":
It seems that the ldelf changes can go into a separate commit just before this. Also please do cleanup in separate patches.

jforissier

Reviewing "libutee: add headers for user-space to access sysregs":

Please see below. Also, you could name the header in the commit subject: s/add headers/add <arm_user_sysreg.h>/.

core/arch/arm/arm.mk

lib/libutee/include/arm64_user_sysreg.h

lib/libutee/include/arm_user_sysreg.h

jforissier

For commit "core: ftrace: Enable user-space access to counter regs":

Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org>

b49020 · 2019-07-08T12:14:00Z

@jenswi-linaro

It seems that the ldelf changes can go into a separate commit just before this.

Ok.

Also please do cleanup in separate patches.

Can you please point to changes where you see them as cleanups?

ldelf/ftrace.c

b49020 · 2019-07-09T08:00:47Z

Updated PR.

b49020 · 2019-07-11T08:19:15Z

Any further comments?

jenswi-linaro · 2019-07-19T07:36:48Z

Please address the comments you haven't addressed yet.

b49020 · 2019-07-19T08:33:50Z

I am not sure which comments you are referring too. If you are looking for generation of custom arm32_user_sysreg.h file for user-space then I have already raised some concerns in this comment which weren't addressed.

jenswi-linaro · 2019-07-19T09:45:48Z

I stopped at the ta_arm32-platform-cppflags += -I$(out-dir)/core/include/generated/ comment since I thought we had agreed that we shouldn't let user space code use that include directory.

jenswi-linaro

A comment for the commit "libutee: add headers for user-space to access sysregs"

lib/libutee/include/arm64_user_sysreg.h

jforissier · 2019-07-30T16:15:08Z

For "libutee: add headers for user-space to access sysregs":

Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org>

core/arch/arm/kernel/user_ta.c

b49020 · 2019-08-09T07:35:29Z

Any further comments?

jforissier

Some minor comments below, in any case:
For "ldelf: ftrace: pass ftrace buffer address to kernel" and "ftrace: Add function execution time support":

Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org>

core/arch/arm/include/sm/sm.h

core/arch/arm/kernel/thread.c

lib/libutee/arch/arm/ftrace/ftrace.c

core/kernel/tee_ta_manager.c

b49020 · 2019-08-09T13:38:20Z

Squashed and tags applied.

jforissier · 2019-08-09T16:11:44Z

@b49020 Testing on QEMU.

xtest 4002 crashes with what looks like a stack overflow (and quite possibly infinite recursion) when I instrument the user libraries. That is, build with: make CFG_TA_FTRACE_SUPPORT=y CFG_TA_MCOUNT=y CFG_ULIBS_MCOUNT=y run.
Trying parent commit ("ldelf: ftrace: pass ftrace buffer address to kernel"), does not build properly:

$ make CFG_TA_FTRACE_SUPPORT=y CFG_TA_MCOUNT=y CFG_ULIBS_MCOUNT=y run
  CC      out/arm/ldelf/ftrace.o
ldelf/ftrace.c: In function 'ftrace_init':
ldelf/ftrace.c:46:9: warning: cast to pointer from integer of different size [-Wint-to-pointer-cast]
  fbuf = (struct ftrace_buf *)finfo->buf_start.ptr64;
         ^
ldelf/ftrace.c:56:6: error: 'struct ftrace_buf' has no member named 'suspend_time'
  fbuf->suspend_time = 0;
      ^~
make[1]: *** [mk/compile.mk:147: out/arm/ldelf/ftrace.o] Error 1
make[1]: Leaving directory '/home/jerome/work/optee_build_qemu/optee_os'
make: *** [common/common.mk:307: optee-os-common] Error 2

b49020 · 2019-08-12T05:04:16Z

@jforissier

xtest 4002 crashes with what looks like a stack overflow (and quite possibly infinite recursion) when I instrument the user libraries. That is, build with: make CFG_TA_FTRACE_SUPPORT=y CFG_TA_MCOUNT=y CFG_ULIBS_MCOUNT=y run.

It works well for me on QEMU 64 bit. Did you applied TF-A patch while testing?

Trying parent commit ("ldelf: ftrace: pass ftrace buffer address to kernel"), does not build properly:

Will fix.

jforissier · 2019-08-12T06:44:13Z

It works well for me on QEMU 64 bit.

I have tested QEMU 32 bit.

Did you applied TF-A patch while testing?

Which patch? I am using v2.0-507-g34efb683 as in current manifest.git.

b49020 · 2019-08-12T09:42:01Z

@jforissier I have tested this on QEMU 64 bit only for both 64 bit as well as 32 bit apps.

Which patch? I am using v2.0-507-g34efb683 as in current manifest.git.

I was referring to https://git.trustedfirmware.org/TF-A/trusted-firmware-a.git/commit/?h=integration&id=43f999a7e35db5bdbb5af6dfc7efc46f6ecab443. But its needed for QEMU 64 bit only.

I have tested QEMU 32 bit.

Now I could reproduce the issue. It seems that compiler isn't able to inline sysreg APIs in arm32_user_sysreg.h, leading to creation of proper functions which are instrumented. And these sysreg APIs are used in profiling code leading to infinite loop. So to avoid this recursion mark these sysreg APIs as __noprof in header generation script (arm32_sysreg.py) only.

Please give it a retry.

Also, I have fixed following:

Trying parent commit ("ldelf: ftrace: pass ftrace buffer address to kernel"), does not build properly:

jforissier · 2019-08-12T12:39:48Z

So to avoid this recursion mark these sysreg APIs as __noprof

Makes sense. It's working now. Another option would be to use the __noprof versions only in the profiling code. But that would be a bit more complicated, and we probably don't loose much by not profiling the register accessors globally.

Should the same fix be applied to lib/libutee/include/arm64_user_sysreg.h? It seems the compiler could also decide not to inline those functions too...

Feel free to add my:

Tested-by: Jerome Forissier <jerome.forissier@linaro.org> (QEMU)

...to "ftrace: Add function execution time support".

scripts/arm32_sysreg.py

b49020 · 2019-08-12T12:48:51Z

Should the same fix be applied to lib/libutee/include/arm64_user_sysreg.h? It seems the compiler could also decide not to inline those functions too...

Makes sense. Will add __noprof for them also.

b49020 · 2019-08-12T13:11:44Z

Squashed fix and applied tested-by tag.

jforissier · 2019-08-12T15:06:20Z

Thanks @b49020. Let's leave some time for @jenswi-linaro to review again.

jenswi-linaro · 2019-08-13T05:55:29Z

Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org>

To enable function execution time support in function tracing output, user-space ftrace framework needs to access frequency register and physical counter register. So enable user-space access. Signed-off-by: Sumit Garg <sumit.garg@linaro.org> Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org> Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org>

User space may require to access system registers like generic timer registers in case function tracing is enabled etc. So provide headers for user space to access sysregs. Signed-off-by: Sumit Garg <sumit.garg@linaro.org> Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org> Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org>

Enable support to pass ftrace buffer address to kernel during loading of particular TA. It is required to support function execution time feature since kernel needs to update timestamps in ftrace buffer during TA suspends for proper execution time. Signed-off-by: Sumit Garg <sumit.garg@linaro.org> Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org> Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org>

Add support to dump function execution time at corresponding function exit points in output ftrace buffer. To achieve proper function execution time we need to exclude TA suspend time from timestamps, so add corresponding support in TEE core. Also user mapping must be active to access ftrace buffer, so do that during TA resume. Signed-off-by: Sumit Garg <sumit.garg@linaro.org> Reviewed-by: Jerome Forissier <jerome.forissier@linaro.org> Tested-by: Jerome Forissier <jerome.forissier@linaro.org> (QEMU) Reviewed-by: Jens Wiklander <jens.wiklander@linaro.org>

b49020 · 2019-08-13T06:03:19Z

Tag applied.

b49020 force-pushed the master branch from fb82288 to 1c7988a Compare July 4, 2019 10:09

jforissier reviewed Jul 8, 2019

View reviewed changes

core/arch/arm/arm.mk Outdated Show resolved Hide resolved

lib/libutee/include/arm64_user_sysreg.h Show resolved Hide resolved

lib/libutee/include/arm_user_sysreg.h Outdated Show resolved Hide resolved

jforissier reviewed Jul 8, 2019

View reviewed changes

jenswi-linaro reviewed Jul 8, 2019

View reviewed changes

ldelf/ftrace.c Show resolved Hide resolved

b49020 force-pushed the master branch from 1c7988a to fa020f7 Compare July 9, 2019 07:59

jenswi-linaro reviewed Jul 29, 2019

View reviewed changes

lib/libutee/include/arm64_user_sysreg.h Outdated Show resolved Hide resolved

b49020 force-pushed the master branch from ae40f7d to 40d9932 Compare July 29, 2019 12:58

jforissier reviewed Aug 2, 2019

View reviewed changes

core/arch/arm/kernel/user_ta.c Outdated Show resolved Hide resolved

b49020 force-pushed the master branch from 3dc3cb1 to 18bbd98 Compare August 9, 2019 11:51

jforissier reviewed Aug 9, 2019

View reviewed changes

core/arch/arm/include/sm/sm.h Show resolved Hide resolved

core/arch/arm/kernel/thread.c Outdated Show resolved Hide resolved

lib/libutee/arch/arm/ftrace/ftrace.c Outdated Show resolved Hide resolved

core/kernel/tee_ta_manager.c Show resolved Hide resolved

b49020 force-pushed the master branch from 18bbd98 to 552ddcc Compare August 9, 2019 13:37

b49020 force-pushed the master branch from 552ddcc to 07062e1 Compare August 12, 2019 09:27

jforissier reviewed Aug 12, 2019

View reviewed changes

scripts/arm32_sysreg.py Show resolved Hide resolved

b49020 force-pushed the master branch from 07062e1 to 7415061 Compare August 12, 2019 13:09

b49020 added 4 commits August 13, 2019 11:29

b49020 force-pushed the master branch from 7415061 to a1f05cf Compare August 13, 2019 06:02

jforissier merged commit f5df167 into OP-TEE:master Aug 13, 2019

jforissier mentioned this pull request Jan 16, 2020

Update TF-A to support NS_TIMER_SWITCH := 1 OP-TEE/manifest#152

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ftrace: Add function execution time support #3117

ftrace: Add function execution time support #3117

b49020 commented Jul 4, 2019

jenswi-linaro commented Jul 8, 2019

jforissier left a comment

jforissier left a comment

b49020 commented Jul 8, 2019

b49020 commented Jul 9, 2019

b49020 commented Jul 11, 2019

jenswi-linaro commented Jul 19, 2019

b49020 commented Jul 19, 2019

jenswi-linaro commented Jul 19, 2019

jenswi-linaro left a comment

jforissier commented Jul 30, 2019

b49020 commented Aug 9, 2019

jforissier left a comment

b49020 commented Aug 9, 2019

jforissier commented Aug 9, 2019 •

edited

b49020 commented Aug 12, 2019

jforissier commented Aug 12, 2019

b49020 commented Aug 12, 2019

jforissier commented Aug 12, 2019

b49020 commented Aug 12, 2019

b49020 commented Aug 12, 2019

jforissier commented Aug 12, 2019

jenswi-linaro commented Aug 13, 2019

b49020 commented Aug 13, 2019

ftrace: Add function execution time support #3117

ftrace: Add function execution time support #3117

Conversation

b49020 commented Jul 4, 2019

jenswi-linaro commented Jul 8, 2019

jforissier left a comment

Choose a reason for hiding this comment

jforissier left a comment

Choose a reason for hiding this comment

b49020 commented Jul 8, 2019

b49020 commented Jul 9, 2019

b49020 commented Jul 11, 2019

jenswi-linaro commented Jul 19, 2019

b49020 commented Jul 19, 2019

jenswi-linaro commented Jul 19, 2019

jenswi-linaro left a comment

Choose a reason for hiding this comment

jforissier commented Jul 30, 2019

b49020 commented Aug 9, 2019

jforissier left a comment

Choose a reason for hiding this comment

b49020 commented Aug 9, 2019

jforissier commented Aug 9, 2019 • edited

b49020 commented Aug 12, 2019

jforissier commented Aug 12, 2019

b49020 commented Aug 12, 2019

jforissier commented Aug 12, 2019

b49020 commented Aug 12, 2019

b49020 commented Aug 12, 2019

jforissier commented Aug 12, 2019

jenswi-linaro commented Aug 13, 2019

b49020 commented Aug 13, 2019

jforissier commented Aug 9, 2019 •

edited