Recording source location

CMakeLists.txt

@@ -124,6 +124,11 @@ option(BUILD_SHARED_LIBS "Build with shared libraries." ON)
 option(RECORDER_ENABLE_PARQUET "Build Parquet format converter." OFF)
 option(RECORDER_ENABLE_CUDA_TRACE "Enable tracing of CUDA kernels." OFF)
 option(RECORDER_ENABLE_FCNTL_TRACE "Enable tracing of fcntl()." ON)
+option(RECORDER_ENABLE_FULL_TRACING "Record the source code location of every traced call." OFF)
+# -DFULL_TRACING=ON is accepted as a shorthand.
+if(FULL_TRACING)
+    set(RECORDER_ENABLE_FULL_TRACING ON)
+endif()
 option(RECORDER_INSTALL_TESTS "Enable installation of tests." OFF)
 
 

include/recorder-logger.h

@@ -41,6 +41,7 @@ typedef struct Record_t {
     double tstart;
     double tend;
     unsigned char call_depth;
+    uint32_t call_site;         // index into the per-rank call site table
     int func_id;
     unsigned char arg_count;
     char **args;                // Store all arguments in array
@@ -84,11 +85,29 @@ typedef enum {
     RECORDER_SECTION_CFG_META   = 4,  /* grammar metadata (interprocess_compression = true) */
     RECORDER_SECTION_RANK_CST   = 5,  /* per-rank CST (interprocess_compression = false)    */
     RECORDER_SECTION_RANK_CFG   = 6,  /* per-rank CFG (interprocess_compression = false)    */
+    RECORDER_SECTION_CALLSITES  = 7,  /* per-rank call site table (FULL_TRACING only)      */
 } RecorderSectionType;
 
+/* Call site table (RECORDER_SECTION_CALLSITES), one per rank. Written only by
+ * builds configured with -DRECORDER_ENABLE_FULL_TRACING=ON, which also makes
+ * the CST key carry call_site and bumps format_version to 2.
+ *   [CallSiteSectionHeader][module paths, NUL-separated][CallSiteEntry * n]
+ * Resolve with: addr2line -a -f -i -C -e <module> <offset> */
+typedef struct CallSiteSectionHeader_t {
+    uint32_t version;           /* 1 */
+    uint32_t num_modules;
+    uint32_t num_sites;
+    uint32_t strtab_bytes;      /* size of the module path string table */
+} CallSiteSectionHeader;
+
+typedef struct CallSiteEntry_t {
+    uint32_t module_id;         /* index into the module string table */
+    uint64_t offset;            /* address - module load base, already ip-1 */
+} __attribute__((packed)) CallSiteEntry;
+
 typedef struct RecorderFileHeader_t {
     char     magic[8];        /* "RECORDER" */
-    uint32_t format_version;  /* 1          */
+    uint32_t format_version;  /* 2 since the CST key carries call_site */
     uint32_t num_sections;
 } RecorderFileHeader;
 
@@ -153,6 +172,7 @@ typedef struct RecorderLogger_t {
 
     bool      store_tid;            // Wether to store thread id
     bool      store_call_depth;     // Wether to store the call depth
+    bool      store_call_site;      // Caller's return address; false unless built with FULL_TRACING
     bool      interprocess_compression; // Wether to perform interprocess compression of cst/cfg
     bool      interprocess_pattern_recognition; 
     bool      intraprocess_pattern_recognition; 
@@ -167,6 +187,12 @@ void logger_init();
 void logger_set_mpi_info(int mpi_rank, int mpi_size);
 void logger_finalize();
 bool logger_initialized();
+/* Call site tracking -- recorder-callsite.c */
+void     callsite_set_enabled(bool enabled);
+uint32_t callsite_intern(void* return_address);
+void     callsite_save_local(int rank, const char* traces_dir);
+void     callsite_cleanup();
+
 void logger_record_enter(Record *record);
 void logger_record_exit(Record *record);
 bool logger_intraprocess_pattern_recognition();

include/recorder.h

@@ -15,6 +15,7 @@
 #define RECORDER_STORE_POINTER        		        "RECORDER_STORE_POINTER"
 #define RECORDER_STORE_TID            		        "RECORDER_STORE_TID"
 #define RECORDER_STORE_CALL_DEPTH          		    "RECORDER_STORE_CALL_DEPTH"
+#define RECORDER_STORE_CALL_SITE           		    "RECORDER_STORE_CALL_SITE"
 #define RECORDER_INTERPROCESS_COMPRESSION	        "RECORDER_INTERPROCESS_COMPRESSION"
 #define RECORDER_INTERPROCESS_PATTERN_RECOGNITION   "RECORDER_INTERPROCESS_PATTERN_RECOGNITION"
 #define RECORDER_INTRAPROCESS_PATTERN_RECOGNITION   "RECORDER_INTRAPROCESS_PATTERN_RECOGNITION"
@@ -50,8 +51,17 @@
  * can change the fields, e.g., fopen will convert the FILE* to an integer res.
  *
  */
+/* Only configured builds pay for the caller's return address.
+ * A preprocessor directive cannot live inside a macro body, hence this. */
+#ifdef RECORDER_ENABLE_FULL_TRACING
+#define RECORDER_CAPTURE_CALL_SITE(rec) (rec)->call_site = callsite_intern(__builtin_return_address(0))
+#else
+#define RECORDER_CAPTURE_CALL_SITE(rec) (rec)->call_site = 0
+#endif
+
 #define RECORDER_INTERCEPTOR_PROLOGUE_CORE(ret, func, real_args)                    \
     Record *record = recorder_malloc(sizeof(Record));                               \
+    RECORDER_CAPTURE_CALL_SITE(record);                                             \
     record->func_id = get_function_id_by_name(#func);                               \
     record->tid = recorder_gettid();                                                \
     logger_record_enter(record);                                                    \

lib/CMakeLists.txt

@@ -147,6 +147,19 @@ if(RECORDER_ENABLE_CUDA_TRACE)
 endif()
 
 
+if(RECORDER_ENABLE_FULL_TRACING)
+    set(RECORDER_SRCS
+        ${CMAKE_CURRENT_SOURCE_DIR}/recorder-callsite.c
+        ${RECORDER_SRCS}
+    )
+    # libunwind is only needed to step out of our own MPI forwarders
+    set(RECORDER_EXT_LIB_DEPENDENCIES unwind ${RECORDER_EXT_LIB_DEPENDENCIES})
+    message("-- " "Full tracing: ON (source locations are recorded)")
+else()
+    message("-- " "Full tracing: OFF (use -DRECORDER_ENABLE_FULL_TRACING=ON to record source locations)")
+endif()
+
+
 INCLUDE(CheckFunctionExists)
 CHECK_FUNCTION_EXISTS(__xstat    HAVE___XSTAT)
 CHECK_FUNCTION_EXISTS(__xstat64  HAVE___XSTAT64)
@@ -190,6 +203,7 @@ target_compile_definitions(recorder
         PRIVATE $<$<AND:$<BOOL:${NETCDF_INCLUDE_DIRS}>,$<BOOL:${NETCDF_LIBRARY_FOUND}>>:RECORDER_WITH_NETCDF>
         PRIVATE $<$<BOOL:${RECORDER_ENABLE_FCNTL_TRACE}>:RECORDER_ENABLE_FCNTL_TRACE>
         PRIVATE $<$<BOOL:${RECORDER_ENABLE_CUDA_TRACE}>:RECORDER_ENABLE_CUDA_TRACE>
+        PUBLIC  $<$<BOOL:${RECORDER_ENABLE_FULL_TRACING}>:RECORDER_ENABLE_FULL_TRACING>
         )
 
 recorder_set_lib_options(recorder "recorder" ${RECORDER_LIBTYPE})

lib/recorder-callsite.c

@@ -0,0 +1,238 @@
+/* Call site tracking: each interceptor records its caller's return address,
+ * interned into a per-rank (module, offset) table.
+ *
+ * Two things that fail silently if changed:
+ *   - offset is against link_map->l_addr (the slide), not Dl_info.dli_fbase.
+ *     Non-PIE main programs have dli_fbase 0x400000 but slide 0.
+ *   - we store ip-1; a return address points past the call.
+ *
+ * The MPI wrappers put the prologue in imp_*() behind a forwarder, so there
+ * __builtin_return_address(0) lands inside librecorder. Only in that case do
+ * we unwind out. */
+#define _GNU_SOURCE
+#define UNW_LOCAL_ONLY
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <stdint.h>
+#include <limits.h>
+#include <unistd.h>
+#include <dlfcn.h>
+#include <link.h>
+#include <libunwind.h>
+#include <pthread.h>
+#include "recorder.h"
+
+#define CALLSITE_UNKNOWN 0xFFFFFFFFu
+
+typedef struct CallSiteModule_t {
+    char*    path;              /* key */
+    uint32_t id;
+    size_t   path_len;          /* including the NUL */
+    UT_hash_handle hh;
+} CallSiteModule;
+
+typedef struct CallSite_t {
+    const void* ip;             /* key: already ip-1 */
+    uint32_t    id;
+    uint32_t    module_id;
+    uint64_t    offset;
+    UT_hash_handle hh;
+} CallSite;
+
+/* dladdr1/realpath can reach intercepted functions. */
+static __thread int in_intern = 0;
+
+static pthread_mutex_t  cs_mutex = PTHREAD_MUTEX_INITIALIZER;
+static bool             cs_enabled      = false;
+static CallSite*        cs_table        = NULL;
+static CallSiteModule*  cs_modules      = NULL;
+static uint32_t         cs_count        = 0;
+static uint32_t         cs_module_count = 0;
+static size_t           cs_strbytes     = 0;
+
+/* Our own address span, to spot returns into our forwarders. */
+static uintptr_t self_start = 0, self_end = 0;
+
+struct self_probe { uintptr_t addr, start, end; };
+
+static int self_phdr_cb(struct dl_phdr_info* info, size_t size, void* data)
+{
+    (void)size;
+    struct self_probe* sp = (struct self_probe*) data;
+    uintptr_t lo = UINTPTR_MAX, hi = 0;
+    int hit = 0;
+    for (int i = 0; i < info->dlpi_phnum; i++) {
+        const ElfW(Phdr)* p = &info->dlpi_phdr[i];
+        if (p->p_type != PT_LOAD) continue;
+        uintptr_t s = info->dlpi_addr + p->p_vaddr;
+        uintptr_t e = s + p->p_memsz;
+        if (s < lo) lo = s;
+        if (e > hi) hi = e;
+        if (sp->addr >= s && sp->addr < e) hit = 1;
+    }
+    if (hit) { sp->start = lo; sp->end = hi; return 1; }
+    return 0;
+}
+
+void callsite_set_enabled(bool enabled)
+{
+    cs_enabled = enabled;
+    if (!enabled || self_end) return;
+    struct self_probe sp = { (uintptr_t)(void*)callsite_set_enabled, 0, 0 };
+    if (dl_iterate_phdr(self_phdr_cb, &sp)) {
+        self_start = sp.start;
+        self_end   = sp.end;
+    }
+}
+
+static inline int is_self(const void* p)
+{
+    uintptr_t a = (uintptr_t) p;
+    return self_end && a >= self_start && a < self_end;
+}
+
+/* First frame outside librecorder. */
+static const void* unwind_out_of_self(void)
+{
+    unw_context_t ctx;
+    unw_cursor_t  cur;
+    if (unw_getcontext(&ctx) != 0) return NULL;
+    if (unw_init_local(&cur, &ctx) != 0) return NULL;
+
+    for (int n = 0; n < 64 && unw_step(&cur) > 0; n++) {
+        unw_word_t ip = 0;
+        unw_get_reg(&cur, UNW_REG_IP, &ip);
+        if (!ip) break;
+        const void* p = (const void*)((uintptr_t)ip - 1);
+        if (!is_self(p)) return p;
+    }
+    return NULL;
+}
+
+static uint32_t module_intern(const char* path)
+{
+    CallSiteModule* m = NULL;
+    HASH_FIND_STR(cs_modules, path, m);
+    if (m) return m->id;
+
+    size_t len = strlen(path) + 1;
+    m = (CallSiteModule*) recorder_malloc(sizeof(CallSiteModule));
+    m->path     = (char*) recorder_malloc(len);
+    memcpy(m->path, path, len);
+    m->path_len = len;
+    m->id       = cs_module_count++;
+    cs_strbytes += len;
+    HASH_ADD_KEYPTR(hh, cs_modules, m->path, len - 1, m);
+    return m->id;
+}
+
+uint32_t callsite_intern(void* return_address)
+{
+    if (!cs_enabled || !return_address) return CALLSITE_UNKNOWN;
+    if (in_intern) return CALLSITE_UNKNOWN;
+
+    /* return address points past the call */
+    const void* ip = (const void*)((const char*)return_address - 1);
+
+    /* Behind a forwarder the address is fixed, so resolve before lookup. */
+    if (is_self(ip)) {
+        in_intern = 1;
+        ip = unwind_out_of_self();
+        in_intern = 0;
+        if (!ip) return CALLSITE_UNKNOWN;
+    }
+
+    CallSite* cs = NULL;
+    pthread_mutex_lock(&cs_mutex);
+    HASH_FIND(hh, cs_table, &ip, sizeof(const void*), cs);
+    if (cs) { uint32_t id = cs->id; pthread_mutex_unlock(&cs_mutex); return id; }
+    pthread_mutex_unlock(&cs_mutex);
+
+    in_intern = 1;
+    Dl_info info;
+    struct link_map* lm = NULL;
+    int ok = dladdr1((void*)ip, &info, (void**)&lm, RTLD_DL_LINKMAP);
+    char resolved[PATH_MAX];
+    const char* path = NULL;
+    if (ok && info.dli_fname && lm) {
+        path = realpath(info.dli_fname, resolved) ? resolved : info.dli_fname;
+    }
+    in_intern = 0;
+    if (!path) return CALLSITE_UNKNOWN;
+
+    pthread_mutex_lock(&cs_mutex);
+    /* another thread may have interned it while we resolved */
+    HASH_FIND(hh, cs_table, &ip, sizeof(const void*), cs);
+    if (cs) { uint32_t id = cs->id; pthread_mutex_unlock(&cs_mutex); return id; }
+
+    cs = (CallSite*) recorder_malloc(sizeof(CallSite));
+    cs->ip        = ip;
+    cs->module_id = module_intern(path);
+    /* slide, not dli_fbase */
+    cs->offset    = (uint64_t)((const char*)ip - (const char*)lm->l_addr);
+    cs->id        = cs_count++;
+    HASH_ADD(hh, cs_table, ip, sizeof(const void*), cs);
+    uint32_t id = cs->id;
+    pthread_mutex_unlock(&cs_mutex);
+    return id;
+}
+
+/* Ids are per-rank, so each rank needs its own table. */
+void callsite_save_local(int rank, const char* traces_dir)
+{
+    if (!cs_enabled) return;
+
+    char path[1280];
+    snprintf(path, sizeof(path), "%s/%d.callsites", traces_dir, rank);
+    FILE* f = GOTCHA_REAL_CALL(fopen)(path, "wb");
+    if (!f) return;
+
+    CallSiteSectionHeader hdr;
+    hdr.version      = 1;
+    hdr.num_modules  = cs_module_count;
+    hdr.num_sites    = cs_count;
+    hdr.strtab_bytes = (uint32_t) cs_strbytes;
+    GOTCHA_REAL_CALL(fwrite)(&hdr, sizeof(hdr), 1, f);
+
+    /* ordered by id */
+    char**  paths = (char**)  calloc(cs_module_count, sizeof(char*));
+    size_t* lens  = (size_t*) calloc(cs_module_count, sizeof(size_t));
+    CallSiteModule *m, *mtmp;
+    HASH_ITER(hh, cs_modules, m, mtmp) { paths[m->id] = m->path; lens[m->id] = m->path_len; }
+    for (uint32_t i = 0; i < cs_module_count; i++)
+        if (paths[i]) GOTCHA_REAL_CALL(fwrite)(paths[i], lens[i], 1, f);
+    free(paths); free(lens);
+
+    /* ordered by id */
+    if (cs_count) {
+        CallSiteEntry* tab = (CallSiteEntry*) calloc(cs_count, sizeof(CallSiteEntry));
+        CallSite *cs, *cstmp;
+        HASH_ITER(hh, cs_table, cs, cstmp) {
+            tab[cs->id].module_id = cs->module_id;
+            tab[cs->id].offset    = cs->offset;
+        }
+        GOTCHA_REAL_CALL(fwrite)(tab, sizeof(CallSiteEntry), cs_count, f);
+        free(tab);
+    }
+    GOTCHA_REAL_CALL(fclose)(f);
+}
+
+void callsite_cleanup()
+{
+    CallSite *cs, *cstmp;
+    HASH_ITER(hh, cs_table, cs, cstmp) {
+        HASH_DEL(cs_table, cs);
+        recorder_free(cs, sizeof(CallSite));
+    }
+    cs_table = NULL;
+
+    CallSiteModule *m, *mtmp;
+    HASH_ITER(hh, cs_modules, m, mtmp) {
+        HASH_DEL(cs_modules, m);
+        recorder_free(m->path, m->path_len);
+        recorder_free(m, sizeof(CallSiteModule));
+    }
+    cs_modules = NULL;
+    cs_count = 0; cs_module_count = 0; cs_strbytes = 0;
+}