From c722bc08f576bd72c5d3844acb7b076db3ca0b70 Mon Sep 17 00:00:00 2001 From: Christopher Haster Date: Fri, 6 Feb 2026 00:15:58 -0600 Subject: [PATCH] runners: Intercept logs/printf and exclude from stack/heap measurements Logging is one of those things that's very useful to keep around, but has a high-risk of stack/heap costs that shouldn't count towards any benchmarks (you can always disable logging). So, lets exclude them from stack/heap measurements. This could've been done by defining all of littlefs's LFS3_DEBUG/INFO/ WARN/ERROR macros, but intercepting printf directly is a bit less tedious. As a plus, we eliminate logging costs from any other filesystem we benchmark, without need to fiddle with everyone's logging APIs. --- Hmm. Actually, now that I've done a test run, these changes seem to have no effect. Which makes sense in hindsight: 1. For efficiencies sake, printf likely tries to allocate infrequently. Maybe only during the first call? And we print the bench id before entering the bench. 2. The way our stack measurements work, we only count them if we enter a bd op or call BENCH_STACK_PAUSE(). So any printfs encountered previously would have been ignored by our stack measurements. Still, better safe than sorry. --- Makefile | 8 ++++ runners/bench_runner.c | 90 ++++++++++++++++++++++++++++++++++-------- runners/bench_runner.h | 12 +++--- runners/test_runner.c | 90 ++++++++++++++++++++++++++++++++++-------- runners/test_runner.h | 12 +++--- 5 files changed, 168 insertions(+), 44 deletions(-) diff --git a/Makefile b/Makefile index 45819c2c..25f0ff49 100644 --- a/Makefile +++ b/Makefile @@ -105,24 +105,32 @@ TEST_CFLAGS += -Wno-unused-function TEST_CFLAGS += -Wno-format-overflow ifdef STACK TEST_CFLAGS += -DTEST_STACK +TEST_CFLAGS += -Wl,--wrap=printf +TEST_CFLAGS += -Wl,--wrap=vprintf endif ifdef HEAP TEST_CFLAGS += -DTEST_HEAP TEST_CFLAGS += -Wl,--wrap=malloc TEST_CFLAGS += -Wl,--wrap=free TEST_CFLAGS += -Wl,--wrap=realloc +TEST_CFLAGS += -Wl,--wrap=printf +TEST_CFLAGS += -Wl,--wrap=vprintf endif BENCH_CFLAGS += -Wno-unused-function BENCH_CFLAGS += -Wno-format-overflow ifndef NO_STACK BENCH_CFLAGS += -DBENCH_STACK +BENCH_CFLAGS += -Wl,--wrap=printf +BENCH_CFLAGS += -Wl,--wrap=vprintf endif ifndef NO_HEAP BENCH_CFLAGS += -DBENCH_HEAP BENCH_CFLAGS += -Wl,--wrap=malloc BENCH_CFLAGS += -Wl,--wrap=free BENCH_CFLAGS += -Wl,--wrap=realloc +BENCH_CFLAGS += -Wl,--wrap=printf +BENCH_CFLAGS += -Wl,--wrap=vprintf endif ifdef VERBOSE diff --git a/runners/bench_runner.c b/runners/bench_runner.c index 7dbc95bb..de91668e 100644 --- a/runners/bench_runner.c +++ b/runners/bench_runner.c @@ -466,12 +466,15 @@ void *bench_trace_backtrace_buffer[ // trace printing void bench_trace(const char *fmt, ...) { + BENCH_STACK_PAUSE(); + BENCH_HEAP_PAUSE(); + if (bench_trace_path) { // sample at a specific period? if (bench_trace_period) { if (bench_trace_cycles % bench_trace_period != 0) { bench_trace_cycles += 1; - return; + goto done; } bench_trace_cycles += 1; } @@ -483,7 +486,7 @@ void bench_trace(const char *fmt, ...) { uint64_t now = (uint64_t)t.tv_sec*1000*1000*1000 + (uint64_t)t.tv_nsec; if (now - bench_trace_time < (1000*1000*1000) / bench_trace_freq) { - return; + goto done; } bench_trace_time = now; } @@ -497,7 +500,7 @@ void bench_trace(const char *fmt, ...) { uint64_t now = (uint64_t)t.tv_sec*1000*1000*1000 + (uint64_t)t.tv_nsec; if (now - bench_trace_open_time < 100*1000*1000) { - return; + goto done; } bench_trace_open_time = now; @@ -506,7 +509,7 @@ void bench_trace(const char *fmt, ...) { if (strcmp(bench_trace_path, "-") == 0) { fd = dup(1); if (fd < 0) { - return; + goto done; } } else { fd = open( @@ -514,7 +517,7 @@ void bench_trace(const char *fmt, ...) { O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK, 0666); if (fd < 0) { - return; + goto done; } int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND); assert(!err); @@ -536,7 +539,7 @@ void bench_trace(const char *fmt, ...) { if (res < 0) { fclose(bench_trace_file); bench_trace_file = NULL; - return; + goto done; } if (bench_trace_backtrace) { @@ -551,7 +554,7 @@ void bench_trace(const char *fmt, ...) { if (res < 0) { fclose(bench_trace_file); bench_trace_file = NULL; - return; + goto done; } } } @@ -559,6 +562,10 @@ void bench_trace(const char *fmt, ...) { // flush immediately fflush(bench_trace_file); } + +done:; + BENCH_HEAP_RESUME(); + BENCH_STACK_RESUME(); } @@ -618,6 +625,7 @@ void bench_permutation(size_t i, uint32_t *buffer, size_t size) { // stack hooks #ifdef BENCH_STACK +uint32_t bench_stack_entered = 0; uint8_t *bench_stack_entrance = NULL; size_t bench_stack_watermark = 0; #endif @@ -626,6 +634,7 @@ size_t bench_stack_watermark = 0; #ifdef BENCH_STACK __attribute__((noinline)) void bench_stack_enter(void) { + bench_stack_entered = 1; bench_stack_entrance = __builtin_frame_address(0); bench_stack_watermark = 0; } @@ -633,7 +642,7 @@ void bench_stack_enter(void) { #ifdef BENCH_STACK void bench_stack_exit(void) { - // do nothing + bench_stack_entered = 0; } #endif @@ -641,23 +650,28 @@ void bench_stack_exit(void) { #ifdef BENCH_STACK __attribute__((noinline)) void bench_stack_pause(void) { - uint8_t *current = __builtin_frame_address(0); + if (bench_stack_entered & 1) { + uint8_t *current = __builtin_frame_address(0); - // keep track of the deepest stack - ssize_t depth = current - bench_stack_entrance; - if (depth < 0) { - depth = -depth; + // keep track of the deepest stack + ssize_t depth = current - bench_stack_entrance; + if (depth < 0) { + depth = -depth; + } + + if ((size_t)depth > bench_stack_watermark) { + bench_stack_watermark = depth; + } } - if ((size_t)depth > bench_stack_watermark) { - bench_stack_watermark = depth; - } + // haha, a little 32-bit stack + bench_stack_entered <<= 1; } #endif #ifdef BENCH_STACK void bench_stack_resume(void) { - // do nothing + bench_stack_entered >>= 1; } #endif @@ -805,6 +819,48 @@ void *__wrap_realloc(void *p, size_t size) { #endif +// rather than intercepting all of littlefs's log functions, just +// intercept all calls to printf at link-time +// +// note this is not a perfect solution as the call itself needs stack, +// which may already be allocated in the parent frame, and some of +// littlefs's debug statements get loooooong +// +// disabling logging at compile time may give you more accurate results +#if defined(BENCH_STACK) || defined(BENCH_HEAP) +extern int __real_vprintf(const char *fmt, va_list args); + +int __wrap_printf(const char *fmt, ...) { + BENCH_STACK_PAUSE(); + BENCH_HEAP_PAUSE(); + + va_list args; + va_start(args, fmt); + int n = __real_vprintf(fmt, args); + va_end(args); + + BENCH_HEAP_RESUME(); + BENCH_STACK_RESUME(); + return n; +} +#endif + +#if defined(BENCH_STACK) || defined(BENCH_HEAP) +extern int __real_vprintf(const char *fmt, va_list args); + +int __wrap_vprintf(const char *fmt, va_list args) { + BENCH_STACK_PAUSE(); + BENCH_HEAP_PAUSE(); + + int n = __real_vprintf(fmt, args); + + BENCH_HEAP_RESUME(); + BENCH_STACK_RESUME(); + return n; +} +#endif + + // bench recording state typedef struct bench_record { const char *probe; diff --git a/runners/bench_runner.h b/runners/bench_runner.h index 5abe9c0a..39be99ff 100644 --- a/runners/bench_runner.h +++ b/runners/bench_runner.h @@ -44,16 +44,18 @@ #endif // override LFS3_TRACE +#ifndef LFS3_NO_TRACE void bench_trace(const char *fmt, ...); - #define LFS3_TRACE_(fmt, ...) \ - bench_trace("%s:%d:trace: " fmt "%s\n", \ - __FILE__, \ - __LINE__, \ - __VA_ARGS__) + bench_trace("%s:%d:trace: " fmt "%s\n", __FILE__, __LINE__, __VA_ARGS__) #define LFS3_TRACE(...) LFS3_TRACE_(__VA_ARGS__, "") #define LFS3_EMUBD_TRACE(...) LFS3_TRACE_(__VA_ARGS__, "") #define LFS3_KIWIBD_TRACE(...) LFS3_TRACE_(__VA_ARGS__, "") +#else +#define LFS3_TRACE(...) +#define LFS3_EMUBD_TRACE(...) +#define LFS3_KIWIBD_TRACE(...) +#endif // note these are indirectly included in any generated files diff --git a/runners/test_runner.c b/runners/test_runner.c index fa7c6a9f..65400700 100644 --- a/runners/test_runner.c +++ b/runners/test_runner.c @@ -483,12 +483,15 @@ void *test_trace_backtrace_buffer[ // trace printing void test_trace(const char *fmt, ...) { + TEST_STACK_PAUSE(); + TEST_HEAP_PAUSE(); + if (test_trace_path) { // sample at a specific period? if (test_trace_period) { if (test_trace_cycles % test_trace_period != 0) { test_trace_cycles += 1; - return; + goto done; } test_trace_cycles += 1; } @@ -500,7 +503,7 @@ void test_trace(const char *fmt, ...) { uint64_t now = (uint64_t)t.tv_sec*1000*1000*1000 + (uint64_t)t.tv_nsec; if (now - test_trace_time < (1000*1000*1000) / test_trace_freq) { - return; + goto done; } test_trace_time = now; } @@ -514,7 +517,7 @@ void test_trace(const char *fmt, ...) { uint64_t now = (uint64_t)t.tv_sec*1000*1000*1000 + (uint64_t)t.tv_nsec; if (now - test_trace_open_time < 100*1000*1000) { - return; + goto done; } test_trace_open_time = now; @@ -523,7 +526,7 @@ void test_trace(const char *fmt, ...) { if (strcmp(test_trace_path, "-") == 0) { fd = dup(1); if (fd < 0) { - return; + goto done; } } else { fd = open( @@ -531,7 +534,7 @@ void test_trace(const char *fmt, ...) { O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK, 0666); if (fd < 0) { - return; + goto done; } int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND); assert(!err); @@ -553,7 +556,7 @@ void test_trace(const char *fmt, ...) { if (res < 0) { fclose(test_trace_file); test_trace_file = NULL; - return; + goto done; } if (test_trace_backtrace) { @@ -568,7 +571,7 @@ void test_trace(const char *fmt, ...) { if (res < 0) { fclose(test_trace_file); test_trace_file = NULL; - return; + goto done; } } } @@ -576,6 +579,10 @@ void test_trace(const char *fmt, ...) { // flush immediately fflush(test_trace_file); } + +done:; + TEST_HEAP_RESUME(); + TEST_STACK_RESUME(); } // test prng @@ -634,6 +641,7 @@ void test_permutation(size_t i, uint32_t *buffer, size_t size) { // stack hooks #ifdef TEST_STACK +uint32_t test_stack_entered = 0; uint8_t *test_stack_entrance = NULL; size_t test_stack_watermark = 0; #endif @@ -642,6 +650,7 @@ size_t test_stack_watermark = 0; #ifdef TEST_STACK __attribute__((noinline)) void test_stack_enter(void) { + test_stack_entered = 1; test_stack_entrance = __builtin_frame_address(0); test_stack_watermark = 0; } @@ -649,7 +658,7 @@ void test_stack_enter(void) { #ifdef TEST_STACK void test_stack_exit(void) { - // do nothing + test_stack_entered = 0; } #endif @@ -657,23 +666,28 @@ void test_stack_exit(void) { #ifdef TEST_STACK __attribute__((noinline)) void test_stack_pause(void) { - uint8_t *current = __builtin_frame_address(0); + if (test_stack_entered & 1) { + uint8_t *current = __builtin_frame_address(0); - // keep track of the deepest stack - ssize_t depth = current - test_stack_entrance; - if (depth < 0) { - depth = -depth; + // keep track of the deepest stack + ssize_t depth = current - test_stack_entrance; + if (depth < 0) { + depth = -depth; + } + + if ((size_t)depth > test_stack_watermark) { + test_stack_watermark = depth; + } } - if ((size_t)depth > test_stack_watermark) { - test_stack_watermark = depth; - } + // haha, a little 32-bit stack + test_stack_entered <<= 1; } #endif #ifdef TEST_STACK void test_stack_resume(void) { - // do nothing + test_stack_entered >>= 1; } #endif @@ -821,6 +835,48 @@ void *__wrap_realloc(void *p, size_t size) { #endif +// rather than intercepting all of littlefs's log functions, just +// intercept all calls to printf at link-time +// +// note this is not a perfect solution as the call itself needs stack, +// which may already be allocated in the parent frame, and some of +// littlefs's debug statements get loooooong +// +// disabling logging at compile time may give you more accurate results +#if defined(TEST_STACK) || defined(TEST_HEAP) +extern int __real_vprintf(const char *fmt, va_list args); + +int __wrap_printf(const char *fmt, ...) { + TEST_STACK_PAUSE(); + TEST_HEAP_PAUSE(); + + va_list args; + va_start(args, fmt); + int n = __real_vprintf(fmt, args); + va_end(args); + + TEST_HEAP_RESUME(); + TEST_STACK_RESUME(); + return n; +} +#endif + +#if defined(TEST_STACK) || defined(TEST_HEAP) +extern int __real_vprintf(const char *fmt, va_list args); + +int __wrap_vprintf(const char *fmt, va_list args) { + TEST_STACK_PAUSE(); + TEST_HEAP_PAUSE(); + + int n = __real_vprintf(fmt, args); + + TEST_HEAP_RESUME(); + TEST_STACK_RESUME(); + return n; +} +#endif + + // encode our permutation into a reusable id static void perm_printid( const struct test_suite *suite, diff --git a/runners/test_runner.h b/runners/test_runner.h index 90dbd7f0..68085bfa 100644 --- a/runners/test_runner.h +++ b/runners/test_runner.h @@ -44,16 +44,18 @@ #endif // override LFS3_TRACE +#ifndef LFS3_NO_TRACE void test_trace(const char *fmt, ...); - #define LFS3_TRACE_(fmt, ...) \ - test_trace("%s:%d:trace: " fmt "%s\n", \ - __FILE__, \ - __LINE__, \ - __VA_ARGS__) + test_trace("%s:%d:trace: " fmt "%s\n", __FILE__, __LINE__, __VA_ARGS__) #define LFS3_TRACE(...) LFS3_TRACE_(__VA_ARGS__, "") #define LFS3_EMUBD_TRACE(...) LFS3_TRACE_(__VA_ARGS__, "") #define LFS3_KIWIBD_TRACE(...) LFS3_TRACE_(__VA_ARGS__, "") +#else +#define LFS3_TRACE(...) +#define LFS3_EMUBD_TRACE(...) +#define LFS3_KIWIBD_TRACE(...) +#endif // note these are indirectly included in any generated files