Github/littlefs
1
Fork 0
Code Actions Activity

Added perfbd.py and block device performance sampling in bench-runner

Browse Source 
Based loosely on Linux's perf tool, perfbd.py uses trace output with
backtraces to aggregate and show the block device usage of all functions
in a program, propagating block devices operation cost up the backtrace
for each operation.

This combined with --trace-period and --trace-freq for
sampling/filtering trace events allow the bench-runner to very
efficiently record the general cost of block device operations with very
little overhead.

Adopted this as the default side-effect of make bench, replacing
cycle-based performance measurements which are less important for
littlefs.
This commit is contained in:
Christopher Haster
2022-10-13 11:09:26 -05:00
parent 29cbafeb67
commit 3a33c3795b
20 changed files with 2026 additions and 610 deletions
Download Patch File Download Diff File Expand all files Collapse all files
runners/test_runner.c
+104 -12
View File
@@ -14,6 +14,8 @@
#include <stdarg.h>
#include <stdio.h>
#include <unistd.h>
#include <time.h>
#include <execinfo.h>
// some helpers
@@ -421,26 +423,63 @@ size_t test_step_step = 1;
const char *test_disk_path = NULL;
const char *test_trace_path = NULL;
bool test_trace_backtrace = false;
uint32_t test_trace_period = 0;
uint32_t test_trace_freq = 0;
FILE *test_trace_file = NULL;
uint32_t test_trace_cycles = 0;
uint64_t test_trace_time = 0;
uint64_t test_trace_open_time = 0;
lfs_emubd_sleep_t test_read_sleep = 0.0;
lfs_emubd_sleep_t test_prog_sleep = 0.0;
lfs_emubd_sleep_t test_erase_sleep = 0.0;
// this determines both the backtrace buffer and the trace printf buffer, if
// trace ends up interleaved or truncated this may need to be increased
#ifndef TEST_TRACE_BACKTRACE_BUFFER_SIZE
#define TEST_TRACE_BACKTRACE_BUFFER_SIZE 8192
#endif
void *test_trace_backtrace_buffer[
TEST_TRACE_BACKTRACE_BUFFER_SIZE / sizeof(void*)];
// trace printing
void test_trace(const char *fmt, ...) {
if (test_trace_path) {
if (!test_trace_file) {
// Tracing output is heavy and trying to open every trace
// call is slow, so we only try to open the trace file every
// so often. Note this doesn't affect successfully opened files
if (test_trace_cycles % 128 != 0) {
// sample at a specific period?
if (test_trace_period) {
if (test_trace_cycles % test_trace_period != 0) {
test_trace_cycles += 1;
return;
}
test_trace_cycles += 1;
}
// sample at a specific frequency?
if (test_trace_freq) {
struct timespec t;
clock_gettime(CLOCK_MONOTONIC, &t);
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;
}
test_trace_time = now;
}
if (!test_trace_file) {
// Tracing output is heavy and trying to open every trace
// call is slow, so we only try to open the trace file every
// so often. Note this doesn't affect successfully opened files
struct timespec t;
clock_gettime(CLOCK_MONOTONIC, &t);
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;
}
test_trace_open_time = now;
// try to open the trace file
int fd;
if (strcmp(test_trace_path, "-") == 0) {
fd = dup(1);
@@ -461,19 +500,42 @@ void test_trace(const char *fmt, ...) {
FILE *f = fdopen(fd, "a");
assert(f);
int err = setvbuf(f, NULL, _IOLBF, BUFSIZ);
int err = setvbuf(f, NULL, _IOFBF,
TEST_TRACE_BACKTRACE_BUFFER_SIZE);
assert(!err);
test_trace_file = f;
}
// print trace
va_list va;
va_start(va, fmt);
int res = vfprintf(test_trace_file, fmt, va);
va_end(va);
if (res < 0) {
fclose(test_trace_file);
test_trace_file = NULL;
return;
}
va_end(va);
if (test_trace_backtrace) {
// print backtrace
size_t count = backtrace(
test_trace_backtrace_buffer,
TEST_TRACE_BACKTRACE_BUFFER_SIZE);
// note we skip our own stack frame
for (size_t i = 1; i < count; i++) {
res = fprintf(test_trace_file, "\tat %p\n",
test_trace_backtrace_buffer[i]);
if (res < 0) {
fclose(test_trace_file);
test_trace_file = NULL;
return;
}
}
}
// flush immediately
fflush(test_trace_file);
}
}
@@ -1838,9 +1900,12 @@ enum opt_flags {
OPT_STEP = 's',
OPT_DISK = 'd',
OPT_TRACE = 't',
OPT_READ_SLEEP = 8,
OPT_PROG_SLEEP = 9,
OPT_ERASE_SLEEP = 10,
OPT_TRACE_BACKTRACE = 8,
OPT_TRACE_PERIOD = 9,
OPT_TRACE_FREQ = 10,
OPT_READ_SLEEP = 11,
OPT_PROG_SLEEP = 12,
OPT_ERASE_SLEEP = 13,
};
const char *short_opts = "hYlLD:G:P:s:d:t:";
@@ -1865,6 +1930,9 @@ const struct option long_opts[] = {
{"step", required_argument, NULL, OPT_STEP},
{"disk", required_argument, NULL, OPT_DISK},
{"trace", required_argument, NULL, OPT_TRACE},
{"trace-backtrace", no_argument, NULL, OPT_TRACE_BACKTRACE},
{"trace-period", required_argument, NULL, OPT_TRACE_PERIOD},
{"trace-freq", required_argument, NULL, OPT_TRACE_FREQ},
{"read-sleep", required_argument, NULL, OPT_READ_SLEEP},
{"prog-sleep", required_argument, NULL, OPT_PROG_SLEEP},
{"erase-sleep", required_argument, NULL, OPT_ERASE_SLEEP},
@@ -1887,8 +1955,11 @@ const char *const help_text[] = {
"Comma-separated list of disk geometries to test.",
"Comma-separated list of power-loss scenarios to test.",
"Comma-separated range of test permutations to run (start,stop,step).",
"Redirect block device operations to this file.",
"Redirect trace output to this file.",
"Direct block device operations to this file.",
"Direct trace output to this file.",
"Include a backtrace with every trace statement.",
"Sample trace output at this period in cycles.",
"Sample trace output at this frequency in hz.",
"Artificial read delay in seconds.",
"Artificial prog delay in seconds.",
"Artificial erase delay in seconds.",
@@ -2460,6 +2531,27 @@ step_unknown:
case OPT_TRACE:
test_trace_path = optarg;
break;
case OPT_TRACE_BACKTRACE:
test_trace_backtrace = true;
break;
case OPT_TRACE_PERIOD: {
char *parsed = NULL;
test_trace_period = strtoumax(optarg, &parsed, 0);
if (parsed == optarg) {
fprintf(stderr, "error: invalid trace-period: %s\n", optarg);
exit(-1);
}
break;
}
case OPT_TRACE_FREQ: {
char *parsed = NULL;
test_trace_freq = strtoumax(optarg, &parsed, 0);
if (parsed == optarg) {
fprintf(stderr, "error: invalid trace-freq: %s\n", optarg);
exit(-1);
}
break;
}
case OPT_READ_SLEEP: {
char *parsed = NULL;
double read_sleep = strtod(optarg, &parsed);