diff options
author | James Kung <kong1191@gmail.com> | 2015-01-27 02:11:22 +0800 |
---|---|---|
committer | James Kung <kong1191@gmail.com> | 2015-01-30 15:05:31 +0800 |
commit | c02a78b1cb1c85040487a4e12792531dd553f38f (patch) | |
tree | f86ecc652c3728d3c7e778ef2692872e2750906a | |
parent | 6406826ef35366200fe69cae9ae8f8f90961ec5d (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/Makefile | 2 | ||||
l--------- | host/arm_sys_counter.c | 1 | ||||
l--------- | host/include/arm_sys_counter.h | 1 | ||||
-rw-r--r-- | host/simple_client.c | 10 | ||||
-rw-r--r-- | libsyscounter/arm_sys_counter.c | 68 | ||||
-rw-r--r-- | libsyscounter/arm_sys_counter.h | 37 | ||||
-rw-r--r-- | script/README.md | 111 | ||||
-rw-r--r-- | script/performance_analysis.py | 290 | ||||
-rw-r--r-- | script/sample_log.txt | 51 | ||||
-rwxr-xr-x | script/setup_fvp_optee.sh | 9 | ||||
-rwxr-xr-x | script/setup_qemu_optee.sh | 8 | ||||
l--------- | ta/arm_sys_counter.c | 1 | ||||
-rw-r--r--[l---------] | ta/include/arm_sys_counter.h | 97 | ||||
-rw-r--r-- | ta/simple_ta.c | 38 | ||||
-rw-r--r-- | ta/sub.mk | 1 |
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; @@ -1,3 +1,2 @@ global-incdirs-y += include srcs-y += simple_ta.c -srcs-y += arm_sys_counter.c |