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

@@ -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

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
+        // keep track of the deepest stack
-    ssize_t depth = current - bench_stack_entrance;
+        ssize_t depth = current - bench_stack_entrance;
-    if (depth < 0) {
+        if (depth < 0) {
-        depth = -depth;
+            depth = -depth;
+        }
+
+        if ((size_t)depth > bench_stack_watermark) {
+            bench_stack_watermark = depth;
+        }
     }
 
-    if ((size_t)depth > bench_stack_watermark) {
+    // haha, a little 32-bit stack
-        bench_stack_watermark = depth;
+    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;

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", \
+    bench_trace("%s:%d:trace: " fmt "%s\n", __FILE__, __LINE__, __VA_ARGS__)
-        __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

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
+        // keep track of the deepest stack
-    ssize_t depth = current - test_stack_entrance;
+        ssize_t depth = current - test_stack_entrance;
-    if (depth < 0) {
+        if (depth < 0) {
-        depth = -depth;
+            depth = -depth;
+        }
+
+        if ((size_t)depth > test_stack_watermark) {
+            test_stack_watermark = depth;
+        }
     }
 
-    if ((size_t)depth > test_stack_watermark) {
+    // haha, a little 32-bit stack
-        test_stack_watermark = depth;
+    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,

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", \
+    test_trace("%s:%d:trace: " fmt "%s\n", __FILE__, __LINE__, __VA_ARGS__)
-        __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