From 28be23d1e6bc335b3d5fcb0c4ec37f7b0c610fc3 Mon Sep 17 00:00:00 2001 From: Zhaobin Zhu Date: Mon, 28 Sep 2026 05:52:08 -0700 Subject: [PATCH 1/2] add find source code and fix for posix.c race --- include/recorder-logger.h | 26 ++++- include/recorder.h | 2 + lib/CMakeLists.txt | 2 + lib/recorder-callsite.c | 238 ++++++++++++++++++++++++++++++++++++++ lib/recorder-cst-cfg.c | 8 +- lib/recorder-logger.c | 42 ++++++- lib/recorder-posix.c | 25 ++-- tools/CMakeLists.txt | 2 +- tools/reader-callsite.c | 173 +++++++++++++++++++++++++++ tools/reader-cst-cfg.c | 9 ++ tools/reader-private.h | 1 + tools/reader.c | 2 + tools/reader.h | 10 ++ tools/recorder2text.c | 18 ++- 14 files changed, 543 insertions(+), 15 deletions(-) create mode 100644 lib/recorder-callsite.c create mode 100644 tools/reader-callsite.c diff --git a/include/recorder-logger.h b/include/recorder-logger.h index 19a21b8a..b6830602 100644 --- a/include/recorder-logger.h +++ b/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,27 @@ 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 (store_call_site = true) */ } RecorderSectionType; +/* Call site table (RECORDER_SECTION_CALLSITES), one per rank: + * [CallSiteSectionHeader][module paths, NUL-separated][CallSiteEntry * n] + * Resolve with: addr2line -f -i -e */ +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 +170,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; // Wether to store the caller's return address bool interprocess_compression; // Wether to perform interprocess compression of cst/cfg bool interprocess_pattern_recognition; bool intraprocess_pattern_recognition; @@ -167,6 +185,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(); diff --git a/include/recorder.h b/include/recorder.h index fdd81063..44665a65 100644 --- a/include/recorder.h +++ b/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" @@ -52,6 +53,7 @@ */ #define RECORDER_INTERCEPTOR_PROLOGUE_CORE(ret, func, real_args) \ Record *record = recorder_malloc(sizeof(Record)); \ + record->call_site = callsite_intern(__builtin_return_address(0)); \ record->func_id = get_function_id_by_name(#func); \ record->tid = recorder_gettid(); \ logger_record_enter(record); \ diff --git a/lib/CMakeLists.txt b/lib/CMakeLists.txt index b56b3edf..124585b9 100644 --- a/lib/CMakeLists.txt +++ b/lib/CMakeLists.txt @@ -18,6 +18,7 @@ set(RECORDER_SRCS ${CMAKE_CURRENT_SOURCE_DIR}/recorder-posix.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-utils.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-logger.c + ${CMAKE_CURRENT_SOURCE_DIR}/recorder-callsite.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-gotcha.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-function-profiler.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-pattern-recognition.c @@ -174,6 +175,7 @@ target_link_libraries(recorder PUBLIC gotcha # this must match add_library(target) in GOTCHA project, PUBLIC ${RECORDER_EXT_LIB_DEPENDENCIES} PUBLIC pthread + PUBLIC unwind # call site fallback behind our own MPI forwarders ) target_compile_definitions(recorder diff --git a/lib/recorder-callsite.c b/lib/recorder-callsite.c new file mode 100644 index 00000000..20a19339 --- /dev/null +++ b/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 +#include +#include +#include +#include +#include +#include +#include +#include +#include +#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; +} diff --git a/lib/recorder-cst-cfg.c b/lib/recorder-cst-cfg.c index 38dc32b2..2bd4d301 100644 --- a/lib/recorder-cst-cfg.c +++ b/lib/recorder-cst-cfg.c @@ -12,6 +12,7 @@ * thread id: sizeof(pthread_t) * func id: sizeof(record->func_id) * call_depth: sizeof(record->call_depth) + * call_site: sizeof(record->call_site) * arg count: sizeof(record->arg_count) * arg strlen: sizeof(int) * args: arg_strlen @@ -21,7 +22,8 @@ int cs_key_args_start() { Record r; size_t args_start = sizeof(pthread_t) + sizeof(r.func_id) + - sizeof(r.call_depth) + sizeof(r.arg_count) + sizeof(int); + sizeof(r.call_depth) + sizeof(r.call_site) + + sizeof(r.arg_count) + sizeof(int); return ((int)args_start); } @@ -69,6 +71,8 @@ char* compose_cs_key(Record* record, int* key_len) { pos += sizeof(record->func_id); memcpy(key+pos, &record->call_depth, sizeof(record->call_depth)); pos += sizeof(record->call_depth); + memcpy(key+pos, &record->call_site, sizeof(record->call_site)); + pos += sizeof(record->call_site); memcpy(key+pos, &record->arg_count, sizeof(record->arg_count)); pos += sizeof(record->arg_count); memcpy(key+pos, &args_strlen, sizeof(int)); @@ -105,6 +109,8 @@ Record* cs_to_record(CallSignature *cs) { pos += sizeof(record->func_id); memcpy(&record->call_depth, key+pos, sizeof(record->call_depth)); pos += sizeof(record->call_depth); + memcpy(&record->call_site, key+pos, sizeof(record->call_site)); + pos += sizeof(record->call_site); memcpy(&record->arg_count, key+pos, sizeof(record->arg_count)); pos += sizeof(record->arg_count); diff --git a/lib/recorder-logger.c b/lib/recorder-logger.c index a86ae2ba..4a1f3084 100644 --- a/lib/recorder-logger.c +++ b/lib/recorder-logger.c @@ -79,6 +79,8 @@ void write_record(Record *record) { record->tid = 0; if(!logger.store_call_depth) record->call_depth = 0; + if(!logger.store_call_site) + record->call_site = 0; int key_len; char* key = compose_cs_key(record, &key_len); @@ -123,15 +125,22 @@ void write_record(Record *record) { pthread_mutex_unlock(&g_mutex); } +/* The per-thread stack is reached through TLS, so the hot path needs no lock. + * g_record_stack only keeps them for cleanup and is touched once per thread. */ +static __thread struct RecordStack* tls_record_stack = NULL; +static pthread_mutex_t g_stack_mutex = PTHREAD_MUTEX_INITIALIZER; + void logger_record_enter(Record* record) { - struct RecordStack *rs; - HASH_FIND(hh, g_record_stack, &record->tid, sizeof(pthread_t), rs); + struct RecordStack *rs = tls_record_stack; if(!rs) { rs = recorder_malloc(sizeof(struct RecordStack)); rs->records = NULL; rs->call_depth = 0; rs->tid = record->tid; + pthread_mutex_lock(&g_stack_mutex); HASH_ADD(hh, g_record_stack, tid, sizeof(pthread_t), rs); + pthread_mutex_unlock(&g_stack_mutex); + tls_record_stack = rs; } DL_APPEND(rs->records, record); @@ -270,6 +279,7 @@ void logger_init() { logger.directory_created = false; logger.store_tid = false; logger.store_call_depth = true; + logger.store_call_site = true; logger.interprocess_compression = true; logger.intraprocess_pattern_recognition = false; logger.interprocess_pattern_recognition = false; @@ -295,6 +305,10 @@ void logger_init() { const char* store_call_depth_str = getenv(RECORDER_STORE_CALL_DEPTH); if(store_call_depth_str) logger.store_call_depth = atoi(store_call_depth_str); + const char* store_call_site_str = getenv(RECORDER_STORE_CALL_SITE); + if(store_call_site_str) + logger.store_call_site = atoi(store_call_site_str); + callsite_set_enabled(logger.store_call_site); const char* interprocess_compression_env = getenv(RECORDER_INTERPROCESS_COMPRESSION); if(interprocess_compression_env) logger.interprocess_compression = atoi(interprocess_compression_env); @@ -316,6 +330,7 @@ void logger_init() { } void cleanup_record_stack() { + tls_record_stack = NULL; struct RecordStack *rs, *tmp; HASH_ITER(hh, g_record_stack, rs, tmp) { HASH_DEL(g_record_stack, rs); @@ -460,6 +475,7 @@ static void combine_output_files() { bool ic = logger.interprocess_compression; int nprocs = logger.nprocs; int nsects = ic ? 5 : (2 + 2 * nprocs); + if (logger.store_call_site) nsects += nprocs; char combined_path[1024]; sprintf(combined_path, "%s/recorder.dat", logger.traces_dir); @@ -472,7 +488,7 @@ static void combine_output_files() { /* Write placeholder file header */ RecorderFileHeader hdr; memcpy(hdr.magic, "RECORDER", 8); - hdr.format_version = 1; + hdr.format_version = 2; /* 2: the CST key carries call_site */ hdr.num_sections = (uint32_t)nsects; write(out_fd, &hdr, sizeof(hdr)); @@ -495,6 +511,15 @@ static void combine_output_files() { sprintf(path, "%s/recorder.ts", logger.traces_dir); write_file_as_section_fd(out_fd, &entries[s++], RECORDER_SECTION_TIMESTAMPS, -1, path); + /* one call site table per rank; ids are per-rank */ + if (logger.store_call_site) { + for (int r = 0; r < nprocs; r++) { + sprintf(path, "%s/%d.callsites", logger.traces_dir, r); + write_file_as_section_fd(out_fd, &entries[s++], + RECORDER_SECTION_CALLSITES, r, path); + } + } + if (ic) { sprintf(path, "%s/recorder.cst", logger.traces_dir); write_file_as_section_fd(out_fd, &entries[s++], RECORDER_SECTION_GLOBAL_CST, -1, path); @@ -551,6 +576,10 @@ void logger_finalize() { iopr_interprocess(&logger); } + // Before the collective cst/cfg phase, which also acts as the barrier. + if(logger.store_call_site) + callsite_save_local(logger.rank, logger.traces_dir); + // interprocess cst and cfg compression cleanup_record_stack(); if(logger.interprocess_compression) { @@ -569,6 +598,13 @@ void logger_finalize() { if(logger.rank == 0) { combine_output_files(); + if(logger.store_call_site) { + char cspath[1280]; + for(int r = 0; r < logger.nprocs; r++) { + sprintf(cspath, "%s/%d.callsites", logger.traces_dir, r); + GOTCHA_REAL_CALL(remove)(cspath); + } + } RECORDER_LOGINFO("[Recorder] trace written to %s/recorder.dat\n", logger.traces_dir); } diff --git a/lib/recorder-posix.c b/lib/recorder-posix.c index e6af38be..702a1fbe 100644 --- a/lib/recorder-posix.c +++ b/lib/recorder-posix.c @@ -36,21 +36,25 @@ typedef struct fd_map { static stream_map_t* stream2name_map; static fd_map_t* fd2name_map; +/* Both maps are global and touched by every open/close from every thread. */ +static pthread_mutex_t map_mutex = PTHREAD_MUTEX_INITIALIZER; static inline char* fd2name(int fd) { fd_map_t *entry = NULL; + pthread_mutex_lock(&map_mutex); HASH_FIND_INT(fd2name_map, &fd, entry); - if(entry) - return strdup(entry->filename); // duplicate the filename as it will be release in free_record() - return NULL; + char* name = entry ? strdup(entry->filename) : NULL; // freed in free_record() + pthread_mutex_unlock(&map_mutex); + return name; } static inline char* stream2name(FILE* stream) { stream_map_t *entry = NULL; + pthread_mutex_lock(&map_mutex); HASH_FIND_PTR(stream2name_map, &stream, entry); - if(entry) - return strdup(entry->filename); - return NULL; + char* name = entry ? strdup(entry->filename) : NULL; + pthread_mutex_unlock(&map_mutex); + return name; } @@ -92,18 +96,23 @@ static inline void add_to_map(char* filename, void* arg, int arg_type) { if(arg_type == ARG_TYPE_STREAM) { // FILE* stream stream_map_t *entry = malloc(sizeof(stream_map_t)); entry->stream = (FILE*) arg; - entry->filename = realrealpath(filename); + entry->filename = realrealpath(filename); // outside the lock, may do I/O + pthread_mutex_lock(&map_mutex); HASH_ADD_PTR(stream2name_map, stream, entry); + pthread_mutex_unlock(&map_mutex); } if(arg_type == ARG_TYPE_FD) { fd_map_t *entry = malloc(sizeof(fd_map_t)); entry->fd = *((int*) arg); entry->filename = realrealpath(filename); + pthread_mutex_lock(&map_mutex); HASH_ADD_INT(fd2name_map, fd, entry); + pthread_mutex_unlock(&map_mutex); } } static inline void remove_from_map(void* arg, int arg_type) { + pthread_mutex_lock(&map_mutex); if(arg_type == ARG_TYPE_FD) { int fd = (*(int*) arg); fd_map_t *entry = NULL; @@ -123,7 +132,7 @@ static inline void remove_from_map(void* arg, int arg_type) { free(entry->filename); free(entry); } - } + } pthread_mutex_unlock(&map_mutex); } diff --git a/tools/CMakeLists.txt b/tools/CMakeLists.txt index b457b64b..fdf9328a 100644 --- a/tools/CMakeLists.txt +++ b/tools/CMakeLists.txt @@ -28,7 +28,7 @@ endif() # Tools #------------------------------------------------------------------------------ -add_library(reader reader.c reader-cst-cfg.c) +add_library(reader reader.c reader-cst-cfg.c reader-callsite.c) target_link_libraries(reader PUBLIC ${ZLIB_LIBRARIES} ) diff --git a/tools/reader-callsite.c b/tools/reader-callsite.c new file mode 100644 index 00000000..353a5eee --- /dev/null +++ b/tools/reader-callsite.c @@ -0,0 +1,173 @@ +/* Resolve call site ids to source locations. + * addr2line is called once per module with all of its offsets: call sites + * repeat heavily, so even huge traces have only a few thousand. + * Output per site: ": in [ <- : in ]...", + * innermost frame first; ":?" when the compiler dropped the line. */ +#define _GNU_SOURCE +#include +#include +#include +#include +#include "reader.h" + +#define CHUNK 128 /* offsets per addr2line invocation */ + +#define MAXFRAMES 16 + +static void strip_discriminator(char* s) +{ + char* p = strstr(s, " (discriminator"); + if (p) *p = '\0'; +} + +/* addr2line lists the innermost frame first, like a backtrace. That frame is + * the line holding the call itself and does not move with inlining; the frames + * after "<-" are the functions it was inlined into. */ +static char* format_frames(char (*fn)[256], char (*loc)[512], int n) +{ + if (n == 0 || strncmp(loc[0], "??", 2) == 0) return NULL; + + size_t cap = 600 + (size_t) n * 800; + char* s = (char*) malloc(cap); + int len = 0; + for (int k = 0; k < n; k++) { + if (k) len += snprintf(s + len, cap - len, " <- "); + len += snprintf(s + len, cap - len, "%s", loc[k]); + if (strncmp(fn[k], "??", 2) != 0) + len += snprintf(s + len, cap - len, " in %s", fn[k]); + } + return s; +} + +static void resolve_module(const char* module, uint32_t* ids, uint64_t* offs, + uint32_t n, char** out) +{ + for (uint32_t start = 0; start < n; start += CHUNK) { + uint32_t cnt = (n - start < CHUNK) ? (n - start) : CHUNK; + + size_t cap = strlen(module) + 80 + cnt * 20; + char* cmd = (char*) malloc(cap); + int len = snprintf(cmd, cap, "addr2line -a -i -f -C -e '%s'", module); + for (uint32_t i = 0; i < cnt; i++) + len += snprintf(cmd + len, cap - len, " 0x%lx", + (unsigned long) offs[start + i]); + snprintf(cmd + len, cap - len, " 2>/dev/null"); + + FILE* p = popen(cmd, "r"); + free(cmd); + if (!p) return; + + /* per address: "0x", then (function, file:line) pairs */ + char fn[MAXFRAMES][256], loc[MAXFRAMES][512]; + int nframes = 0, want_fn = 1; + long cur = -1; + char line[1024]; + while (fgets(line, sizeof(line), p)) { + line[strcspn(line, "\n")] = '\0'; + if (line[0] == '0' && line[1] == 'x') { + if (cur >= 0 && cur < (long) cnt) + out[ids[start + cur]] = format_frames(fn, loc, nframes); + cur++; nframes = 0; want_fn = 1; + continue; + } + if (nframes >= MAXFRAMES) continue; + if (want_fn) { + snprintf(fn[nframes], sizeof(fn[nframes]), "%s", line); + } else { + strip_discriminator(line); + snprintf(loc[nframes], sizeof(loc[nframes]), "%s", line); + nframes++; + } + want_fn = !want_fn; + } + if (cur >= 0 && cur < (long) cnt) + out[ids[start + cur]] = format_frames(fn, loc, nframes); + pclose(p); + } +} + +CallSiteTable* callsite_table_load(const char* combined_path, int rank) +{ + FILE* f = fopen(combined_path, "rb"); + if (!f) return NULL; + + RecorderFileHeader hdr; + if (fread(&hdr, sizeof(hdr), 1, f) != 1 || + memcmp(hdr.magic, "RECORDER", 8) != 0) { fclose(f); return NULL; } + + RecorderSectionEntry* tab = (RecorderSectionEntry*) + malloc(sizeof(RecorderSectionEntry) * hdr.num_sections); + if (fread(tab, sizeof(RecorderSectionEntry), hdr.num_sections, f) != hdr.num_sections) { + free(tab); fclose(f); return NULL; + } + + uint64_t off = 0, size = 0; + int found = 0; + for (uint32_t i = 0; i < hdr.num_sections; i++) + if (tab[i].type == (uint32_t)RECORDER_SECTION_CALLSITES && tab[i].rank == rank) { + off = tab[i].offset; size = tab[i].size; found = 1; break; + } + free(tab); + if (!found || size < sizeof(CallSiteSectionHeader)) { fclose(f); return NULL; } + + char* sec = (char*) malloc(size); + fseek(f, (long) off, SEEK_SET); + if (fread(sec, 1, size, f) != size) { free(sec); fclose(f); return NULL; } + fclose(f); + + CallSiteSectionHeader* sh = (CallSiteSectionHeader*) sec; + if (sh->num_sites == 0) { free(sec); return NULL; } + + /* module paths */ + char** mods = (char**) calloc(sh->num_modules, sizeof(char*)); + char* p = sec + sizeof(CallSiteSectionHeader); + for (uint32_t i = 0; i < sh->num_modules; i++) { mods[i] = p; p += strlen(p) + 1; } + + CallSiteEntry* ent = (CallSiteEntry*) (sec + sizeof(CallSiteSectionHeader) + + sh->strtab_bytes); + + CallSiteTable* t = (CallSiteTable*) calloc(1, sizeof(CallSiteTable)); + t->num_sites = sh->num_sites; + t->loc = (char**) calloc(sh->num_sites, sizeof(char*)); + + /* one addr2line run per module */ + uint32_t* ids = (uint32_t*) malloc(sizeof(uint32_t) * sh->num_sites); + uint64_t* offs = (uint64_t*) malloc(sizeof(uint64_t) * sh->num_sites); + for (uint32_t m = 0; m < sh->num_modules; m++) { + uint32_t n = 0; + for (uint32_t i = 0; i < sh->num_sites; i++) + if (ent[i].module_id == m) { ids[n] = i; offs[n] = ent[i].offset; n++; } + if (n) resolve_module(mods[m], ids, offs, n, t->loc); + } + free(ids); free(offs); + + /* unresolved: keep module+offset, still usable later */ + for (uint32_t i = 0; i < sh->num_sites; i++) { + if (t->loc[i]) continue; + const char* mod = (ent[i].module_id < sh->num_modules) + ? mods[ent[i].module_id] : "?"; + const char* base = strrchr(mod, '/'); + char buf[512]; + snprintf(buf, sizeof(buf), "%s+0x%lx", base ? base + 1 : mod, + (unsigned long) ent[i].offset); + t->loc[i] = strdup(buf); + } + + free(mods); + free(sec); + return t; +} + +const char* callsite_table_get(CallSiteTable* t, uint32_t id) +{ + if (!t || id >= t->num_sites || !t->loc[id]) return NULL; + return t->loc[id]; +} + +void callsite_table_free(CallSiteTable* t) +{ + if (!t) return; + for (uint32_t i = 0; i < t->num_sites; i++) free(t->loc[i]); + free(t->loc); + free(t); +} diff --git a/tools/reader-cst-cfg.c b/tools/reader-cst-cfg.c index 7fb53559..a074d258 100644 --- a/tools/reader-cst-cfg.c +++ b/tools/reader-cst-cfg.c @@ -140,6 +140,10 @@ CFG* reader_get_cfg(RecorderReader* reader, int rank) { // Caller needs to free the record after use // by using recorder_free_record() call. +/* Traces before format version 2 have no call_site in the key. */ +static int key_has_call_site = 1; +void reader_set_key_has_call_site(int has) { key_has_call_site = has; } + Record* reader_cs_to_record(CallSignature *cs) { Record *record = malloc(sizeof(Record)); @@ -153,6 +157,11 @@ Record* reader_cs_to_record(CallSignature *cs) { pos += sizeof(record->func_id); memcpy(&record->call_depth, key+pos, sizeof(record->call_depth)); pos += sizeof(record->call_depth); + record->call_site = 0; + if (key_has_call_site) { + memcpy(&record->call_site, key+pos, sizeof(record->call_site)); + pos += sizeof(record->call_site); + } memcpy(&record->arg_count, key+pos, sizeof(record->arg_count)); pos += sizeof(record->arg_count); diff --git a/tools/reader-private.h b/tools/reader-private.h index b485a78e..0d8460d6 100644 --- a/tools/reader-private.h +++ b/tools/reader-private.h @@ -58,6 +58,7 @@ CST* reader_get_cst(RecorderReader* reader, int rank); CFG* reader_get_cfg(RecorderReader* reader, int rank); Record* reader_cs_to_record(CallSignature *cs); +void reader_set_key_has_call_site(int has); IntervalsMap* build_offset_intervals(RecorderReader *reader, int *num_files); diff --git a/tools/reader.c b/tools/reader.c index e19fd113..56399ec0 100644 --- a/tools/reader.c +++ b/tools/reader.c @@ -105,6 +105,7 @@ static void load_combined_sections(RecorderReader* reader) { RecorderFileHeader hdr; fread(&hdr, sizeof(hdr), 1, fp); assert(memcmp(hdr.magic, "RECORDER", 8) == 0); + reader_set_key_has_call_site(hdr.format_version >= 2); reader->num_sections = (int)hdr.num_sections; reader->sections = malloc(sizeof(RecorderSectionEntry) * reader->num_sections); @@ -320,6 +321,7 @@ void read_metadata(RecorderReader* reader) { } void recorder_init_reader(const char* logs_dir, RecorderReader *reader) { + reader_set_key_has_call_site(0); /* multi-file traces predate call sites */ assert(logs_dir); assert(reader); diff --git a/tools/reader.h b/tools/reader.h index 9fd5f485..49e72a66 100644 --- a/tools/reader.h +++ b/tools/reader.h @@ -31,6 +31,16 @@ typedef struct CFG_t { RuleHash* cfg_head; } CFG; +/* Call site resolution -- reader-callsite.c */ +typedef struct CallSiteTable_t { + uint32_t num_sites; + char** loc; /* resolved "file:line", or "module+0xoff" */ +} CallSiteTable; + +CallSiteTable* callsite_table_load(const char* combined_path, int rank); +const char* callsite_table_get(CallSiteTable* t, uint32_t id); +void callsite_table_free(CallSiteTable* t); + typedef struct RecorderReader_t { RecorderMetadata metadata; diff --git a/tools/recorder2text.c b/tools/recorder2text.c index 0c9e4f0e..1ac3d0f8 100644 --- a/tools/recorder2text.c +++ b/tools/recorder2text.c @@ -22,6 +22,9 @@ int digits_count(int n) { return digits; } +/* table of the rank being written */ +static CallSiteTable* cs_table = NULL; + void write_to_textfile(Record *record, void* arg) { FILE* f = (FILE*) arg; @@ -37,7 +40,13 @@ void write_to_textfile(Record *record, void* arg) { fprintf(f, " %s", arg); } - fprintf(f, " )\n"); + fprintf(f, " )"); + + /* empty if call site tracking was off */ + const char* loc = callsite_table_get(cs_table, record->call_site); + if (loc) fprintf(f, " @ %s", loc); + + fprintf(f, "\n"); } @@ -80,8 +89,15 @@ int main(int argc, char **argv) { sprintf(textfile_path, formatting_fname, textfile_dir, rank); FILE* fout = fopen(textfile_path, "w"); + char combined[1200]; + snprintf(combined, sizeof(combined), "%s/recorder.dat", argv[1]); + cs_table = callsite_table_load(combined, rank); + recorder_decode_records(&reader, rank, write_to_textfile, fout); + callsite_table_free(cs_table); + cs_table = NULL; + fclose(fout); printf("\r[Recorder] rank %d finished\n", rank); From 9a2e4390b53e231e0487af10b13db3fd8671d986 Mon Sep 17 00:00:00 2001 From: Zhaobin Zhu Date: Mon, 28 Sep 2026 06:11:15 -0700 Subject: [PATCH 2/2] trace all as an option --- CMakeLists.txt | 5 +++++ include/recorder-logger.h | 10 ++++++---- include/recorder.h | 10 +++++++++- lib/CMakeLists.txt | 16 ++++++++++++++-- lib/recorder-cst-cfg.c | 12 ++++++++++-- lib/recorder-logger.c | 12 ++++++++++++ 6 files changed, 56 insertions(+), 9 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 2b177997..4c909df0 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/include/recorder-logger.h b/include/recorder-logger.h index b6830602..dfe70c84 100644 --- a/include/recorder-logger.h +++ b/include/recorder-logger.h @@ -85,12 +85,14 @@ 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 (store_call_site = true) */ + RECORDER_SECTION_CALLSITES = 7, /* per-rank call site table (FULL_TRACING only) */ } RecorderSectionType; -/* Call site table (RECORDER_SECTION_CALLSITES), one per rank: +/* 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 -f -i -e */ + * Resolve with: addr2line -a -f -i -C -e */ typedef struct CallSiteSectionHeader_t { uint32_t version; /* 1 */ uint32_t num_modules; @@ -170,7 +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; // Wether to store the caller's return address + 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; diff --git a/include/recorder.h b/include/recorder.h index 44665a65..8ee6e68c 100644 --- a/include/recorder.h +++ b/include/recorder.h @@ -51,9 +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)); \ - record->call_site = callsite_intern(__builtin_return_address(0)); \ + RECORDER_CAPTURE_CALL_SITE(record); \ record->func_id = get_function_id_by_name(#func); \ record->tid = recorder_gettid(); \ logger_record_enter(record); \ diff --git a/lib/CMakeLists.txt b/lib/CMakeLists.txt index 124585b9..da1f89ef 100644 --- a/lib/CMakeLists.txt +++ b/lib/CMakeLists.txt @@ -18,7 +18,6 @@ set(RECORDER_SRCS ${CMAKE_CURRENT_SOURCE_DIR}/recorder-posix.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-utils.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-logger.c - ${CMAKE_CURRENT_SOURCE_DIR}/recorder-callsite.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-gotcha.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-function-profiler.c ${CMAKE_CURRENT_SOURCE_DIR}/recorder-pattern-recognition.c @@ -148,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) @@ -175,7 +187,6 @@ target_link_libraries(recorder PUBLIC gotcha # this must match add_library(target) in GOTCHA project, PUBLIC ${RECORDER_EXT_LIB_DEPENDENCIES} PUBLIC pthread - PUBLIC unwind # call site fallback behind our own MPI forwarders ) target_compile_definitions(recorder @@ -192,6 +203,7 @@ target_compile_definitions(recorder PRIVATE $<$,$>:RECORDER_WITH_NETCDF> PRIVATE $<$:RECORDER_ENABLE_FCNTL_TRACE> PRIVATE $<$:RECORDER_ENABLE_CUDA_TRACE> + PUBLIC $<$:RECORDER_ENABLE_FULL_TRACING> ) recorder_set_lib_options(recorder "recorder" ${RECORDER_LIBTYPE}) diff --git a/lib/recorder-cst-cfg.c b/lib/recorder-cst-cfg.c index 2bd4d301..bea5600a 100644 --- a/lib/recorder-cst-cfg.c +++ b/lib/recorder-cst-cfg.c @@ -12,7 +12,7 @@ * thread id: sizeof(pthread_t) * func id: sizeof(record->func_id) * call_depth: sizeof(record->call_depth) - * call_site: sizeof(record->call_site) + * call_site: sizeof(record->call_site) (only with FULL_TRACING) * arg count: sizeof(record->arg_count) * arg strlen: sizeof(int) * args: arg_strlen @@ -22,7 +22,10 @@ int cs_key_args_start() { Record r; size_t args_start = sizeof(pthread_t) + sizeof(r.func_id) + - sizeof(r.call_depth) + sizeof(r.call_site) + + sizeof(r.call_depth) + +#ifdef RECORDER_ENABLE_FULL_TRACING + sizeof(r.call_site) + +#endif sizeof(r.arg_count) + sizeof(int); return ((int)args_start); } @@ -71,8 +74,10 @@ char* compose_cs_key(Record* record, int* key_len) { pos += sizeof(record->func_id); memcpy(key+pos, &record->call_depth, sizeof(record->call_depth)); pos += sizeof(record->call_depth); +#ifdef RECORDER_ENABLE_FULL_TRACING memcpy(key+pos, &record->call_site, sizeof(record->call_site)); pos += sizeof(record->call_site); +#endif memcpy(key+pos, &record->arg_count, sizeof(record->arg_count)); pos += sizeof(record->arg_count); memcpy(key+pos, &args_strlen, sizeof(int)); @@ -109,8 +114,11 @@ Record* cs_to_record(CallSignature *cs) { pos += sizeof(record->func_id); memcpy(&record->call_depth, key+pos, sizeof(record->call_depth)); pos += sizeof(record->call_depth); + record->call_site = 0; +#ifdef RECORDER_ENABLE_FULL_TRACING memcpy(&record->call_site, key+pos, sizeof(record->call_site)); pos += sizeof(record->call_site); +#endif memcpy(&record->arg_count, key+pos, sizeof(record->arg_count)); pos += sizeof(record->arg_count); diff --git a/lib/recorder-logger.c b/lib/recorder-logger.c index 4a1f3084..d73c7056 100644 --- a/lib/recorder-logger.c +++ b/lib/recorder-logger.c @@ -279,7 +279,11 @@ void logger_init() { logger.directory_created = false; logger.store_tid = false; logger.store_call_depth = true; +#ifdef RECORDER_ENABLE_FULL_TRACING logger.store_call_site = true; +#else + logger.store_call_site = false; /* not configured: nothing to store */ +#endif logger.interprocess_compression = true; logger.intraprocess_pattern_recognition = false; logger.interprocess_pattern_recognition = false; @@ -305,10 +309,12 @@ void logger_init() { const char* store_call_depth_str = getenv(RECORDER_STORE_CALL_DEPTH); if(store_call_depth_str) logger.store_call_depth = atoi(store_call_depth_str); +#ifdef RECORDER_ENABLE_FULL_TRACING const char* store_call_site_str = getenv(RECORDER_STORE_CALL_SITE); if(store_call_site_str) logger.store_call_site = atoi(store_call_site_str); callsite_set_enabled(logger.store_call_site); +#endif const char* interprocess_compression_env = getenv(RECORDER_INTERPROCESS_COMPRESSION); if(interprocess_compression_env) logger.interprocess_compression = atoi(interprocess_compression_env); @@ -488,7 +494,11 @@ static void combine_output_files() { /* Write placeholder file header */ RecorderFileHeader hdr; memcpy(hdr.magic, "RECORDER", 8); +#ifdef RECORDER_ENABLE_FULL_TRACING hdr.format_version = 2; /* 2: the CST key carries call_site */ +#else + hdr.format_version = 1; +#endif hdr.num_sections = (uint32_t)nsects; write(out_fd, &hdr, sizeof(hdr)); @@ -577,8 +587,10 @@ void logger_finalize() { } // Before the collective cst/cfg phase, which also acts as the barrier. +#ifdef RECORDER_ENABLE_FULL_TRACING if(logger.store_call_site) callsite_save_local(logger.rank, logger.traces_dir); +#endif // interprocess cst and cfg compression cleanup_record_stack();