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