From 5e91e388b968bd55a9a78fa1c8dd12b0807839bf Mon Sep 17 00:00:00 2001 From: Dmitrii Kuvaiskii Date: Tue, 30 Jun 2020 21:04:15 +0000 Subject: [PATCH] [LibOS,Pal] Print SGX stats right-before Glibc startup and on app request Introduce a hack to print out SGX-specific statistics during runtime: - DkThreadDelayExecution(-42) is called after enclave is initialized and entered, and right-before Graphene passes control to Glibc loader; - DkThreadDelayExecution(-41) is called by the application (when opening /dev/null) to print stats at any point during app execution. LibOS test `multi_pthread` shows how to use this hack. --- LibOS/shim/src/elf/shim_rtld.c | 3 +++ LibOS/shim/src/fs/dev/null.c | 3 +++ LibOS/shim/test/regression/multi_pthread.c | 7 +++++++ Pal/src/host/Linux-SGX/sgx_enclave.c | 17 +++++++++++++++-- Pal/src/host/Linux-SGX/sgx_thread.c | 12 +++++++----- Pal/src/host/Linux-SGX/sgx_tls.h | 2 +- Pal/src/host/Linux/db_threading.c | 6 ++++++ 7 files changed, 42 insertions(+), 8 deletions(-) diff --git a/LibOS/shim/src/elf/shim_rtld.c b/LibOS/shim/src/elf/shim_rtld.c index 96dd8c9f..2d0db29f 100644 --- a/LibOS/shim/src/elf/shim_rtld.c +++ b/LibOS/shim/src/elf/shim_rtld.c @@ -1586,6 +1586,9 @@ noreturn void execute_elf_object(struct shim_handle* exec, void* argp, ElfW(auxv ElfW(Addr) entry = interp_map ? interp_map->l_entry : exec_map->l_entry; + /* hack: print out stats of main thread right-before passing control to Glibc and app */ + DkThreadDelayExecution((unsigned long)-42); + /* Ready to start execution, re-enable preemption. */ shim_tcb_t* tcb = shim_get_tcb(); __enable_preempt(tcb); diff --git a/LibOS/shim/src/fs/dev/null.c b/LibOS/shim/src/fs/dev/null.c index 75ec7cdd..21387663 100644 --- a/LibOS/shim/src/fs/dev/null.c +++ b/LibOS/shim/src/fs/dev/null.c @@ -52,6 +52,9 @@ static int dev_null_open(struct shim_handle* hdl, const char* name, int flags) { __UNUSED(name); __UNUSED(flags); + /* hack: print out stats of main thread when requested by app (via opening /dev/null) */ + DkThreadDelayExecution((unsigned long)-41); + struct shim_dev_ops ops = {.read = &dev_null_read, .write = &dev_null_write, .truncate = &dev_null_truncate, diff --git a/LibOS/shim/test/regression/multi_pthread.c b/LibOS/shim/test/regression/multi_pthread.c index fa0c1054..87295544 100644 --- a/LibOS/shim/test/regression/multi_pthread.c +++ b/LibOS/shim/test/regression/multi_pthread.c @@ -15,6 +15,13 @@ static void* inc(void* arg) { } int main(int argc, char** argv) { + /* hack: opening /dev/null prints out SGX stats on this thread */ + FILE* f = fopen("/dev/null", "w"); + if (!f) { + perror("fopen /dev/null"); + return 1; + } + for (int i = 0; i < THREAD_NUM; i++) { pthread_t thread[CONC_THREAD_NUM]; diff --git a/Pal/src/host/Linux-SGX/sgx_enclave.c b/Pal/src/host/Linux-SGX/sgx_enclave.c index 74ac0cff..acd16337 100644 --- a/Pal/src/host/Linux-SGX/sgx_enclave.c +++ b/Pal/src/host/Linux-SGX/sgx_enclave.c @@ -58,7 +58,7 @@ static long sgx_ocall_exit(void* pms) /* exit the whole process if exit_group() */ if (ms->ms_is_exitgroup) { - update_and_print_stats(/*process_wide=*/true); + update_and_print_stats(/*thread_exits=*/true, /*process_wide=*/true); INLINE_SYSCALL(exit_group, 1, (int)ms->ms_exitcode); } @@ -70,7 +70,7 @@ static long sgx_ocall_exit(void* pms) if (!current_enclave_thread_cnt()) { /* no enclave threads left, kill the whole process */ - update_and_print_stats(/*process_wide=*/true); + update_and_print_stats(/*thread_exits=*/true, /*process_wide=*/true); INLINE_SYSCALL(exit_group, 1, (int)ms->ms_exitcode); } @@ -578,10 +578,23 @@ static long sgx_ocall_sleep(void * pms) ms_ocall_sleep_t * ms = (ms_ocall_sleep_t *) pms; long ret; ODEBUG(OCALL_SLEEP, ms); + + if (ms->ms_microsec == (unsigned long)-42 || ms->ms_microsec == (unsigned long)-41) { + /* hack: DkThreadDelayExecution(-42/-41) is used to print current stats of enclave thread; + * note that sleep OCALL is non-exitless and thus we have EEXITed enclave thread */ + if (ms->ms_microsec == (unsigned long)-42) + pal_printf("----- [SGX stats right-before handing control to Glibc and app] -----\n"); + else if (ms->ms_microsec == (unsigned long)-41) + pal_printf("----- [SGX stats explicitly requested by app] -----\n"); + update_and_print_stats(/*thread_exits=*/false, /*process_wide=*/false); + return 0; + } + if (!ms->ms_microsec) { INLINE_SYSCALL(sched_yield, 0); return 0; } + struct timespec req, rem; unsigned long microsec = ms->ms_microsec; const unsigned long VERY_LONG_TIME_IN_US = 1000000L * 60 * 60 * 24 * 365 * 128; diff --git a/Pal/src/host/Linux-SGX/sgx_thread.c b/Pal/src/host/Linux-SGX/sgx_thread.c index e6ede6a8..518347df 100644 --- a/Pal/src/host/Linux-SGX/sgx_thread.c +++ b/Pal/src/host/Linux-SGX/sgx_thread.c @@ -24,7 +24,7 @@ static struct thread_map * enclave_thread_map; bool g_sgx_enable_stats = false; -void update_and_print_stats(bool process_wide) { +void update_and_print_stats(bool thread_exits, bool process_wide) { static atomic_ulong g_eenter_cnt = 0; static atomic_ulong g_eexit_cnt = 0; static atomic_ulong g_aex_cnt = 0; @@ -42,9 +42,11 @@ void update_and_print_stats(bool process_wide) { " # of AEXs: %lu\n", tid, tcb->eenter_cnt, tcb->eexit_cnt, tcb->aex_cnt); - g_eenter_cnt += tcb->eenter_cnt; - g_eexit_cnt += tcb->eexit_cnt; - g_aex_cnt += tcb->aex_cnt; + if (thread_exits) { + g_eenter_cnt += tcb->eenter_cnt; + g_eexit_cnt += tcb->eexit_cnt; + g_aex_cnt += tcb->aex_cnt; + } if (process_wide) { int pid = INLINE_SYSCALL(getpid, 0); @@ -189,7 +191,7 @@ noreturn void thread_exit(int status) { * (by sgx_ocall_exit()) but we keep it here for future proof */ block_async_signals(true); - update_and_print_stats(/*process_wide=*/false); + update_and_print_stats(/*thread_exits=*/true, /*process_wide=*/false); if (tcb->alt_stack) { stack_t ss; diff --git a/Pal/src/host/Linux-SGX/sgx_tls.h b/Pal/src/host/Linux-SGX/sgx_tls.h index 7b62adb6..0507f1d9 100644 --- a/Pal/src/host/Linux-SGX/sgx_tls.h +++ b/Pal/src/host/Linux-SGX/sgx_tls.h @@ -102,7 +102,7 @@ static inline PAL_TCB_URTS* get_tcb_urts(void) { } extern bool g_sgx_enable_stats; -void update_and_print_stats(bool process_wide); +void update_and_print_stats(bool thread_exits, bool process_wide); # endif #endif /* __SGX_TLS_H__ */ diff --git a/Pal/src/host/Linux/db_threading.c b/Pal/src/host/Linux/db_threading.c index a5699b75..cdab7914 100644 --- a/Pal/src/host/Linux/db_threading.c +++ b/Pal/src/host/Linux/db_threading.c @@ -179,6 +179,12 @@ err: int _DkThreadDelayExecution (unsigned long * duration) { + if (*duration == (unsigned long)-42 || *duration == (unsigned long)-41) { + /* hack: DkThreadDelayExecution(-42/-41) is used to print current stats of enclave thread; + * just ignore this SGX-specific hack in Linux PAL */ + return 0; + } + struct timespec sleeptime; struct timespec remainingtime;