[PAL/Linux-SGX] perf: flush profile data on SIGUSR1 signal

This allows to collect profile data only for a particular period (e.g.,
during Gramine startup or during an actual benchmark run).

Signed-off-by: jkr0103 <[email protected]>

Documentation/performance.rst

@@ -630,6 +630,14 @@ prematurely. Killing the application abruptly via SIGKILL will result in incorre
 perf data. Instead, add ``sys.enable_sigterm_injection = true`` to manifest and
 terminate the application using command ``kill <pid>`` (i.e. send SIGTERM).
 
+It is also possible to flush the collected profile data in a file interactively,
+using the ``SIGUSR1`` signal. This helps to collect profile data only for a
+particular period, e.g., skipping the Gramine startup and application
+initialization time and concentrating only on the actual application processing.
+Send ``SIGUSR1`` using command ``kill -SIGUSR1 -<PGID>`` (note the minus sign
+before <PGID>). Sending multiple ``SIGUSR1`` will create multiple files, each
+containing profile data collected after the previous ``SIGUSR1``.
+
 *Note*: The accuracy of this tool is unclear (though we had positive experiences
 using the tool so far). The SGX profiling works by measuring the value of
 instruction pointer on each asynchronous enclave exit (AEX), which happen on

pal/src/host/linux-sgx/host_exception.c

@@ -188,6 +188,18 @@ static void handle_dummy_signal(int signum, siginfo_t* info, struct ucontext* uc
     /* we need this handler to interrupt blocking syscalls in RPC threads */
 }
 
+#ifdef DEBUG
+static void handle_sigusr1(int signum, siginfo_t* info, struct ucontext* uc) {
+    __UNUSED(signum);
+    __UNUSED(info);
+    __UNUSED(uc);
+
+    if (g_pal_enclave.profile_enable) {
+        __atomic_store_n(&g_trigger_profile_reinit, true, __ATOMIC_RELEASE);
+    }
+}
+#endif /* DEBUG */
+
 int sgx_signal_setup(void) {
     int ret;
 
@@ -226,6 +238,12 @@ int sgx_signal_setup(void) {
     if (ret < 0)
         goto err;
 
+#ifdef DEBUG
+    ret = set_signal_handler(SIGUSR1, handle_sigusr1);
+    if (ret < 0)
+        goto err;
+#endif /* DEBUG */
+
     /* SIGUSR2 is reserved for Gramine usage: interrupting blocking syscalls in RPC threads.
      * We block SIGUSR2 in enclave threads; it is unblocked by each RPC thread explicitly. */
     ret = set_signal_handler(SIGUSR2, handle_dummy_signal);

pal/src/host/linux-sgx/host_internal.h

@@ -50,14 +50,18 @@ struct pal_enclave {
     /* profiling */
     bool profile_enable;
     int profile_mode;
-    char profile_filename[64];
     bool profile_with_stack;
     int profile_frequency;
 #endif
 };
 
 extern struct pal_enclave g_pal_enclave;
 
+#ifdef DEBUG
+extern bool g_trigger_profile_reinit;
+extern char g_profile_filename[128];
+#endif /* DEBUG */
+
 void* realloc(void* ptr, size_t new_size);
 
 int open_sgx_driver(void);
@@ -144,10 +148,6 @@ enum {
     SGX_PROFILE_MODE_OCALL_OUTER = 3,
 };
 
-/* Filenames for saved data */
-#define SGX_PROFILE_FILENAME "sgx-perf.data"
-#define SGX_PROFILE_FILENAME_WITH_PID "sgx-perf-%d.data"
-
 /* Initialize based on g_pal_enclave settings */
 int sgx_profile_init(void);
 
@@ -174,8 +174,10 @@ void sgx_profile_report_elf(const char* filename, void* addr);
 struct perf_data;
 
 struct perf_data* pd_open(const char* file_name, bool with_stack);
+int pd_open_file(struct perf_data* pd, const char* file_name);
 
 /* Finalize and close; returns resulting file size */
+ssize_t pd_close_file(struct perf_data* pd);
 ssize_t pd_close(struct perf_data* pd);
 
 /* Write PERF_RECORD_COMM (report command name) */

pal/src/host/linux-sgx/host_main.c

@@ -798,20 +798,15 @@ static int parse_loader_config(char* manifest, struct pal_enclave* enclave_info,
 
 #ifdef DEBUG
     enclave_info->profile_enable = false;
-    enclave_info->profile_filename[0] = '\0';
 
     if (!profile_str || !strcmp(profile_str, "none")) {
         // do not enable
     } else if (!strcmp(profile_str, "main")) {
         if (enclave_info->is_first_process) {
-            snprintf(enclave_info->profile_filename, ARRAY_SIZE(enclave_info->profile_filename),
-                     SGX_PROFILE_FILENAME);
             enclave_info->profile_enable = true;
         }
     } else if (!strcmp(profile_str, "all")) {
         enclave_info->profile_enable = true;
-        snprintf(enclave_info->profile_filename, ARRAY_SIZE(enclave_info->profile_filename),
-                 SGX_PROFILE_FILENAME_WITH_PID, (int)g_host_pid);
     } else {
         log_error("Invalid 'sgx.profile.enable' "
                   "(the value must be \"none\", \"main\" or \"all\")");

pal/src/host/linux-sgx/host_perf_data.c

@@ -140,13 +140,13 @@ static int pd_write(struct perf_data* pd, const void* data, size_t size) {
     return 0;
 }
 
-struct perf_data* pd_open(const char* file_name, bool with_stack) {
+int pd_open_file(struct perf_data* pd, const char* file_name) {
     int ret;
 
     int fd = DO_SYSCALL(open, file_name, O_WRONLY | O_TRUNC | O_CREAT | O_CLOEXEC, PERM_rw_r__r__);
     if (fd < 0) {
-        log_error("pd_open: cannot open %s for writing: %s", file_name, unix_strerror(fd));
-        return NULL;
+        log_error("pd_open_file: cannot open %s for writing: %s", file_name, unix_strerror(fd));
+        return fd;
     }
 
     /*
@@ -162,23 +162,36 @@ struct perf_data* pd_open(const char* file_name, bool with_stack) {
     if (ret < 0)
         goto fail;
 
+    assert(pd->fd == -1);
+    pd->fd = fd;
+    return 0;
+
+fail:;
+    int close_ret = DO_SYSCALL(close, fd);
+    if (close_ret < 0)
+        log_error("pd_open_file: close failed: %s", unix_strerror(close_ret));
+    return ret;
+}
+
+struct perf_data* pd_open(const char* file_name, bool with_stack) {
     struct perf_data* pd = malloc(sizeof(*pd));
     if (!pd) {
         log_error("pd_open: out of memory");
-        goto fail;
+        return NULL;
+    }
+
+    pd->fd  = -1;
+    int ret = pd_open_file(pd, file_name);
+    if (ret < 0) {
+        free(pd);
+        return NULL;
     }
 
-    pd->fd = fd;
     pd->buf_count = 0;
     pd->with_stack = with_stack;
-    return pd;
 
-fail:
-    ret = DO_SYSCALL(close, fd);
-    if (ret < 0)
-        log_error("pd_open: close failed: %s", unix_strerror(ret));
-    return NULL;
-};
+    return pd;
+}
 
 static int write_prologue_epilogue(struct perf_data* pd) {
     int ret;
@@ -266,9 +279,8 @@ static int write_prologue_epilogue(struct perf_data* pd) {
     return 0;
 }
 
-ssize_t pd_close(struct perf_data* pd) {
-    ssize_t ret = 0;
-    int close_ret;
+ssize_t pd_close_file(struct perf_data* pd) {
+    ssize_t ret;
 
     ret = pd_flush(pd);
     if (ret < 0)
@@ -282,12 +294,20 @@ ssize_t pd_close(struct perf_data* pd) {
     if (ret < 0)
         goto out;
 
-out:
-    close_ret = DO_SYSCALL(close, pd->fd);
+out:;
+    int close_ret = DO_SYSCALL(close, pd->fd);
+    pd->fd = -1;
     if (close_ret < 0)
-        log_error("pd_close: close failed: %s", unix_strerror(close_ret));
+        log_error("pd_close_file: close failed: %s", unix_strerror(close_ret));
+
+    /* Returns the size of the finalized perf-data file on success */
+    return ret;
+}
 
+ssize_t pd_close(struct perf_data* pd) {
+    ssize_t ret = pd_close_file(pd);
     free(pd);
+
     return ret;
 }
 

pal/src/host/linux-sgx/host_profile.c

@@ -19,6 +19,7 @@
 #include <stddef.h>
 
 #include "cpu.h"
+#include "debug_map.h"
 #include "elf/elf.h"
 #include "host_internal.h"
 #include "host_log.h"
@@ -35,13 +36,20 @@ char* realpath(const char* path, char* resolved_path);
 
 #define NSEC_IN_SEC 1000000000
 
+/* Filename for saved data */
+#define SGX_PROFILE_FILENAME_WITH_PID_AND_TIME "sgx-perf-%d-%lu.data"
+
 static spinlock_t g_perf_data_lock = INIT_SPINLOCK_UNLOCKED;
 static struct perf_data* g_perf_data = NULL;
 
 static bool g_profile_enabled = false;
+bool g_trigger_profile_reinit;
 static int g_profile_mode;
 static uint64_t g_profile_period;
 static int g_mem_fd = -1;
+char g_profile_filename[128];
+
+static void _sgx_profile_report_elf(const char* filename, void* addr);
 
 /* Read memory from inside enclave (using /proc/self/mem). */
 static ssize_t debug_read(void* dest, void* addr, size_t size) {
@@ -117,7 +125,17 @@ int sgx_profile_init(void) {
     }
     g_mem_fd = ret;
 
-    struct perf_data* pd = pd_open(g_pal_enclave.profile_filename, g_pal_enclave.profile_with_stack);
+    struct timespec ts;
+    ret = DO_SYSCALL(clock_gettime, CLOCK_REALTIME, &ts);
+    if (ret < 0) {
+        log_error("sgx_profile_init: clock_gettime failed: %s", unix_strerror(ret));
+        goto out;
+    }
+
+    snprintf(g_profile_filename, ARRAY_SIZE(g_profile_filename),
+             SGX_PROFILE_FILENAME_WITH_PID_AND_TIME, (int)g_host_pid, ts.tv_sec);
+
+    struct perf_data* pd = pd_open(g_profile_filename, g_pal_enclave.profile_with_stack);
     if (!pd) {
         log_error("sgx_profile_init: pd_open failed");
         ret = -EINVAL;
@@ -135,7 +153,7 @@ int sgx_profile_init(void) {
     return 0;
 
 out:
-    if (g_mem_fd > 0) {
+    if (g_mem_fd >= 0) {
         int close_ret = DO_SYSCALL(close, g_mem_fd);
         if (close_ret < 0) {
             log_error("sgx_profile_init: closing /proc/self/mem failed: %s",
@@ -175,15 +193,63 @@ void sgx_profile_finish(void) {
         log_error("sgx_profile_finish: closing /proc/self/mem failed: %s", unix_strerror(ret));
     g_mem_fd = -1;
 
-    log_debug("Profile data written to %s (%lu bytes)", g_pal_enclave.profile_filename, size);
+    log_error("[INFO] Profile data written to %s (%lu bytes)", g_profile_filename, size);
 
     g_profile_enabled = false;
 }
 
+static int sgx_profile_reinit(void) {
+    assert(spinlock_is_locked(&g_perf_data_lock));
+
+    int ret;
+    ssize_t size;
+
+    size = pd_close_file(g_perf_data);
+    if (size < 0) {
+        log_error("sgx_profile_reinit: pd_close_file failed: %s", unix_strerror(size));
+        return size;
+    }
+
+    log_error("[INFO] Profile data written to %s (%lu bytes)", g_profile_filename, size);
+
+    struct timespec ts;
+    ret = DO_SYSCALL(clock_gettime, CLOCK_REALTIME, &ts);
+    if (ret < 0) {
+        log_error("sgx_profile_reinit: clock_gettime failed: %s", unix_strerror(ret));
+        return ret;
+    }
+
+    snprintf(g_profile_filename, ARRAY_SIZE(g_profile_filename),
+             SGX_PROFILE_FILENAME_WITH_PID_AND_TIME, (int)g_host_pid, ts.tv_sec);
+
+    ret = pd_open_file(g_perf_data, g_profile_filename);
+    if (ret < 0) {
+        log_error("sgx_profile_reinit: pd_open_file failed");
+        return ret;
+    }
+
+    /* Report all ELFs already loaded */
+    struct debug_map* map = g_debug_map;
+    while (map) {
+        _sgx_profile_report_elf(map->name, map->addr);
+        map = map->next;
+    }
+
+    return 0;
+}
+
 static void sample_simple(uint64_t rip) {
     int ret;
 
     spinlock_lock(&g_perf_data_lock);
+    if (__atomic_exchange_n(&g_trigger_profile_reinit, false, __ATOMIC_ACQ_REL) == true) {
+        ret = sgx_profile_reinit();
+        if (ret < 0) {
+            /* No need to print error message since sgx_profile_init() already prints it */
+            BUG();
+        }
+    }
+
     // Report all events as the same PID so that they are grouped in report.
     ret = pd_event_sample_simple(g_perf_data, rip, g_host_pid, /*tid=*/g_host_pid,
                                  g_profile_period);
@@ -207,6 +273,14 @@ static void sample_stack(sgx_pal_gpr_t* gpr) {
     stack_size = ret;
 
     spinlock_lock(&g_perf_data_lock);
+    if (__atomic_exchange_n(&g_trigger_profile_reinit, false, __ATOMIC_ACQ_REL) == true) {
+        ret = sgx_profile_reinit();
+        if (ret < 0) {
+            /* No need to print error message since sgx_profile_init() already prints it */
+            BUG();
+        }
+    }
+
     // Report all events as the same PID so that they are grouped in report.
     ret = pd_event_sample_stack(g_perf_data, gpr->rip, g_host_pid, /*tid=*/g_host_pid,
                                 g_profile_period, gpr, stack, stack_size);
@@ -305,7 +379,8 @@ void sgx_profile_sample_ocall_outer(void* ocall_func) {
     sample_simple((uint64_t)ocall_func);
 }
 
-void sgx_profile_report_elf(const char* filename, void* addr) {
+static void _sgx_profile_report_elf(const char* filename, void* addr) {
+    assert(spinlock_is_locked(&g_perf_data_lock));
     int ret;
 
     if (!g_profile_enabled && !g_vtune_profile_enabled)
@@ -372,8 +447,6 @@ void sgx_profile_report_elf(const char* filename, void* addr) {
     const elf_phdr_t* phdr = (const elf_phdr_t*)((uintptr_t)elf_addr + ehdr->e_phoff);
     ret = 0;
 
-    spinlock_lock(&g_perf_data_lock);
-
     for (unsigned int i = 0; i < ehdr->e_phnum; i++) {
         if (phdr[i].p_type == PT_LOAD && phdr[i].p_flags & PF_X) {
             uint64_t mapstart = ALLOC_ALIGN_DOWN(phdr[i].p_vaddr);
@@ -392,8 +465,6 @@ void sgx_profile_report_elf(const char* filename, void* addr) {
         }
     }
 
-    spinlock_unlock(&g_perf_data_lock);
-
     if (ret < 0) {
         log_error("sgx_profile_report_elf(%s): pd_event_mmap failed: %s", filename,
                   unix_strerror(ret));
@@ -412,4 +483,10 @@ void sgx_profile_report_elf(const char* filename, void* addr) {
         log_error("sgx_profile_report_elf(%s): close failed: %s", filename, unix_strerror(ret));
 }
 
+void sgx_profile_report_elf(const char* filename, void* addr) {
+    spinlock_lock(&g_perf_data_lock);
+    _sgx_profile_report_elf(filename, addr);
+    spinlock_unlock(&g_perf_data_lock);
+}
+
 #endif /* DEBUG */