ftrace: ftrace_format.py: display seconds

When the time spent in a function is 1 second or more, display it as
seconds not milliseconds in order to keep the output nicely aligned.

Signed-off-by: Je

ftrace: ftrace_format.py: display seconds

When the time spent in a function is 1 second or more, display it as
seconds not milliseconds in order to keep the output nicely aligned.

Signed-off-by: Jerome Forissier <jerome.forissier@linaro.org>
Reviewed-by: Joakim Bech <joakim.bech@linaro.org>
Acked-by: Jens Wiklander <jens.wiklander@linaro.org>

show more ...

ftrace: change implementation to use binary circular buffer

The current implementation of function tracing (CFG_FTRACE_SUPPORT)
produces human-readable text into the output buffer that is passed to

ftrace: change implementation to use binary circular buffer

The current implementation of function tracing (CFG_FTRACE_SUPPORT)
produces human-readable text into the output buffer that is passed to
tee-supplicant and ultimately saved to the Linux filesystem. Two main
issues with that:

1. The string formatting code is somewhat complex. It introduces
significant overhead in the execution time of the instrumented
functions.
2. The various policies about how to handle a buffer full condition
(CFG_FTRACE_BUF_WHEN_FULL) are not very convenient. In particular,
"shift" is typically the most desirable option because it always
keeps the most recent entries, but it is very inefficient to the
point of not being usable in practice.

This commit addresses the above concerns by making the ftrace buffer
circular one, each entry being 64-bit value. The formatting code is
offloaded to a new Python script: scripts/ftrace_format.py. The
output is unchanged except for an added field showing the current
depth in the call stack.

Typical usage (captured on QEMUv8):

build$ mkdir -p ../tmp
build$ chmod a+w ../tmp
build$ make CFG_FTRACE_SUPPORT=y CFG_FTRACE_BUF_SIZE=15000 \
CFG_TA_MCOUNT=y CFG_ULIBS_MCOUNT=y CFG_SYSCALL_FTRACE=y \
QEMU_VIRTFS_AUTOMOUNT=y run
$ xtest regression_1004
...
$ cp /tmp/ftrace-cb3e5ba0-adf1-11e0-998b-0002a5d5c51b.out /mnt/host/tmp
build$ cd ..
optee$ optee_os/scripts/ftrace_format.py \
tmp/ftrace-cb3e5ba0-adf1-11e0-998b-0002a5d5c51b.out |
optee_os/scripts/symbolize.py \
-d optee_os/out/arm/core \
-d out-br/build/optee_test_ext-1.0/ta/*/out | less
TEE load address @ 0x5ab04000
Function graph for TA: cb3e5ba0-adf1-11e0-998b-0002a5d5c51b @ 80085000
| 1 | __ta_entry() {
| 2 | __utee_entry() {
43.840 us | 3 | ta_header_get_session()
7.216 us | 3 | tahead_get_trace_level()
14.480 us | 3 | trace_set_level()
| 3 | malloc_add_pool() {
| 4 | raw_malloc_add_pool() {
46.032 us | 5 | bpool()
| 5 | raw_realloc() {
166.256 us | 6 | bget()
23.056 us | 6 | raw_malloc_return_hook()
267.952 us | 5 | }
398.720 us | 4 | }
426.992 us | 3 | }
| 3 | TEE_GetPropertyAsU32() {
23.600 us | 4 | is_propset_pseudo_handle()
| 4 | __utee_check_instring_annotation() {
26.416 us | 5 | strlen()
| 5 | check_access() {
| 6 | TEE_CheckMemoryAccessRights() {
| 7 | _utee_check_access_rights() {
| 8 | syscall_check_access_rights() {
| 9 | ts_get_current_session() {
4.304 us | 10 | ts_get_current_session_may_fail()
10.976 us | 9 | }
| 9 | to_user_ta_ctx() {
2.496 us | 10 | is_user_ta_ctx()
8.096 us | 9 | }
| 9 | vm_check_access_rights() {
| 10 | vm_buf_is_inside_um_private() {
| 11 | core_is_buffer_inside() {
...

Signed-off-by: Jerome Forissier <jerome.forissier@linaro.org>
Acked-by: Jens Wiklander <jens.wiklander@linaro.org>
Reviewed-by: Sumit Garg <sumit.garg@linaro.org>
Acked-by: Etienne Carriere <etienne.carriere@foss.st.com>

show more ...