aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJames Kung <kong1191@gmail.com>2015-01-27 02:11:22 +0800
committerJames Kung <kong1191@gmail.com>2015-01-30 15:05:31 +0800
commitc02a78b1cb1c85040487a4e12792531dd553f38f (patch)
treef86ecc652c3728d3c7e778ef2692872e2750906a
parent6406826ef35366200fe69cae9ae8f8f90961ec5d (diff)
New performance analysis tool and system call changed
- performance analysis tool for parsing logfile and generate performance report - Refactor generic timer register access functions - Secure system call changed - Modify setup scripts to default enable performance analysis flags
-rw-r--r--host/Makefile2
l---------host/arm_sys_counter.c1
l---------host/include/arm_sys_counter.h1
-rw-r--r--host/simple_client.c10
-rw-r--r--libsyscounter/arm_sys_counter.c68
-rw-r--r--libsyscounter/arm_sys_counter.h37
-rw-r--r--script/README.md111
-rw-r--r--script/performance_analysis.py290
-rw-r--r--script/sample_log.txt51
-rwxr-xr-xscript/setup_fvp_optee.sh9
-rwxr-xr-xscript/setup_qemu_optee.sh8
l---------ta/arm_sys_counter.c1
-rw-r--r--[l---------]ta/include/arm_sys_counter.h97
-rw-r--r--ta/simple_ta.c38
-rw-r--r--ta/sub.mk1
15 files changed, 596 insertions, 129 deletions
diff --git a/host/Makefile b/host/Makefile
index 04aee4a..bf01efc 100644
--- a/host/Makefile
+++ b/host/Makefile
@@ -7,7 +7,7 @@ OBJCOPY = $(CROSS_COMPILE)objcopy
OBJDUMP = $(CROSS_COMPILE)objdump
READELF = $(CROSS_COMPILE)readelf
-OBJS = simple_client.o arm_sys_counter.o
+OBJS = simple_client.o
CFLAGS += -Wall -I../ta/include -I$(TEEC_EXPORT)/include -I./include
LDADD += -lteec -L$(TEEC_EXPORT)/lib
diff --git a/host/arm_sys_counter.c b/host/arm_sys_counter.c
deleted file mode 120000
index 63e91af..0000000
--- a/host/arm_sys_counter.c
+++ /dev/null
@@ -1 +0,0 @@
-../libsyscounter/arm_sys_counter.c \ No newline at end of file
diff --git a/host/include/arm_sys_counter.h b/host/include/arm_sys_counter.h
deleted file mode 120000
index d544def..0000000
--- a/host/include/arm_sys_counter.h
+++ /dev/null
@@ -1 +0,0 @@
-../../libsyscounter/arm_sys_counter.h \ No newline at end of file
diff --git a/host/simple_client.c b/host/simple_client.c
index b6e3c2f..bbbe2ea 100644
--- a/host/simple_client.c
+++ b/host/simple_client.c
@@ -68,12 +68,12 @@ TEEC_Result measure_time_of_open_session(TEEC_UUID *uuid, TEEC_Context *ctx, TEE
op.params[0].tmpref.buffer = (void *)&counter_ta;
op.params[0].tmpref.size = sizeof(counter_ta);
- counter_start = arm_sys_counter_get_counter();
+ counter_start = read_cntvct();
res = TEEC_OpenSession(ctx, sess, uuid,
TEEC_LOGIN_PUBLIC, NULL, &op, &err_origin);
- counter_end = arm_sys_counter_get_counter();
+ counter_end = read_cntvct();
if (res != TEEC_SUCCESS) {
errx(1, "TEEC_Opensession failed with code 0x%x origin 0x%x",
@@ -105,11 +105,11 @@ TEEC_Result measure_time_of_invoke_command(TEEC_Session *sess)
op.params[0].tmpref.buffer = (void *)&counter_ta;
op.params[0].tmpref.size = sizeof(counter_ta);
- counter_start = arm_sys_counter_get_counter();
+ counter_start = read_cntvct();
res = TEEC_InvokeCommand(sess, TAF_REPORT_TIMESTAMP, &op, &err_origin);
- counter_end = arm_sys_counter_get_counter();
+ counter_end = read_cntvct();
if (res != TEEC_SUCCESS) {
errx(1, "TEEC_InvokeCommand failed with code 0x%x origin 0x%x",
@@ -184,7 +184,7 @@ void measure_performance(void)
*/
TEEC_UUID uuid = SIMPLE_TA_UUID;
- uint32_t freq = arm_sys_counter_get_frequency();
+ uint32_t freq = read_cntfrq();
printf("CounterTimerFrequency: 0x%x\n", freq);
res = measure_time_of_open_session(&uuid, &ctx, &sess);
diff --git a/libsyscounter/arm_sys_counter.c b/libsyscounter/arm_sys_counter.c
deleted file mode 100644
index 90da6fc..0000000
--- a/libsyscounter/arm_sys_counter.c
+++ /dev/null
@@ -1,68 +0,0 @@
-/*
- * Copyright (c) 2014, Linaro Limited
- * All rights reserved.
- *
- * Redistribution and use in source and binary forms, with or without
- * modification, are permitted provided that the following conditions are met:
- *
- * 1. Redistributions of source code must retain the above copyright notice,
- * this list of conditions and the following disclaimer.
- *
- * 2. Redistributions in binary form must reproduce the above copyright notice,
- * this list of conditions and the following disclaimer in the documentation
- * and/or other materials provided with the distribution.
- *
- * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
- * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
- * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
- * ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
- * liABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
- * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
- * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
- * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
- * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
- * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
- * POSSIBILITY OF SUCH DAMAGE.
- */
-#include <arm_sys_counter.h>
-
-#define WORD_SIZE 32
-
-uint64_t arm_sys_counter_get_counter(void)
-{
- uint64_t val;
-
-#ifdef __aarch64__
-
- asm volatile("mrs %0, cntvct_el0" : "=r"(val));
-
-#else
-
- uint32_t cntvct_low, cntvct_high;
- __asm__ volatile("mrrc p15, 1, %0, %1, c14"
- : "=r"(cntvct_low), "=r"(cntvct_high));
-
- val = cntvct_low | ((uint64_t)cntvct_high << WORD_SIZE);
-
-#endif
-
- return val;
-}
-
-
-uint32_t arm_sys_counter_get_frequency(void)
-{
- uint32_t frq;
-
-#ifdef __aarch64__
-
- asm volatile("mrs %0, cntfrq_el0" : "=r"(frq));
-
-#else
-
- asm volatile("mrc p15, 0, %0, c14, c0, 0" : "=r"(frq));
-
-#endif
-
- return frq;
-}
diff --git a/libsyscounter/arm_sys_counter.h b/libsyscounter/arm_sys_counter.h
deleted file mode 100644
index 8406051..0000000
--- a/libsyscounter/arm_sys_counter.h
+++ /dev/null
@@ -1,37 +0,0 @@
-/*
- * Copyright (c) 2014, Linaro Limited
- * All rights reserved.
- *
- * Redistribution and use in source and binary forms, with or without
- * modification, are permitted provided that the following conditions are met:
- *
- * 1. Redistributions of source code must retain the above copyright notice,
- * this list of conditions and the following disclaimer.
- *
- * 2. Redistributions in binary form must reproduce the above copyright notice,
- * this list of conditions and the following disclaimer in the documentation
- * and/or other materials provided with the distribution.
- *
- * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
- * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
- * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
- * ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
- * liABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
- * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
- * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
- * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
- * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
- * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
- * POSSIBILITY OF SUCH DAMAGE.
- */
-#ifndef OPTEE_BENCHMARK_LIBSYSCOUNTER_ARM_SYS_COUNTER_H_
-#define OPTEE_BENCHMARK_LIBSYSCOUNTER_ARM_SYS_COUNTER_H_
-
-#include <stdint.h>
-#include <inttypes.h>
-
-uint64_t arm_sys_counter_get_counter(void);
-uint32_t arm_sys_counter_get_frequency(void);
-
-
-#endif /* OPTEE_BENCHMARK_LIBSYSCOUNTER_ARM_SYS_COUNTER_H_ */
diff --git a/script/README.md b/script/README.md
new file mode 100644
index 0000000..3615bf2
--- /dev/null
+++ b/script/README.md
@@ -0,0 +1,111 @@
+OP-TEE benchmark performance analysis tool
+---
+
+performance_analysis.py can help to analysis the REE and TEE console outputs and generate a performance report.
+
+Usage:
+
+ $ python performance_analysis.py <logfile>
+
+
+# Log file format
+
+Script scan the logfile content and find out the data needed for performance analysis.
+The following message patterns are used by the script to parse the logfile:
+
+Printed by Host Application (simple_client):
+
+* CounterTimerFrequency: `<counter frequency>`
+* ClientOpenSession: start=`<counter value>`, enter_ta=`<counter value>`, return=`<counter value>`
+* ClientInvokeCommand: start=`<counter value>`, enter_ta=`<counter value>`, return=`<counter value>`
+* SecureSysCall: start=`<counter value>`, enter_svc=`<counter value>`, return=`<counter value>`
+
+Printed by OP-TEE Linux driver:
+
+* TEEDriver: do smc call, cmd=`<cmd number>`, cntvct=`<counter value>`
+* TEEDriver: finish smc call, cmd=`<cmd number>`, cntvct=`<counter value>`
+
+Printed by OP-TEE OS:
+
+* TEECore: receiving smc call, cmd=`<cmd number>`, cntvct=`<counter value>`
+* TEECore: finish smc call, cmd=`<cmd number>`, cntvct=`<counter value>`
+
+
+# Performance Report
+
+Here is a sample performance report.
+
+The "Interval" field shows how long does it takes from previous step to current step.
+For example, if we want to know how long doest it takes from "Client start Open Session command"
+to "Driver start SMC call", we can look at the interval value at the same line as "Driver start
+SMC Call" in the "Open Session" section, that is 398672(ns).
+
+Interval = (CounterValueOfCurrentStep - CounterValueOfPreviousStep) x (CounterResolution)
+
+```
+$ cd script/
+$ python performance_analysis.py sample_log.txt
+Counter resolution (ns) = 16
+
+================================================================
+Open Session
+================================================================
+When Counter Value Interval(ns)
+----------------------------------------------------------------
+Client Start Command 19411438612 0
+Driver Start SMC Call 19411463529 398672
+TEE OS Receive SMC Call 19411497473 543104
+TA Enter Command 19412202128 11274480
+TEE OS Finish SMC Call 19412296092 1503424
+Driver Finish SMC Call 19412368547 1159280
+Client Return From Command 19412416471 766784
+
+----------------------------------------------------------------
+Summary
+----------------------------------------------------------------
+Client -> TA (one way trip) = 12216256 (ns)
+Client -> Client (round trip) = 15645744 (ns)
+SMC Call Send To Secure OS = 543104 (ns)
+SMC Call Return From Secure OS = 1159280 (ns)
+
+
+================================================================
+Invoke Command
+================================================================
+When Counter Value Interval(ns)
+----------------------------------------------------------------
+Client Start Command 19412494140 0
+Driver Start SMC Call 19412517733 377488
+TEE OS Receive SMC Call 19412551522 540624
+TA Enter Command 19412613966 999104
+TEE OS Finish SMC Call 19412802652 3018976
+Driver Finish SMC Call 19412859796 914304
+Client Return From Command 19412920217 966736
+
+----------------------------------------------------------------
+Summary
+----------------------------------------------------------------
+Client -> TA (one way trip) = 1917216 (ns)
+Client -> Client (round trip) = 6817232 (ns)
+SMC Call Send To Secure OS = 540624 (ns)
+SMC Call Return From Secure OS = 914304 (ns)
+
+
+================================================================
+Secure System Call (TEE_GetPropertyAsBinaryBlock)
+================================================================
+When Counter Value Interval(ns)
+----------------------------------------------------------------
+TA Invoke System Call 19413195393 0
+Secure OS Receive System Call 19413225884 487856
+TA Return From System Call 19413228214 37280
+
+----------------------------------------------------------------
+Summary
+----------------------------------------------------------------
+TA -> OS = 487856 (ns)
+OS -> TA = 37280 (ns)
+TA -> TA = 525136 (ns)
+
+$
+``` \ No newline at end of file
diff --git a/script/performance_analysis.py b/script/performance_analysis.py
new file mode 100644
index 0000000..c17b44d
--- /dev/null
+++ b/script/performance_analysis.py
@@ -0,0 +1,290 @@
+import re
+import sys
+
+
+class OperationCounterInfo:
+ def __init__(self, name):
+ self.name = name
+ self.client_start_cmd = 0L
+ self.client_return_cmd = 0L
+ self.driver_start_smc = 0L
+ self.driver_finish_smc = 0L
+ self.tee_os_receive_smc = 0L
+ self.tee_os_finish_smc = 0L
+ self.ta_enter_cmd = 0L
+
+ def __repr__(self):
+ tmp_str = self.name + "\n"
+ tmp_str += "\tClient Start Command =%d\n" % self.client_start_cmd
+ tmp_str += "\tDriver Start SMC Call =%d\n" % self.driver_start_smc
+ tmp_str += "\tTEE OS Receive SMC Call =%d\n" % self.tee_os_receive_smc
+ tmp_str += "\tTA Enter Command =%d\n" % self.ta_enter_cmd
+ tmp_str += "\tTEE OS Finish SMC Call =%d\n" % self.tee_os_finish_smc
+ tmp_str += "\tDriver Finish SMC Call =%d\n" % self.driver_finish_smc
+ tmp_str += "\tClient Return From Command =%d\n" % self.client_return_cmd
+ return tmp_str
+
+ def do_analysis(self, resolution_in_ns):
+ tmp_str = "================================================================\n"
+ tmp_str += self.name + "\n"
+ tmp_str += "================================================================\n"
+ tmp_str += "When Counter Value Interval(ns)\n"
+ tmp_str += "----------------------------------------------------------------\n"
+ tmp_str += "Client Start Command %16d%16d\n" % (self.client_start_cmd, 0)
+ tmp_str += "Driver Start SMC Call %16d%16d\n" % (self.driver_start_smc , resolution_in_ns * (self.driver_start_smc - self.client_start_cmd ))
+ tmp_str += "TEE OS Receive SMC Call %16d%16d\n" % (self.tee_os_receive_smc, resolution_in_ns * (self.tee_os_receive_smc - self.driver_start_smc ))
+ tmp_str += "TA Enter Command %16d%16d\n" % (self.ta_enter_cmd , resolution_in_ns * (self.ta_enter_cmd - self.tee_os_receive_smc))
+ tmp_str += "TEE OS Finish SMC Call %16d%16d\n" % (self.tee_os_finish_smc , resolution_in_ns * (self.tee_os_finish_smc - self.ta_enter_cmd ))
+ tmp_str += "Driver Finish SMC Call %16d%16d\n" % (self.driver_finish_smc , resolution_in_ns * (self.driver_finish_smc - self.tee_os_finish_smc ))
+ tmp_str += "Client Return From Command %16d%16d\n" % (self.client_return_cmd , resolution_in_ns * (self.client_return_cmd - self.driver_finish_smc ))
+ tmp_str += "\n"
+ tmp_str += "----------------------------------------------------------------\n"
+ tmp_str += "Summary\n"
+ tmp_str += "----------------------------------------------------------------\n"
+ tmp_str += "Client -> TA (one way trip) = %10d (ns)\n" % (resolution_in_ns * (self.ta_enter_cmd - self.client_start_cmd))
+ tmp_str += "Client -> Client (round trip) = %10d (ns)\n" % (resolution_in_ns * (self.client_return_cmd - self.client_start_cmd))
+ tmp_str += "SMC Call Send To Secure OS = %10d (ns)\n" % (resolution_in_ns * (self.tee_os_receive_smc - self.driver_start_smc))
+ tmp_str += "SMC Call Return From Secure OS = %10d (ns)\n" % (resolution_in_ns * (self.driver_finish_smc - self.tee_os_finish_smc))
+ tmp_str += "\n"
+ return tmp_str
+
+
+class SysCallCounterInfo:
+ def __init__(self, name):
+ self.name = name
+ self.start = 0L
+ self.enter = 0L
+ self.finish = 0L
+
+ def __repr__(self):
+ tmp_str = self.name + "\n"
+ tmp_str += "\tTA Invoke System Call =%d\n" % self.start
+ tmp_str += "\tTEE OS Receive System Call =%d\n" % self.enter
+ tmp_str += "\tTA Return From System Call =%d\n" % self.finish
+ return tmp_str
+
+ def do_analysis(self, resolution_in_ns):
+ tmp_str = "================================================================\n"
+ tmp_str += self.name + "\n"
+ tmp_str += "================================================================\n"
+ tmp_str += "When Counter Value Interval(ns)\n"
+ tmp_str += "----------------------------------------------------------------\n"
+ tmp_str += "TA Invoke System Call %16d%16d\n" % (self.start, 0)
+ tmp_str += "Secure OS Receive System Call %16d%16d\n" % (self.enter, resolution_in_ns * (self.enter - self.start))
+ tmp_str += "TA Return From System Call %16d%16d\n" % (self.finish, resolution_in_ns * (self.finish - self.enter))
+ tmp_str += "\n"
+ tmp_str += "----------------------------------------------------------------\n"
+ tmp_str += "Summary\n"
+ tmp_str += "----------------------------------------------------------------\n"
+ tmp_str += "TA -> OS = %10d (ns)\n" % (resolution_in_ns * (self.enter - self.start))
+ tmp_str += "OS -> TA = %10d (ns)\n" % (resolution_in_ns * (self.finish - self.enter))
+ tmp_str += "TA -> TA = %10d (ns)\n" % (resolution_in_ns * (self.finish - self.start))
+ tmp_str += "\n"
+ return tmp_str
+
+
+class CounterInfo:
+ def __init__(self):
+ self.freq = 0L
+ self.open_session = OperationCounterInfo("Open Session")
+ self.invoke_command = OperationCounterInfo("Invoke Command")
+ self.secure_sys_call = SysCallCounterInfo("Secure System Call (TEE_GetPropertyAsBinaryBlock)")
+
+ def __repr__(self):
+ tmp_str = "Counter-Timer Frequency = %d (Hz)\n" % self.freq
+ tmp_str += "\n"
+ tmp_str += self.open_session.__repr__()
+ tmp_str += "\n"
+ tmp_str += self.invoke_command.__repr__()
+ tmp_str += "\n"
+ tmp_str += self.secure_sys_call.__repr__()
+ return tmp_str
+
+ def do_analysis(self):
+ counter_resolution_in_ns = pow(10, 9) / counter_info.freq
+ tmp_str = "Counter resolution (ns) = %d\n" % counter_resolution_in_ns
+ tmp_str += "\n"
+ tmp_str += self.open_session.do_analysis(counter_resolution_in_ns)
+ tmp_str += "\n"
+ tmp_str += self.invoke_command.do_analysis(counter_resolution_in_ns)
+ tmp_str += "\n"
+ tmp_str += self.secure_sys_call.do_analysis(counter_resolution_in_ns)
+ tmp_str += "\n"
+ return tmp_str
+
+counter_info = CounterInfo()
+
+
+def show_help():
+ print "Usage: " + sys.argv[0] + " <filename>"
+
+
+def is_counter_freq(line):
+ result = re.search(r'CounterTimerFrequency:\s0x([0-9a-f]+)', line)
+ if result:
+ counter_info.freq = long(result.group(1), 16)
+ return True
+ else:
+ return False
+
+
+def is_client_open_session(line):
+ result = re.search(r'ClientOpenSession:\sstart=0x([0-9a-f]+),\senter_ta=0x([0-9a-f]+),\sreturn=0x([0-9a-f]+)', line)
+ if result:
+ counter_info.open_session.client_start_cmd = long(result.group(1), 16)
+ counter_info.open_session.ta_enter_cmd = long(result.group(2), 16)
+ counter_info.open_session.client_return_cmd = long(result.group(3), 16)
+ return True
+ else:
+ return False
+
+
+def is_client_invoke_command(line):
+ result = re.search(r'ClientInvokeCommand:\sstart=0x([0-9a-f]+),\senter_ta=0x([0-9a-f]+),\sreturn=0x([0-9a-f]+)',
+ line)
+ if result:
+ counter_info.invoke_command.client_start_cmd = long(result.group(1), 16)
+ counter_info.invoke_command.ta_enter_cmd = long(result.group(2), 16)
+ counter_info.invoke_command.client_return_cmd = long(result.group(3), 16)
+ return True
+ else:
+ return False
+
+
+def is_secure_sys_call(line):
+ result = re.search(r'SecureSysCall:\sstart=0x([0-9a-f]+),\senter_svc=0x([0-9a-f]+),\sreturn=0x([0-9a-f]+)', line)
+ if result:
+ counter_info.secure_sys_call.start = long(result.group(1), 16)
+ counter_info.secure_sys_call.enter = long(result.group(2), 16)
+ counter_info.secure_sys_call.finish = long(result.group(3), 16)
+ return True
+ else:
+ return False
+
+
+def is_tee_driver_do_smc_call(line):
+ result = re.search(r'TEEDriver:\sdo\ssmc\scall,\scmd=([0-9]),\scntvct=0x([0-9a-f]+)', line)
+ if result:
+ cmd = int(result.group(1))
+ if cmd == 0: # Open Session
+ if counter_info.open_session.driver_start_smc == 0L: # uninitialized
+ counter_info.open_session.driver_start_smc = long(result.group(2), 16)
+ elif cmd == 1: # Invoke Command
+ if counter_info.invoke_command.driver_start_smc == 0L: # uninitialized
+ counter_info.invoke_command.driver_start_smc = long(result.group(2), 16)
+ elif cmd == 2: # Close Session
+ pass
+ else:
+ print "Unknown SMC call command = %d" % cmd
+
+ return True
+ else:
+ return False
+
+
+def is_tee_driver_finish_smc_call(line):
+ result = re.search(r'TEEDriver:\sfinish\ssmc\scall,\scmd=([0-9]),\scntvct=0x([0-9a-f]+)', line)
+ if result:
+ cmd = int(result.group(1))
+ if cmd == 0: # Open Session
+ if counter_info.open_session.driver_finish_smc == 0L: # uninitialized
+ counter_info.open_session.driver_finish_smc = long(result.group(2), 16)
+ elif cmd == 1: # Invoke Command
+ if counter_info.invoke_command.driver_finish_smc == 0L: # uninitialized
+ counter_info.invoke_command.driver_finish_smc = long(result.group(2), 16)
+ elif cmd == 2: # Close Session
+ pass
+ else:
+ print "Unknown SMC call command = %d" % cmd
+
+ return True
+ else:
+ return False
+
+
+def is_tee_core_receive_smc_call(line):
+ result = re.search(r'TEECore:\sreceiving\ssmc\scall,\scmd=([0-9]),\scntvct=0x([0-9a-f]+)', line)
+ if result:
+ cmd = int(result.group(1))
+ if cmd == 0: # Open Session
+ if counter_info.open_session.tee_os_receive_smc == 0L: # uninitialized
+ counter_info.open_session.tee_os_receive_smc = long(result.group(2), 16)
+ elif cmd == 1: # Invoke Command
+ if counter_info.invoke_command.tee_os_receive_smc == 0L: # uninitialized
+ counter_info.invoke_command.tee_os_receive_smc = long(result.group(2), 16)
+ elif cmd == 2: # Close Session
+ pass
+ else:
+ print "Unknown SMC call command = %d" % cmd
+
+ return True
+ else:
+ return False
+
+
+def is_tee_core_finish_smc_call(line):
+ result = re.search(r'TEECore:\sfinish\ssmc\scall,\scmd=([0-9]),\scntvct=0x([0-9a-f]+)', line)
+ if result:
+ cmd = int(result.group(1))
+ if cmd == 0: # Open Session
+ if counter_info.open_session.tee_os_finish_smc == 0L: # uninitialized
+ counter_info.open_session.tee_os_finish_smc = long(result.group(2), 16)
+ elif cmd == 1: # Invoke Command
+ if counter_info.invoke_command.tee_os_finish_smc == 0L: # uninitialized
+ counter_info.invoke_command.tee_os_finish_smc = long(result.group(2), 16)
+ elif cmd == 2: # Close Session
+ pass
+ else:
+ print "Unknown SMC call command = %d" % cmd
+
+ return True
+ else:
+ return False
+
+
+def get_counter_data(line):
+ if is_counter_freq(line):
+ pass
+ elif is_client_open_session(line):
+ pass
+ elif is_client_invoke_command(line):
+ pass
+ elif is_secure_sys_call(line):
+ pass
+ elif is_tee_driver_do_smc_call(line):
+ pass
+ elif is_tee_driver_finish_smc_call(line):
+ pass
+ elif is_tee_core_receive_smc_call(line):
+ pass
+ elif is_tee_core_finish_smc_call(line):
+ pass
+ else:
+ pass
+
+
+def do_parse(f_object):
+ try:
+ while True:
+ line = f_object.next()
+ get_counter_data(line)
+ except StopIteration:
+ pass
+
+
+# Main #
+if len(sys.argv) < 2:
+ show_help()
+ exit()
+
+try:
+ filename = sys.argv[1]
+ f = open(filename, 'r')
+ do_parse(f)
+ f.close()
+except IOError:
+ print "can not open file"
+
+#print counter_info
+print counter_info.do_analysis()
+
diff --git a/script/sample_log.txt b/script/sample_log.txt
new file mode 100644
index 0000000..a8bc262
--- /dev/null
+++ b/script/sample_log.txt
@@ -0,0 +1,51 @@
+CounterTimerFrequency: 0x3b9aca0
+TEEDriver: do smc call, cmd=0, cntvct=0x485036d69
+TEEDriver: finish smc call, cmd=0, cntvct=0x485113ca3
+ClientOpenSession: start=0x485030c14, enter_ta=0x4850eb290, return=0x48511f7d7
+TEEDriver: do smc call, cmd=1, cntvct=0x485138365
+TEEDriver: finish smc call, cmd=1, cntvct=0x48518bb94
+ClientInvokeCommand: start=0x48513273c, enter_ta=0x48514fb4e, return=0x48519a799
+TEEDriver: do smc call, cmd=1, cntvct=0x4851b6404
+TEEDriver: finish smc call, cmd=1, cntvct=0x485205c55
+SecureSysCall: start=0x4851dda81, enter_svc=0x4851e519c, return=0x4851e5ab6
+TEEDriver: do smc call, cmd=2, cntvct=0x48521c276
+TEEDriver: finish smc call, cmd=2, cntvct=0x4853763d5
+
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: receiving smc call, cmd=0, cntvct=0x48503f201
+DBG TEE-CORE:tee_ta_init_static_ta_session:1198: Lookup for Static TA 99e937a0-8f3e-11e4
+DBG TEE-CORE:tee_ta_init_session_with_signed_ta:1242: Load dynamic TA
+DBG TEE-CORE:tee_ta_load:653: Loaded TA at 0x7e100000, ro_size 28796, rw_size 576, zi_size 14513
+DBG TEE-CORE:tee_ta_load:654: ELF load address 0x200000
+DBG TEE-CORE:tee_ta_init_session_with_signed_ta:1251: dyn TA : 99e937a0-8f3e-11e4
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_CreateEntryPoint:49: has been called
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+tee_user_mem_alloc:342: Allocate: link:[0x1fffc4], buf:[0x1fffd4:16]
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_OpenSessionEntryPoint:90: has been called (session opened with the Simple TA)
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: finish smc call, cmd=0, cntvct=0x48510219c
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: receiving smc call, cmd=1, cntvct=0x485140762
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_InvokeCommandEntryPoint:122: Enter Invoke Command Entry Point
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_InvokeCommandEntryPoint:183: Leave Invoke Command Entry Point
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: finish smc call, cmd=1, cntvct=0x48517dc5c
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: receiving smc call, cmd=1, cntvct=0x4851bcb0b
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_InvokeCommandEntryPoint:122: Enter Invoke Command Entry Point
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #56
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_InvokeCommandEntryPoint:183: Leave Invoke Command Entry Point
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: finish smc call, cmd=1, cntvct=0x4851f89ea
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: receiving smc call, cmd=2, cntvct=0x485223b7a
+DBG TEE-CORE:tee_ta_close_session:1069: tee_ta_close_session(7df37f14)
+DBG TEE-CORE:tee_ta_close_session:1084: ... Destroy session
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_CloseSessionEntryPoint:103: has been called (session with the Comcast Crypto TA will be closed)
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+tee_user_mem_free:441: Free: link:[0x1fffc4], buf:[0x1fffd4:16]
+FLW TEE-CORE:tee_svc_trace_syscall:53: syscall #1
+DBG USER-TA:TA_DestroyEntryPoint:59: has been called
+DBG TEE-CORE:tee_ta_destroy_context:1022: ... Destroy TA ctx
+MSG TEE-CORE:print_cntvct_with_message:328: TEECore: finish smc call, cmd=2, cntvct=0x485368d9e
+
diff --git a/script/setup_fvp_optee.sh b/script/setup_fvp_optee.sh
index ec9c157..71f2739 100755
--- a/script/setup_fvp_optee.sh
+++ b/script/setup_fvp_optee.sh
@@ -233,6 +233,10 @@ dir /data/tee 755 0 0
# TAs
dir /lib/teetz 755 0 0
+
+file /lib/teetz/99e937a0-8f3e-11e4-8b8f0002a5d5c51b.ta $DST_OPTEE_BENCHMARK/ta/out-client-aarch64/99e937a0-8f3e-11e4-8b8f0002a5d5c51b.ta 444 0 0
+
+file /bin/simple_client $DST_OPTEE_BENCHMARK/host/simple_client 755 0 0
EOF
if [ -n "$HAVE_ACCESS_TO_OPTEE_TEST" ]; then
@@ -248,6 +252,7 @@ file /lib/teetz/e6a33ed4-562b-463a-bb7eff5e15a493c8.ta $DEV_PATH/out/utest/user_
# OP-TEE Tests
file /bin/xtest $DEV_PATH/out/utest/host/xtest/bin/xtest 755 0 0
EOF
+
fi
################################################################################
@@ -262,6 +267,7 @@ export PLATFORM=vexpress
export PLATFORM_FLAVOR=fvp
export O=$DST_OPTEE_OS/out-os-fvp
export CFG_TEE_CORE_LOG_LEVEL=4
+export CFG_TEE_TRACE_PERFORMANCE=y
#export DEBUG=1
cd $DST_OPTEE_OS
@@ -376,7 +382,7 @@ cat > $DEV_PATH/build_optee_linuxkernel.sh << EOF
export PATH=$DST_AARCH64_GCC/bin:\$PATH
cd $DST_KERNEL
-make V=0 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- LOCALVERSION= M=$DST_OPTEE_LK modules \$@
+make CONFIG_TEE_TRACE_PERFORMANCE=y V=0 ARCH=arm64 CROSS_COMPILE=aarch64-linux-gnu- LOCALVERSION= M=$DST_OPTEE_LK modules \$@
EOF
chmod 711 $DEV_PATH/build_optee_linuxkernel.sh
@@ -419,6 +425,7 @@ make O=./out-client-aarch64 \\
EOF
chmod 711 $DST_OPTEE_BENCHMARK/build_app.sh
+$DST_OPTEE_BENCHMARK/build_app.sh
################################################################################
# Generate build_device_tree_files.sh #
diff --git a/script/setup_qemu_optee.sh b/script/setup_qemu_optee.sh
index 8739a07..61f005e 100755
--- a/script/setup_qemu_optee.sh
+++ b/script/setup_qemu_optee.sh
@@ -298,6 +298,10 @@ dir /data/tee 755 0 0
# TAs
dir /lib/teetz 755 0 0
+
+file /lib/teetz/99e937a0-8f3e-11e4-8b8f0002a5d5c51b.ta $DST_OPTEE_BENCHMARK/ta/out-client-aarch32/99e937a0-8f3e-11e4-8b8f0002a5d5c51b.ta 444 0 0
+
+file /bin/simple_client $DST_OPTEE_BENCHMARK/host/simple_client 755 0 0
EOF
if [ -n "$HAVE_ACCESS_TO_TEETEST" ]; then
@@ -328,6 +332,7 @@ export PLATFORM=vexpress
export PLATFORM_FLAVOR=qemu_virt
export O=$DEV_PATH/out-os-qemu
export CFG_TEE_CORE_LOG_LEVEL=4
+export CFG_TEE_TRACE_PERFORMANCE=y
export DEBUG=0
cd $DST_OPTEE_OS
@@ -387,7 +392,7 @@ cat > $DEV_PATH/build_optee_linuxkernel.sh << EOF
export PATH=$DST_AARCH32_GCC/bin:\$PATH
cd $DST_KERNEL
-make V=0 ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- LOCALVERSION= M=$DST_OPTEE_LK modules \$@
+make CONFIG_TEE_TRACE_PERFORMANCE=y V=0 ARCH=arm CROSS_COMPILE=arm-linux-gnueabihf- LOCALVERSION= M=$DST_OPTEE_LK modules \$@
EOF
chmod 711 $DEV_PATH/build_optee_linuxkernel.sh
@@ -442,6 +447,7 @@ if [ -f "build_optee_tests.sh" ]; then
./build_optee_tests.sh
fi
./build_optee_linuxkernel.sh
+$DST_OPTEE_BENCHMARK/build_app.sh
./update_rootfs.sh
./build_bios.sh cscope all
EOF
diff --git a/ta/arm_sys_counter.c b/ta/arm_sys_counter.c
deleted file mode 120000
index 63e91af..0000000
--- a/ta/arm_sys_counter.c
+++ /dev/null
@@ -1 +0,0 @@
-../libsyscounter/arm_sys_counter.c \ No newline at end of file
diff --git a/ta/include/arm_sys_counter.h b/ta/include/arm_sys_counter.h
index d544def..b18ed9c 120000..100644
--- a/ta/include/arm_sys_counter.h
+++ b/ta/include/arm_sys_counter.h
@@ -1 +1,96 @@
-../../libsyscounter/arm_sys_counter.h \ No newline at end of file
+/*
+ * Copyright (c) 2014, Linaro Limited
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are met:
+ *
+ * 1. Redistributions of source code must retain the above copyright notice,
+ * this list of conditions and the following disclaimer.
+ *
+ * 2. Redistributions in binary form must reproduce the above copyright notice,
+ * this list of conditions and the following disclaimer in the documentation
+ * and/or other materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
+ * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
+ * liABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
+ * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
+ * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
+ * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
+ * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
+ * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
+ * POSSIBILITY OF SUCH DAMAGE.
+ */
+#ifndef OPTEE_BENCHMARK_LIBSYSCOUNTER_ARM_SYS_COUNTER_H_
+#define OPTEE_BENCHMARK_LIBSYSCOUNTER_ARM_SYS_COUNTER_H_
+
+#include <stdint.h>
+#include <inttypes.h>
+
+static inline uint64_t read_cntvct(void)
+{
+ uint64_t cntvct;
+
+#ifdef __aarch64__
+
+ asm volatile ("mrs %[cntvct], cntvct_el0"
+ : [cntvct] "=r" (cntvct)
+ );
+
+#else
+
+ asm volatile ("mrrc p15, 1, %Q[cntvct], %R[cntvct], c14"
+ : [cntvct] "=r" (cntvct)
+ );
+
+#endif
+
+ return cntvct;
+}
+
+static inline uint64_t read_cntpct(void)
+{
+ uint64_t cntpct;
+
+#ifdef __aarch64__
+
+ asm volatile ("mrs %[cntpct], cntpct_el0"
+ : [cntpct] "=r" (cntpct)
+ );
+
+#else
+
+ asm volatile ("mrrc p15, 0, %Q[cntpct], %R[cntpct], c14"
+ : [cntpct] "=r" (cntpct)
+ );
+
+#endif
+
+ return cntpct;
+}
+
+static inline uint32_t read_cntfrq(void)
+{
+ uint32_t cntfrq;
+
+#ifdef __aarch64__
+
+ asm volatile ("mrs %[cntfrq], cntfrq_el0"
+ : [cntfrq] "=r" (cntfrq)
+ );
+
+#else
+
+ asm volatile ("mrc p15, 0, %[cntfrq], c14, c0, 0"
+ : [cntfrq] "=r" (cntfrq)
+ );
+
+#endif
+
+ return cntfrq;
+}
+
+#endif /* OPTEE_BENCHMARK_LIBSYSCOUNTER_ARM_SYS_COUNTER_H_ */
diff --git a/ta/simple_ta.c b/ta/simple_ta.c
index fea8ad7..40486d7 100644
--- a/ta/simple_ta.c
+++ b/ta/simple_ta.c
@@ -28,6 +28,7 @@
#include "string.h"
#include <utee_defines.h>
+#include <utee_types.h>
#include <assert.h>
#include <stdint.h>
#include <inttypes.h>
@@ -68,7 +69,7 @@ void TA_DestroyEntryPoint(void)
TEE_Result TA_OpenSessionEntryPoint(uint32_t param_types,
TEE_Param params[4], void **sess_ctx)
{
- uint64_t ta_counter_value = arm_sys_counter_get_counter();
+ uint64_t ta_counter_value = read_cntvct();
uint32_t exp_param_types = TEE_PARAM_TYPES(TEE_PARAM_TYPE_MEMREF_OUTPUT,
TEE_PARAM_TYPE_NONE,
@@ -81,7 +82,8 @@ TEE_Result TA_OpenSessionEntryPoint(uint32_t param_types,
(void)&sess_ctx;
/* Return system counter value to Host app */
- memcpy(params[0].memref.buffer, &ta_counter_value, sizeof(ta_counter_value));
+ memcpy(params[0].memref.buffer, &ta_counter_value,
+ sizeof(ta_counter_value));
/*
* The DMSG() macro is non-standard, TEE Internal API doesn't
@@ -100,7 +102,7 @@ TEE_Result TA_OpenSessionEntryPoint(uint32_t param_types,
void TA_CloseSessionEntryPoint(void *sess_ctx)
{
(void)&sess_ctx; /* Unused parameter */
- DMSG("has been called (session with the Comcast Crypto TA will be closed)");
+ DMSG("has been called (session with the Simple TA will be closed)");
}
@@ -113,11 +115,14 @@ TEE_Result TA_InvokeCommandEntryPoint(void *sess_ctx, uint32_t cmd_id,
uint32_t param_types, TEE_Param params[4])
{
TEE_Result result = TEE_SUCCESS;
- uint64_t enter_function_counter_value = arm_sys_counter_get_counter();
+ uint64_t enter_function_counter_value = read_cntvct();
uint64_t sys_call_start_counter_value = 0;
uint64_t sys_call_received_counter_value = 0;
uint64_t sys_call_return_counter_value = 0;
uint32_t exp_param_types = 0;
+ struct generic_timer_info timer_info;
+ size_t buffer_size = sizeof(timer_info);
+ char timer_property_string[] = "ext.tee.arm.genericTimerInfo";
DMSG("Enter Invoke Command Entry Point");
@@ -143,20 +148,30 @@ TEE_Result TA_InvokeCommandEntryPoint(void *sess_ctx, uint32_t cmd_id,
break;
}
- sys_call_start_counter_value = arm_sys_counter_get_counter();
+ sys_call_start_counter_value = read_cntvct();
- TEE_GetSystemCounter(&sys_call_received_counter_value);
+ result = TEE_GetPropertyAsBinaryBlock(
+ TEE_PROPSET_TEE_IMPLEMENTATION,
+ timer_property_string,
+ &timer_info, &buffer_size);
- sys_call_return_counter_value = arm_sys_counter_get_counter();
+ if (result != TEE_SUCCESS)
+ break;
+
+ sys_call_received_counter_value = timer_info.virtual_counter_value;
+ sys_call_return_counter_value = read_cntvct();
params[0].memref.size = sizeof(sys_call_start_counter_value);
- memcpy(params[0].memref.buffer, &sys_call_start_counter_value, params[0].memref.size);
+ memcpy(params[0].memref.buffer, &sys_call_start_counter_value,
+ params[0].memref.size);
params[1].memref.size = sizeof(sys_call_received_counter_value);
- memcpy(params[1].memref.buffer, &sys_call_received_counter_value, params[1].memref.size);
+ memcpy(params[1].memref.buffer, &sys_call_received_counter_value,
+ params[1].memref.size);
params[1].memref.size = sizeof(sys_call_return_counter_value);
- memcpy(params[2].memref.buffer, &sys_call_return_counter_value, params[1].memref.size);
+ memcpy(params[2].memref.buffer, &sys_call_return_counter_value,
+ params[1].memref.size);
break;
@@ -171,7 +186,8 @@ TEE_Result TA_InvokeCommandEntryPoint(void *sess_ctx, uint32_t cmd_id,
break;
}
- memcpy(params[0].memref.buffer, &enter_function_counter_value, sizeof(enter_function_counter_value));
+ memcpy(params[0].memref.buffer, &enter_function_counter_value,
+ sizeof(enter_function_counter_value));
params[0].memref.size = sizeof(enter_function_counter_value);
break;
diff --git a/ta/sub.mk b/ta/sub.mk
index 7f75547..a7e1914 100644
--- a/ta/sub.mk
+++ b/ta/sub.mk
@@ -1,3 +1,2 @@
global-incdirs-y += include
srcs-y += simple_ta.c
-srcs-y += arm_sys_counter.c