From 4af4cf321204bc562f1580a2ec2301a3d1d017a1 Mon Sep 17 00:00:00 2001 From: Christopher Haster Date: Mon, 9 Feb 2026 13:43:55 -0600 Subject: [PATCH] runners: bench: Added flags to control reading from bench probes - -S/--probe - Specify a probe to sample. - -x/--probe-step - Sample probes every n steps. - --probe-runfreq - Sample probes at this frequency in hz. - -X/--probe-simfreq - Sample probes at this frequency in simulated hz. Also: - --trace-simfreq - Sample trace output at this frequency in simulated hz. These give finer grain control over which probes we measure during benching, and how we measure them. These also introduce several exciting bench features: - -S/--probe provides the ability to easily filter which probes you're interested in at runtime. This should replace the growing use of MASK defines in the benches. - -x/--probe-step makes it easy to relax sampling rate when the amount of data overwhelms later scripts. This should replace the growing use of STEP defines in the benches. - The additional concept of simfreq, which allows perf-esque sampling in simtime. This provides another option for intuitively relaxing probe sampling rate without sacrificing reproducibility. (runfreq depends on wall time, so good bye reproducibility, though may still be useful in interactive contexts.) Note -S/--probe and -x/--probe-step replace MASK/STEP defines, which have already proved their usefulness, but required reimplementation in every bench case. An obvious contender to move into the bench_runner! --- Note note that -S/--probe also supports some simple sample expressions, allowing flexible step/simfreq/runfreq at the per-probe level: - -Swrite=100 - Sample probe "write" every 100 steps - -Swrite=100rhz - Sample probe "write" 100 times a runtime second - -Swrite=100shz - Sample probe "write" 100 times a simulated second Though I wonder how long it will take before I forget this feature exists. --- benches/bench_rt.toml | 14 +- benches/bench_wt.toml | 10 +- runners/bench_runner.c | 827 +++++++++++++++++++++++++++++------------ runners/bench_runner.h | 9 +- runners/test_runner.c | 247 ++++++------ runners/test_runner.h | 7 + scripts/bench.py | 31 +- scripts/test.py | 6 +- 8 files changed, 773 insertions(+), 378 deletions(-) diff --git a/benches/bench_rt.toml b/benches/bench_rt.toml index 4d7a1cd0..ca40befe 100644 --- a/benches/bench_rt.toml +++ b/benches/bench_rt.toml @@ -56,7 +56,7 @@ code = ''' lfs3_file_write(&lfs3, &file, wbuf, CHUNK) => CHUNK; // taking too long? - if (SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME) { + if (SIM_TIME && BENCH_SIMTIME() >= SIM_TIME) { return; } } @@ -71,7 +71,7 @@ code = ''' lfs3_off_t size = 0; uint64_t readed = 0; while (!(SIM_SIZE && readed >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // read from the file uint8_t rbuf[CHUNK]; lfs3_file_read(&lfs3, &file, rbuf, CHUNK) => CHUNK; @@ -123,7 +123,7 @@ code = ''' lfs3_file_write(&lfs3, &file, wbuf, CHUNK) => CHUNK; // taking too long? - if (SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME) { + if (SIM_TIME && BENCH_SIMTIME() >= SIM_TIME) { return; } } @@ -137,7 +137,7 @@ code = ''' lfs3_file_open(&lfs3, &file, "bench_random", LFS3_O_RDONLY) => 0; uint64_t readed = 0; while (!(SIM_SIZE && readed >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // seek to a random location lfs3_off_t pos = BENCH_PRNG(&prng) % SIZE; lfs3_file_seek(&lfs3, &file, pos, LFS3_SEEK_SET) => pos; @@ -191,7 +191,7 @@ code = ''' lfs3_file_write(&lfs3, &file, wbuf, d) => d; // taking too long? - if (SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME) { + if (SIM_TIME && BENCH_SIMTIME() >= SIM_TIME) { return; } } @@ -205,7 +205,7 @@ code = ''' BENCH_START("read"); uint64_t readed = 0; while (!(SIM_SIZE && readed >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // choose a random filename lfs3_off_t pos = BENCH_PRNG(&prng) % ((SIZE+(CHUNK-1))/CHUNK); char name[256]; @@ -224,7 +224,7 @@ code = ''' readed += d; // taking too long? - if (SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME) { + if (SIM_TIME && BENCH_SIMTIME() >= SIM_TIME) { break; } } diff --git a/benches/bench_wt.toml b/benches/bench_wt.toml index 30756ee0..c42d3d25 100644 --- a/benches/bench_wt.toml +++ b/benches/bench_wt.toml @@ -54,7 +54,7 @@ code = ''' // ok, one of these needs to be non-zero LFS3_ASSERT(SIM_TIME > 0 || SIM_SIZE > 0); while (!(SIM_SIZE && written >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // arguably we should just rewind and continue writing to the // front of the file when we hit the end, but this overly // penalizes littlefs2, so instead we truncate @@ -122,7 +122,7 @@ code = ''' lfs3_off_t size = 0; uint64_t written = 0; while (!(SIM_SIZE && written >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // seek to a random location lfs3_off_t pos = BENCH_PRNG(&prng) % SIZE; lfs3_file_seek(&lfs3, &file, pos, LFS3_SEEK_SET) => pos; @@ -189,7 +189,7 @@ code = ''' // ok, one of these needs to be non-zero LFS3_ASSERT(SIM_TIME > 0 || SIM_SIZE > 0); while (!(SIM_SIZE && written >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // append to log uint8_t wbuf[CHUNK]; for (lfs3_size_t j = 0; j < CHUNK; j++) { @@ -265,7 +265,7 @@ code = ''' // ok, one of these needs to be non-zero LFS3_ASSERT(SIM_TIME > 0 || SIM_SIZE > 0); while (!(SIM_SIZE && written >= (uint64_t)SIM_SIZE) - && !(SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME)) { + && !(SIM_TIME && BENCH_SIMTIME() >= SIM_TIME)) { // choose a random filename lfs3_off_t pos = BENCH_PRNG(&prng) % FILE_COUNT; char name[256]; @@ -287,7 +287,7 @@ code = ''' written += d; // taking too long? - if (SIM_TIME && BENCH_SIMTIME() >= (bench_ns_t)SIM_TIME) { + if (SIM_TIME && BENCH_SIMTIME() >= SIM_TIME) { break; } } diff --git a/runners/bench_runner.c b/runners/bench_runner.c index bfadf28a..16134ef3 100644 --- a/runners/bench_runner.c +++ b/runners/bench_runner.c @@ -165,6 +165,7 @@ ssize_t *bench_suite_define_map = NULL; bench_define_t *bench_override_defines = NULL; size_t bench_override_define_count = 0; +size_t bench_override_define_capacity = 0; size_t bench_define_depth = 1000; @@ -421,23 +422,27 @@ const bench_id_t *bench_ids = (const bench_id_t[]) { {NULL, NULL, 0}, }; size_t bench_id_count = 1; +size_t bench_id_capacity = 0; size_t bench_step_start = 0; size_t bench_step_stop = -1; size_t bench_step_step = 1; -size_t bench_step = 0; // incremented every permutation +size_t bench_steps = 0; // incremented every permutation bool bench_force = false; bench_flags_t bench_mask = 0; const char *bench_disk_path = NULL; const char *bench_trace_path = NULL; bool bench_trace_backtrace = false; -uint32_t bench_trace_step = 0; -uint32_t bench_trace_runfreq = 0; +size_t bench_trace_step = 0; +double bench_trace_runfreq = 0.0; +double bench_trace_simfreq = 0.0; +uint32_t bench_trace_paused = false; FILE *bench_trace_file = NULL; -uint32_t bench_trace_cycles = 0; -uint64_t bench_trace_time = 0; -uint64_t bench_trace_open_time = 0; +size_t bench_trace_steps = 0; +bench_ns_t bench_trace_runtime = 0; +bench_ns_t bench_trace_simtime = 0; +bench_ns_t bench_trace_open_runtime = 0; bench_ns_t bench_read_sleep = 0.0; bench_ns_t bench_prog_sleep = 0.0; bench_ns_t bench_erase_sleep = 0.0; @@ -455,106 +460,140 @@ void bench_trace(const char *fmt, ...) { BENCH_STACK_PAUSE(); BENCH_HEAP_PAUSE(); - if (bench_trace_path) { - // sample at a specific step? - if (bench_trace_step) { - if (bench_trace_cycles % bench_trace_step != 0) { - bench_trace_cycles += 1; - goto done; - } - bench_trace_cycles += 1; - } - - // sample at a specific frequency? - if (bench_trace_runfreq) { - 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 - bench_trace_time - < (1000*1000*1000) / bench_trace_runfreq) { - goto done; - } - bench_trace_time = now; - } - - if (!bench_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 - bench_trace_open_time < 100*1000*1000) { - goto done; - } - bench_trace_open_time = now; - - // try to open the trace file - int fd; - if (strcmp(bench_trace_path, "-") == 0) { - fd = dup(1); - if (fd < 0) { - goto done; - } - } else { - fd = open( - bench_trace_path, - O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK, - 0666); - if (fd < 0) { - goto done; - } - int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND); - assert(!err); - } - - FILE *f = fdopen(fd, "a"); - assert(f); - int err = setvbuf(f, NULL, _IOFBF, - BENCH_TRACE_BACKTRACE_BUFFER_SIZE); - assert(!err); - bench_trace_file = f; - } - - // print trace - va_list va; - va_start(va, fmt); - int res = vfprintf(bench_trace_file, fmt, va); - va_end(va); - if (res < 0) { - fclose(bench_trace_file); - bench_trace_file = NULL; - goto done; - } - - if (bench_trace_backtrace) { - // print backtrace - size_t count = backtrace( - bench_trace_backtrace_buffer, - BENCH_TRACE_BACKTRACE_BUFFER_SIZE); - // note we skip our own stack frame - for (size_t i = 1; i < count; i++) { - res = fprintf(bench_trace_file, "\tat %p\n", - bench_trace_backtrace_buffer[i]); - if (res < 0) { - fclose(bench_trace_file); - bench_trace_file = NULL; - goto done; - } - } - } - - // flush immediately - fflush(bench_trace_file); + if (!bench_trace_path || bench_trace_paused) { + goto done; } + // prevent accidental recursion + BENCH_TRACE_PAUSE(); + + // sample at a specific step? + if (bench_trace_step) { + if (bench_trace_steps % bench_trace_step != 0) { + bench_trace_steps += 1; + goto done_; + } + bench_trace_steps += 1; + } + + // sample at a specific frequency? + if (bench_trace_runfreq) { + struct timespec t; + clock_gettime(CLOCK_MONOTONIC, &t); + bench_ns_t now = (bench_ns_t)t.tv_sec*1000*1000*1000 + + (bench_ns_t)t.tv_nsec; + if (now - bench_trace_runtime + < (bench_ns_t)((1000.0*1000.0*1000.0) + / bench_trace_runfreq)) { + goto done_; + } + bench_trace_runtime = now; + } + + // sample at a specific simulated frequency? + if (bench_trace_simfreq) { + bench_sns_t now = BENCH_SIMTIME(); + if (now < 0) { + // I guess we shouldn't print anything until bench has + // started + goto done_; + } + if (now - bench_trace_simtime + < (bench_ns_t)((1000.0*1000.0*1000.0) + / bench_trace_simfreq)) { + goto done_; + } + bench_trace_simtime = now; + } + + if (!bench_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); + bench_ns_t now = (bench_ns_t)t.tv_sec*1000*1000*1000 + + (bench_ns_t)t.tv_nsec; + if (now - bench_trace_open_runtime < 100*1000*1000) { + goto done_; + } + bench_trace_open_runtime = now; + + // try to open the trace file + int fd; + if (strcmp(bench_trace_path, "-") == 0) { + fd = dup(1); + if (fd < 0) { + goto done_; + } + } else { + fd = open( + bench_trace_path, + O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK, + 0666); + if (fd < 0) { + goto done_; + } + int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND); + assert(!err); + } + + FILE *f = fdopen(fd, "a"); + assert(f); + int err = setvbuf(f, NULL, _IOFBF, + BENCH_TRACE_BACKTRACE_BUFFER_SIZE); + assert(!err); + bench_trace_file = f; + } + + // print trace + va_list va; + va_start(va, fmt); + int res = vfprintf(bench_trace_file, fmt, va); + va_end(va); + if (res < 0) { + fclose(bench_trace_file); + bench_trace_file = NULL; + goto done_; + } + + if (bench_trace_backtrace) { + // print backtrace + size_t count = backtrace( + bench_trace_backtrace_buffer, + BENCH_TRACE_BACKTRACE_BUFFER_SIZE); + // note we skip our own stack frame + for (size_t i = 1; i < count; i++) { + res = fprintf(bench_trace_file, "\tat %p\n", + bench_trace_backtrace_buffer[i]); + if (res < 0) { + fclose(bench_trace_file); + bench_trace_file = NULL; + goto done_; + } + } + } + + // flush immediately + fflush(bench_trace_file); + +done_:; + BENCH_TRACE_RESUME(); + done:; BENCH_HEAP_RESUME(); BENCH_STACK_RESUME(); } +void bench_trace_pause(void) { + bench_trace_paused += 1; +} + +void bench_trace_resume(void) { + assert(bench_trace_paused); + bench_trace_paused -= 1; +} + // bench prng uint32_t bench_prng(uint32_t *state) { @@ -861,78 +900,84 @@ int __wrap_vprintf(const char *fmt, va_list args) { #endif -// bench recording state + +// bench probe/recording state +typedef struct bench_probe { + const char *probe; + size_t step; + double runfreq; + double simfreq; +} bench_probe_t; + +#define BENCH_RECORD_IGNORED 0x01 +#define BENCH_RECORD_STARTED 0x02 +#define BENCH_RECORD_DIRTY 0x04 +#define BENCH_RECORD_RESULT 0x10 +#define BENCH_RECORD_FRESULT 0x20 +#define BENCH_RECORD_SIMTIME 0x40 + typedef struct bench_record { const char *probe; - bench_io_t cumul_reads; + uint32_t flags; + size_t step; + double runfreq; + double simfreq; + size_t steps; + bench_ns_t runtime; // time of last print + bench_ns_t simtime; + + uintmax_t n; + uintmax_t result; + double fresult; + bench_io_t cumul_reads; // cumulative results bench_io_t cumul_progs; bench_io_t cumul_erases; bench_io_t cumul_readed; bench_io_t cumul_progged; bench_io_t cumul_erased; bench_ns_t cumul_simtime; - bench_io_t last_reads; - bench_io_t last_progs; - bench_io_t last_erases; - bench_io_t last_readed; - bench_io_t last_progged; - bench_io_t last_erased; - bench_ns_t last_simtime; + bench_io_t start_reads; // start of probe + bench_io_t start_progs; + bench_io_t start_erases; + bench_io_t start_readed; + bench_io_t start_progged; + bench_io_t start_erased; + bench_ns_t start_simtime; } bench_record_t; -static const struct lfs3_cfg *bench_cfg = NULL; -static bench_record_t *bench_records; -size_t bench_record_count; -size_t bench_record_capacity; +bench_probe_t *bench_probes = NULL; +size_t bench_probe_count = 0; +size_t bench_probe_capacity = 0; +size_t bench_probe_step = 0; +double bench_probe_runfreq = 0.0; +double bench_probe_simfreq = 0.0; + +const struct lfs3_cfg *bench_cfg = NULL; +bench_record_t *bench_records = NULL; +size_t bench_record_count = 0; +size_t bench_record_capacity = 0; void bench_init(const struct lfs3_cfg *cfg) { bench_cfg = cfg; bench_record_count = 0; } +// needed in bench_deinit +void bench_print(bench_record_t *record); + void bench_deinit(const struct lfs3_cfg *cfg) { (void)cfg; - // do nothing + bench_cfg = NULL; + + // print any dirty probes at least once at the end of the bench + for (size_t i = 0; i < bench_record_count; i++) { + if (bench_records[i].flags & BENCH_RECORD_DIRTY) { + bench_print(&bench_records[i]); + } + } } -void bench_start(const char *probe) { - BENCH_STACK_PAUSE(); - BENCH_HEAP_PAUSE(); - - // measure current read/prog/erase - assert(bench_cfg); - #ifndef BENCH_KIWIBD - bench_sio_t reads = lfs3_emubd_reads(bench_cfg); - assert(reads >= 0); - bench_sio_t progs = lfs3_emubd_progs(bench_cfg); - assert(progs >= 0); - bench_sio_t erases = lfs3_emubd_erases(bench_cfg); - assert(erases >= 0); - bench_sio_t readed = lfs3_emubd_readed(bench_cfg); - assert(readed >= 0); - bench_sio_t progged = lfs3_emubd_progged(bench_cfg); - assert(progged >= 0); - bench_sio_t erased = lfs3_emubd_erased(bench_cfg); - assert(erased >= 0); - // note this can error if no timings provided - bench_sns_t simtime = lfs3_emubd_simtime(bench_cfg); - #else - bench_sio_t reads = lfs3_kiwibd_reads(bench_cfg); - assert(reads >= 0); - bench_sio_t progs = lfs3_kiwibd_progs(bench_cfg); - assert(progs >= 0); - bench_sio_t erases = lfs3_kiwibd_erases(bench_cfg); - assert(erases >= 0); - bench_sio_t readed = lfs3_kiwibd_readed(bench_cfg); - assert(readed >= 0); - bench_sio_t progged = lfs3_kiwibd_progged(bench_cfg); - assert(progged >= 0); - bench_sio_t erased = lfs3_kiwibd_erased(bench_cfg); - assert(erased >= 0); - // note this can error if no timings provided - bench_sns_t simtime = lfs3_kiwibd_simtime(bench_cfg); - #endif - +bench_record_t *bench_find(const char *probe) { // find our record bench_record_t *record = NULL; for (size_t i = 0; i < bench_record_count; i++) { @@ -950,6 +995,16 @@ void bench_start(const char *probe) { &bench_record_count, &bench_record_capacity); record->probe = probe; + record->flags = 0; + record->step = 0; + record->runfreq = 0.0; + record->simfreq = 0.0; + record->steps = 0; + record->runtime = 0; + record->simtime = 0; + record->n = 0; + record->result = 0; + record->fresult = 0.0; record->cumul_reads = 0; record->cumul_progs = 0; record->cumul_erases = 0; @@ -957,25 +1012,143 @@ void bench_start(const char *probe) { record->cumul_progged = 0; record->cumul_erased = 0; record->cumul_simtime = 0; - } - record->last_reads = reads; - record->last_progs = progs; - record->last_erases = erases; - record->last_readed = readed; - record->last_progged = progged; - record->last_erased = erased; - record->last_simtime = simtime; - BENCH_HEAP_RESUME(); - BENCH_STACK_RESUME(); + if (bench_probe_count) { + // find probe descriptor, if there is one + bench_probe_t *probe_ = NULL; + for (size_t i = 0; i < bench_probe_count; i++) { + if (strcmp(bench_probes[i].probe, probe) == 0) { + probe_ = &bench_probes[i]; + break; + } + } + + // no matching probe descriptor? + if (!probe_) { + record->flags |= BENCH_RECORD_IGNORED; + } else { + record->step = probe_->step; + record->runfreq = probe_->runfreq; + record->simfreq = probe_->simfreq; + } + } + + // fallback to default step/runfreq/simfreq + if (!record->step && !record->runfreq && !record->simfreq) { + record->step = bench_probe_step; + record->runfreq = bench_probe_runfreq; + record->simfreq = bench_probe_simfreq; + } + } + + return record; } -void bench_stop(const char *probe, uintmax_t n) { +void bench_print(bench_record_t *record) { + if (record->flags & BENCH_RECORD_RESULT) { + printf("benched %s %jd %"PRIu64"\n", + record->probe, + record->n, + record->result); + } else if (record->flags & BENCH_RECORD_FRESULT) { + printf("benched %s %jd %.6f\n", + record->probe, + record->n, + record->fresult); + } else if (record->flags & BENCH_RECORD_SIMTIME) { + printf("benched %s %jd " + "%"PRIu64" %"PRIu64" %"PRIu64" " + "%"PRIu64" %"PRIu64" %"PRIu64" " + "%"PRIu64"\n", + record->probe, + record->n, + record->cumul_reads, + record->cumul_progs, + record->cumul_erases, + record->cumul_readed, + record->cumul_progged, + record->cumul_erased, + record->cumul_simtime); + } else { + printf("benched %s %jd " + "%"PRIu64" %"PRIu64" %"PRIu64" " + "%"PRIu64" %"PRIu64" %"PRIu64"\n", + record->probe, + record->n, + record->cumul_reads, + record->cumul_progs, + record->cumul_erases, + record->cumul_readed, + record->cumul_progged, + record->cumul_erased); + } + + record->flags &= ~BENCH_RECORD_DIRTY; +} + +void bench_sample(bench_record_t *record) { + // if no sample method is set, default to only printing at the end + // of the bench + if (!record->step && !record->runfreq && !record->simfreq) { + return; + } + + // sample at a specific step? + if (record->step) { + if (record->steps % record->step != 0) { + record->steps += 1; + return; + } + record->steps += 1; + } + + // sample at a specific frequency? + if (record->runfreq) { + struct timespec t; + clock_gettime(CLOCK_MONOTONIC, &t); + bench_ns_t now = (bench_ns_t)t.tv_sec*1000*1000*1000 + + (bench_ns_t)t.tv_nsec; + if (now - record->runtime + < (bench_ns_t)((1000.0*1000.0*1000.0) + / record->runfreq)) { + return; + } + record->runtime = now; + } + + // sample at a specific simulated frequency? + if (record->simfreq) { + bench_sns_t now = BENCH_SIMTIME(); + if (now - record->simtime + < (bench_ns_t)((1000.0*1000.0*1000.0) + / record->simfreq)) { + return; + } + record->simtime = now; + } + + bench_print(record); +} + +void bench_start(const char *probe) { BENCH_STACK_PAUSE(); BENCH_HEAP_PAUSE(); - // measure current read/prog/erase - assert(bench_cfg); + // find our record + bench_record_t *record = bench_find(probe); + if (record->flags & BENCH_RECORD_IGNORED) { + goto done; + } + + if (record->flags & BENCH_RECORD_STARTED) { + fprintf(stderr, "error: probe double started before it was " + "stopped (%s)\n", + probe); + assert(false); + exit(-1); + } + + // find current read/prog/erase #ifndef BENCH_KIWIBD bench_sio_t reads = lfs3_emubd_reads(bench_cfg); assert(reads >= 0); @@ -1008,61 +1181,95 @@ void bench_stop(const char *probe, uintmax_t n) { bench_sns_t simtime = lfs3_kiwibd_simtime(bench_cfg); #endif + record->flags |= BENCH_RECORD_STARTED; + + record->start_reads = reads; + record->start_progs = progs; + record->start_erases = erases; + record->start_readed = readed; + record->start_progged = progged; + record->start_erased = erased; + record->start_simtime = simtime; + +done:; + BENCH_HEAP_RESUME(); + BENCH_STACK_RESUME(); +} + +void bench_stop(const char *probe, uintmax_t n) { + BENCH_STACK_PAUSE(); + BENCH_HEAP_PAUSE(); + // find our record - bench_record_t *record = NULL; - for (size_t i = 0; i < bench_record_count; i++) { - if (strcmp(bench_records[i].probe, probe) == 0) { - record = &bench_records[i]; - break; - } + bench_record_t *record = bench_find(probe); + if (record->flags & BENCH_RECORD_IGNORED) { + goto done; } - // not found? - if (!record) { + if (!(record->flags & BENCH_RECORD_STARTED)) { fprintf(stderr, "error: probe stopped before it was started (%s)\n", probe); assert(false); exit(-1); } - // add to cumulative measurements - record->cumul_reads += reads - record->last_reads; - record->cumul_progs += progs - record->last_progs; - record->cumul_erases += erases - record->last_erases; - record->cumul_readed += readed - record->last_readed; - record->cumul_progged += progged - record->last_progged; - record->cumul_erased += erased - record->last_erased; - record->cumul_simtime += simtime - record->last_simtime; + // find current read/prog/erase + #ifndef BENCH_KIWIBD + bench_sio_t reads = lfs3_emubd_reads(bench_cfg); + assert(reads >= 0); + bench_sio_t progs = lfs3_emubd_progs(bench_cfg); + assert(progs >= 0); + bench_sio_t erases = lfs3_emubd_erases(bench_cfg); + assert(erases >= 0); + bench_sio_t readed = lfs3_emubd_readed(bench_cfg); + assert(readed >= 0); + bench_sio_t progged = lfs3_emubd_progged(bench_cfg); + assert(progged >= 0); + bench_sio_t erased = lfs3_emubd_erased(bench_cfg); + assert(erased >= 0); + // note this can error if no timings provided + bench_sns_t simtime = lfs3_emubd_simtime(bench_cfg); + #else + bench_sio_t reads = lfs3_kiwibd_reads(bench_cfg); + assert(reads >= 0); + bench_sio_t progs = lfs3_kiwibd_progs(bench_cfg); + assert(progs >= 0); + bench_sio_t erases = lfs3_kiwibd_erases(bench_cfg); + assert(erases >= 0); + bench_sio_t readed = lfs3_kiwibd_readed(bench_cfg); + assert(readed >= 0); + bench_sio_t progged = lfs3_kiwibd_progged(bench_cfg); + assert(progged >= 0); + bench_sio_t erased = lfs3_kiwibd_erased(bench_cfg); + assert(erased >= 0); + // note this can error if no timings provided + bench_sns_t simtime = lfs3_kiwibd_simtime(bench_cfg); + #endif - // print probe sample + // mark as dirty + record->flags |= BENCH_RECORD_DIRTY; + record->flags &= ~BENCH_RECORD_RESULT; + record->flags &= ~BENCH_RECORD_FRESULT; if (simtime >= 0) { - printf("benched %s %jd " - "%"PRIu64" %"PRIu64" %"PRIu64" " - "%"PRIu64" %"PRIu64" %"PRIu64" " - "%"PRIu64"\n", - probe, - n, - record->cumul_reads, - record->cumul_progs, - record->cumul_erases, - record->cumul_readed, - record->cumul_progged, - record->cumul_erased, - record->cumul_simtime); - } else { - printf("benched %s %jd " - "%"PRIu64" %"PRIu64" %"PRIu64" " - "%"PRIu64" %"PRIu64" %"PRIu64"\n", - probe, - n, - record->cumul_reads, - record->cumul_progs, - record->cumul_erases, - record->cumul_readed, - record->cumul_progged, - record->cumul_erased); + record->flags |= BENCH_RECORD_SIMTIME; } + // update n + record->n = n; + // add to cumulative measurements + record->cumul_reads += reads - record->start_reads; + record->cumul_progs += progs - record->start_progs; + record->cumul_erases += erases - record->start_erases; + record->cumul_readed += readed - record->start_readed; + record->cumul_progged += progged - record->start_progged; + record->cumul_erased += erased - record->start_erased; + record->cumul_simtime += simtime - record->start_simtime; + + // report probe sample + bench_sample(record); + + record->flags &= ~BENCH_RECORD_STARTED; + done:; BENCH_HEAP_RESUME(); BENCH_STACK_RESUME(); @@ -1072,12 +1279,26 @@ void bench_result(const char *probe, uintmax_t n, uintmax_t result) { BENCH_STACK_PAUSE(); BENCH_HEAP_PAUSE(); - // we just print these directly - printf("benched %s %jd %"PRIu64"\n", - probe, - n, - result); + // find our record + bench_record_t *record = bench_find(probe); + if (record->flags & BENCH_RECORD_IGNORED) { + goto done; + } + // mark as dirty + record->flags |= BENCH_RECORD_DIRTY; + record->flags |= BENCH_RECORD_RESULT; + record->flags &= ~BENCH_RECORD_FRESULT; + + // update n + record->n = n; + // update result + record->result = result; + + // report probe sample + bench_sample(record); + +done:; BENCH_HEAP_RESUME(); BENCH_STACK_RESUME(); } @@ -1086,27 +1307,44 @@ void bench_fresult(const char *probe, uintmax_t n, double result) { BENCH_STACK_PAUSE(); BENCH_HEAP_PAUSE(); - // we just print these directly - printf("benched %s %jd %.6f\n", - probe, - n, - result); + // find our record + bench_record_t *record = bench_find(probe); + if (record->flags & BENCH_RECORD_IGNORED) { + goto done; + } + // mark as dirty + record->flags |= BENCH_RECORD_DIRTY; + record->flags &= ~BENCH_RECORD_RESULT; + record->flags |= BENCH_RECORD_FRESULT; + + // update n + record->n = n; + // update result + record->fresult = result; + + // report probe sample + bench_sample(record); + +done:; BENCH_HEAP_RESUME(); BENCH_STACK_RESUME(); } -bench_ns_t bench_simtime(void) { + +bench_sns_t bench_simtime(void) { + // bench not started? + if (!bench_cfg) { + return LFS3_ERR_INVAL; + } + // get the current simtime - assert(bench_cfg); #ifndef BENCH_KIWIBD // note this can error if no timings provided bench_sns_t simtime = lfs3_emubd_simtime(bench_cfg); - assert(simtime >= 0); #else // note this can error if no timings provided bench_sns_t simtime = lfs3_kiwibd_simtime(bench_cfg); - assert(simtime >= 0); #endif return simtime; } @@ -1333,13 +1571,13 @@ void perm_count( } // skip this step? - if (!(bench_step >= bench_step_start - && bench_step < bench_step_stop - && (bench_step-bench_step_start) % bench_step_step == 0)) { - bench_step += 1; + if (!(bench_steps >= bench_step_start + && bench_steps < bench_step_stop + && (bench_steps-bench_step_start) % bench_step_step == 0)) { + bench_steps += 1; return; } - bench_step += 1; + bench_steps += 1; state->total += 1; @@ -2058,13 +2296,13 @@ void perm_run( } // skip this step? - if (!(bench_step >= bench_step_start - && bench_step < bench_step_stop - && (bench_step-bench_step_start) % bench_step_step == 0)) { - bench_step += 1; + if (!(bench_steps >= bench_step_start + && bench_steps < bench_step_stop + && (bench_steps-bench_step_start) % bench_step_step == 0)) { + bench_steps += 1; return; } - bench_step += 1; + bench_steps += 1; // filter? this includes ifdef (run=NULL) and if checks if (!case_->run || !(bench_force || !case_->if_ || case_->if_())) { @@ -2205,21 +2443,26 @@ enum opt_flags { OPT_LIST_CASE_PROBES = 8, OPT_DEFINE = 'D', OPT_DEFINE_DEPTH = 9, - OPT_STEP = 10, - OPT_FORCE = 11, - OPT_NO_INTERNAL = 12, - OPT_NO_LITMUS = 13, + OPT_PROBE = 'S', + OPT_PROBE_STEP = 'x', + OPT_PROBE_RUNFREQ = 10, + OPT_PROBE_SIMFREQ = 'X', + OPT_STEP = 11, + OPT_FORCE = 12, + OPT_NO_INTERNAL = 13, + OPT_NO_LITMUS = 14, OPT_DISK = 'd', OPT_TRACE = 't', - OPT_TRACE_BACKTRACE = 14, - OPT_TRACE_STEP = 15, - OPT_TRACE_RUNFREQ = 16, - OPT_READ_SLEEP = 17, - OPT_PROG_SLEEP = 18, - OPT_ERASE_SLEEP = 19, + OPT_TRACE_BACKTRACE = 15, + OPT_TRACE_STEP = 16, + OPT_TRACE_RUNFREQ = 17, + OPT_TRACE_SIMFREQ = 18, + OPT_READ_SLEEP = 19, + OPT_PROG_SLEEP = 20, + OPT_ERASE_SLEEP = 21, }; -const char *short_opts = "hYlLD:d:t:"; +const char *short_opts = "hYlLD:S:x:X:d:t:"; const struct option long_opts[] = { {"help", no_argument, NULL, OPT_HELP}, @@ -2239,6 +2482,10 @@ const struct option long_opts[] = { {"list-case-probes", no_argument, NULL, OPT_LIST_CASE_PROBES}, {"define", required_argument, NULL, OPT_DEFINE}, {"define-depth", required_argument, NULL, OPT_DEFINE_DEPTH}, + {"probe", required_argument, NULL, OPT_PROBE}, + {"probe-step", required_argument, NULL, OPT_PROBE_STEP}, + {"probe-runfreq", required_argument, NULL, OPT_PROBE_RUNFREQ}, + {"probe-simfreq", required_argument, NULL, OPT_PROBE_SIMFREQ}, {"step", required_argument, NULL, OPT_STEP}, {"force", no_argument, NULL, OPT_FORCE}, {"no-internal", no_argument, NULL, OPT_NO_INTERNAL}, @@ -2248,6 +2495,7 @@ const struct option long_opts[] = { {"trace-backtrace", no_argument, NULL, OPT_TRACE_BACKTRACE}, {"trace-step", required_argument, NULL, OPT_TRACE_STEP}, {"trace-runfreq", required_argument, NULL, OPT_TRACE_RUNFREQ}, + {"trace-simfreq", required_argument, NULL, OPT_TRACE_SIMFREQ}, {"read-sleep", required_argument, NULL, OPT_READ_SLEEP}, {"prog-sleep", required_argument, NULL, OPT_PROG_SLEEP}, {"erase-sleep", required_argument, NULL, OPT_ERASE_SLEEP}, @@ -2269,6 +2517,10 @@ const char *const help_text[] = { "List estimated probes for each bench case.", "Override a bench define.", "How deep to evaluate recursive defines before erroring.", + "Specify a probe to sample.", + "Sample probes every n steps.", + "Sample probes at this frequency in hz.", + "Sample probes at this frequency in simulated hz.", "Comma-separated range of permutations to run.", "Ignore bench filters.", "Don't run internal benches.", @@ -2278,6 +2530,7 @@ const char *const help_text[] = { "Include a backtrace with every trace statement.", "Sample trace output every n steps.", "Sample trace output at this frequency in hz.", + "Sample trace output at this frequency in simulated hz.", "Artificial read delay in seconds.", "Artificial prog delay in seconds.", "Artificial erase delay in seconds.", @@ -2286,9 +2539,6 @@ const char *const help_text[] = { int main(int argc, char **argv) { void (*op)(void) = run; - size_t bench_override_define_capacity = 0; - size_t bench_id_capacity = 0; - // parse options while (true) { int c = getopt_long(argc, argv, short_opts, long_opts, NULL); @@ -2554,6 +2804,82 @@ int main(int argc, char **argv) { } break; + case OPT_PROBE:; + // allocate space + bench_probe_t *probe = mappend( + (void**)&bench_probes, + sizeof(bench_probe_t), + &bench_probe_count, + &bench_probe_capacity); + + // parse into string key/intmax_t value, cannibalizing the + // arg in the process + probe->probe = optarg; + sep = strchr(optarg, '='); + if (sep) { + *sep = '\0'; + } + probe->step = 0; + probe->runfreq = 0.0; + probe->simfreq = 0.0; + + if (sep) { + optarg = sep+1; + + // parse sample rate + if (strstr(optarg, "rhz")) { + parsed = NULL; + probe->runfreq = strtod(optarg, &parsed); + if (parsed == optarg) { + goto invalid_probe; + } + } else if (strstr(optarg, "shz")) { + parsed = NULL; + probe->simfreq = strtod(optarg, &parsed); + if (parsed == optarg) { + goto invalid_probe; + } + } else { + parsed = NULL; + probe->step = strtoumax(optarg, &parsed, 0); + if (parsed == optarg) { + goto invalid_probe; + } + } + } + break; + + invalid_probe:; + fprintf(stderr, "error: invalid probe: %s\n", optarg); + exit(-1); + + case OPT_PROBE_STEP:; + parsed = NULL; + bench_probe_step = strtoumax(optarg, &parsed, 0); + if (parsed == optarg) { + fprintf(stderr, "error: invalid probe-step: %s\n", optarg); + exit(-1); + } + break; + + case OPT_PROBE_RUNFREQ:; + parsed = NULL; + bench_probe_runfreq = strtod(optarg, &parsed); + if (parsed == optarg) { + fprintf(stderr, "error: invalid probe-runfreq: %s\n", optarg); + exit(-1); + } + break; + + case OPT_PROBE_SIMFREQ:; + parsed = NULL; + bench_probe_simfreq = strtod(optarg, &parsed); + if (parsed == optarg) { + fprintf(stderr, "error: invalid probe-simfreq: %s\n", optarg); + exit(-1); + } + break; + case OPT_STEP:; parsed = NULL; bench_step_start = strtoumax(optarg, &parsed, 0); @@ -2642,13 +2968,22 @@ int main(int argc, char **argv) { case OPT_TRACE_RUNFREQ:; parsed = NULL; - bench_trace_runfreq = strtoumax(optarg, &parsed, 0); + bench_trace_runfreq = strtod(optarg, &parsed); if (parsed == optarg) { fprintf(stderr, "error: invalid trace-runfreq: %s\n", optarg); exit(-1); } break; + case OPT_TRACE_SIMFREQ:; + parsed = NULL; + bench_trace_simfreq = strtod(optarg, &parsed); + if (parsed == optarg) { + fprintf(stderr, "error: invalid trace-simfreq: %s\n", optarg); + exit(-1); + } + break; + case OPT_READ_SLEEP:; parsed = NULL; double read_sleep = strtod(optarg, &parsed); @@ -2670,12 +3005,14 @@ int main(int argc, char **argv) { break; case OPT_ERASE_SLEEP:; + printf("hmm [%s]\n", optarg); parsed = NULL; double erase_sleep = strtod(optarg, &parsed); if (parsed == optarg) { fprintf(stderr, "error: invalid erase-sleep: %s\n", optarg); exit(-1); } + printf("huh [%s]\n", parsed); bench_erase_sleep = erase_sleep*1.0e9; break; diff --git a/runners/bench_runner.h b/runners/bench_runner.h index 64d1368b..adb9736a 100644 --- a/runners/bench_runner.h +++ b/runners/bench_runner.h @@ -156,7 +156,7 @@ void bench_fresult(const char *probe, uintmax_t n, double result); // extra hooks to get the current simtime, pause readed/progged/erased // counters, etc -bench_ns_t bench_simtime(void); +bench_sns_t bench_simtime(void); void bench_simreset(void); void bench_simpause(void); void bench_simresume(void); @@ -185,6 +185,13 @@ void bench_permutation(size_t i, uint32_t *buffer, size_t size); #define BENCH_FACTORIAL(x) bench_factorial(x) #define BENCH_PERMUTATION(i, buffer, size) bench_permutation(i, buffer, size) +// option to pause trace output +void bench_trace_pause(void); +void bench_trace_resume(void); + +#define BENCH_TRACE_PAUSE() bench_trace_pause() +#define BENCH_TRACE_RESUME() bench_trace_resume() + #ifdef BENCH_STACK // get the maximum/current stack usage for this run extern size_t bench_stack_watermark; diff --git a/runners/test_runner.c b/runners/test_runner.c index 621e373d..b248ce94 100644 --- a/runners/test_runner.c +++ b/runners/test_runner.c @@ -176,6 +176,7 @@ ssize_t *test_suite_define_map = NULL; test_define_t *test_override_defines = NULL; size_t test_override_define_count = 0; +size_t test_override_define_capacity = 0; size_t test_define_depth = 1000; @@ -432,23 +433,25 @@ const test_id_t *test_ids = (const test_id_t[]) { {NULL, NULL, 0, {NULL, NULL, NULL, 0}}, }; size_t test_id_count = 1; +size_t test_id_capacity = 0; size_t test_step_start = 0; size_t test_step_stop = -1; size_t test_step_step = 1; -size_t test_step = 0; // incremented every permutation +size_t test_steps = 0; // incremented every permutation bool test_force = false; test_flags_t test_mask = 0; const char *test_disk_path = NULL; const char *test_trace_path = NULL; bool test_trace_backtrace = false; -uint32_t test_trace_step = 0; -uint32_t test_trace_runfreq = 0; +size_t test_trace_step = 0; +double test_trace_runfreq = 0; +uint32_t test_trace_paused = false; FILE *test_trace_file = NULL; -uint32_t test_trace_cycles = 0; -uint64_t test_trace_time = 0; -uint64_t test_trace_open_time = 0; +size_t test_trace_steps = 0; +test_ns_t test_trace_runtime = 0; +test_ns_t test_trace_open_runtime = 0; test_ns_t test_read_sleep = 0.0; test_ns_t test_prog_sleep = 0.0; test_ns_t test_erase_sleep = 0.0; @@ -469,104 +472,123 @@ void *test_trace_backtrace_buffer[ // trace printing void test_trace(const char *fmt, ...) { - if (test_trace_path) { - // sample at a specific step? - if (test_trace_step) { - if (test_trace_cycles % test_trace_step != 0) { - test_trace_cycles += 1; - goto done; - } - test_trace_cycles += 1; - } - - // sample at a specific frequency? - if (test_trace_runfreq) { - 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_runfreq) { - goto done; - } - 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) { - goto done; - } - test_trace_open_time = now; - - // try to open the trace file - int fd; - if (strcmp(test_trace_path, "-") == 0) { - fd = dup(1); - if (fd < 0) { - goto done; - } - } else { - fd = open( - test_trace_path, - O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK, - 0666); - if (fd < 0) { - goto done; - } - int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND); - assert(!err); - } - - FILE *f = fdopen(fd, "a"); - assert(f); - 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; - goto done; - } - - 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; - goto done; - } - } - } - - // flush immediately - fflush(test_trace_file); + if (!test_trace_path || test_trace_paused) { + goto done; } + // prevent accidental recursion + TEST_TRACE_PAUSE(); + + // sample at a specific step? + if (test_trace_step) { + if (test_trace_steps % test_trace_step != 0) { + test_trace_steps += 1; + goto done_; + } + test_trace_steps += 1; + } + + // sample at a specific frequency? + if (test_trace_runfreq) { + struct timespec t; + clock_gettime(CLOCK_MONOTONIC, &t); + test_ns_t now = (test_ns_t)t.tv_sec*1000*1000*1000 + + (test_ns_t)t.tv_nsec; + if (now - test_trace_runtime + < (test_ns_t)((1000.0*1000.0*1000.0) + / test_trace_runfreq)) { + goto done_; + } + test_trace_runtime = 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); + test_ns_t now = (test_ns_t)t.tv_sec*1000*1000*1000 + + (test_ns_t)t.tv_nsec; + if (now - test_trace_open_runtime < 100*1000*1000) { + goto done_; + } + test_trace_open_runtime = now; + + // try to open the trace file + int fd; + if (strcmp(test_trace_path, "-") == 0) { + fd = dup(1); + if (fd < 0) { + goto done_; + } + } else { + fd = open( + test_trace_path, + O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK, + 0666); + if (fd < 0) { + goto done_; + } + int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND); + assert(!err); + } + + FILE *f = fdopen(fd, "a"); + assert(f); + 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; + goto done_; + } + + 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; + goto done_; + } + } + } + + // flush immediately + fflush(test_trace_file); + +done_:; + TEST_TRACE_RESUME(); + done:; } +void test_trace_pause(void) { + test_trace_paused += 1; +} + +void test_trace_resume(void) { + assert(test_trace_paused); + test_trace_paused -= 1; +} + + // test prng uint32_t test_prng(uint32_t *state) { // A simple xorshift32 generator, easily reproducible. Keep in mind @@ -822,13 +844,13 @@ void perm_count( } // skip this step? - if (!(test_step >= test_step_start - && test_step < test_step_stop - && (test_step-test_step_start) % test_step_step == 0)) { - test_step += 1; + if (!(test_steps >= test_step_start + && test_steps < test_step_stop + && (test_steps-test_step_start) % test_step_step == 0)) { + test_steps += 1; return; } - test_step += 1; + test_steps += 1; state->total += 1; @@ -1868,6 +1890,7 @@ size_t test_powerloss_count = 2; #else size_t test_powerloss_count = 1; #endif +size_t test_powerloss_capacity = 0; static void list_powerlosses(void) { // at least size so that names fit @@ -1913,13 +1936,13 @@ void perm_run( } // skip this step? - if (!(test_step >= test_step_start - && test_step < test_step_stop - && (test_step-test_step_start) % test_step_step == 0)) { - test_step += 1; + if (!(test_steps >= test_step_start + && test_steps < test_step_stop + && (test_steps-test_step_start) % test_step_step == 0)) { + test_steps += 1; return; } - test_step += 1; + test_steps += 1; // set pls to 1 if running under powerloss so it useful for if predicates TEST_PLS = (powerloss->run != run_powerloss_none); @@ -2062,10 +2085,6 @@ const char *const help_text[] = { int main(int argc, char **argv) { void (*op)(void) = run; - size_t test_override_define_capacity = 0; - size_t test_powerloss_capacity = 0; - size_t test_id_capacity = 0; - // parse options while (true) { int c = getopt_long(argc, argv, short_opts, long_opts, NULL); @@ -2582,7 +2601,7 @@ int main(int argc, char **argv) { case OPT_TRACE_RUNFREQ:; parsed = NULL; - test_trace_runfreq = strtoumax(optarg, &parsed, 0); + test_trace_runfreq = strtod(optarg, &parsed); if (parsed == optarg) { fprintf(stderr, "error: invalid trace-runfreq: %s\n", optarg); exit(-1); diff --git a/runners/test_runner.h b/runners/test_runner.h index 13cbac86..7b86a588 100644 --- a/runners/test_runner.h +++ b/runners/test_runner.h @@ -153,6 +153,13 @@ void test_permutation(size_t i, uint32_t *buffer, size_t size); #define TEST_FACTORIAL(x) test_factorial(x) #define TEST_PERMUTATION(i, buffer, size) test_permutation(i, buffer, size) +// option to pause trace output +void test_trace_pause(void); +void test_trace_resume(void); + +#define TEST_TRACE_PAUSE() test_trace_pause() +#define TEST_TRACE_RESUME() test_trace_resume() + // declare implicit defines as global intmax_ts #define TEST_DEFINE(k, v) \ diff --git a/scripts/bench.py b/scripts/bench.py index c982025d..ac121c10 100755 --- a/scripts/bench.py +++ b/scripts/bench.py @@ -822,6 +822,15 @@ def find_runner(runner, id=None, main=True, **args): # other context if args.get('define_depth'): cmd.append('--define-depth=%s' % args['define_depth']) + if args.get('probe'): + for probe in args['probe']: + cmd.append('-S%s' % probe) + if args.get('probe_step'): + cmd.append('-x%s' % args['probe_step']) + if args.get('probe_runfreq'): + cmd.append('--probe-runfreq=%s' % args['probe_runfreq']) + if args.get('probe_simfreq'): + cmd.append('-X%s' % args['probe_simfreq']) if args.get('force'): cmd.append('--force') if args.get('no_internal'): @@ -1203,7 +1212,7 @@ def run_stage(name, runner, bench_ids, stdout_, trace_, output_, **args): last_defines = None # fetched on demand last_stdout = co.deque(maxlen=args.get('context', 5) + 1) last_assert = None - last_time = time.time() + last_runtime = time.time() try: while True: # parse a line for state changes @@ -1234,7 +1243,7 @@ def run_stage(name, runner, bench_ids, stdout_, trace_, output_, **args): last_defines = None last_stdout.clear() last_assert = None - last_time = time.time() + last_runtime = time.time() elif op == 'finished': # force a failure if args.get('fail'): @@ -1296,7 +1305,7 @@ def run_stage(name, runner, bench_ids, stdout_, trace_, output_, **args): 'bench_erased': erased_, 'bench_simtime': simtime_, 'bench_runtime': '%.6f' % ( - time.time() - last_time)}) + time.time() - last_runtime)}) # keep track of total for summary readed += readed_ progged += progged_ @@ -1758,6 +1767,19 @@ if __name__ == "__main__": bench_parser.add_argument( '--define-depth', help="How deep to evaluate recursive defines before erroring.") + bench_parser.add_argument( + '-S', '--probe', + action='append', + help="Specify a probe to sample.") + bench_parser.add_argument( + '-x', '--probe-step', + help="Sample probes every n steps.") + bench_parser.add_argument( + '--probe-runfreq', + help="Sample probes at this frequency in hz.") + bench_parser.add_argument( + '-X', '--probe-simfreq', + help="Sample probes at this frequency in simulated hz.") bench_parser.add_argument( '--force', action='store_true', @@ -1786,6 +1808,9 @@ if __name__ == "__main__": bench_parser.add_argument( '--trace-runfreq', help="Sample trace output at this frequency in hz.") + bench_parser.add_argument( + '--trace-simfreq', + help="Sample trace output at this frequency in simulated hz.") bench_parser.add_argument( '-O', '--stdout', help="Direct stdout to this file. Note stderr is already merged " diff --git a/scripts/test.py b/scripts/test.py index b5d4f4ce..ecdd4edf 100755 --- a/scripts/test.py +++ b/scripts/test.py @@ -1179,7 +1179,7 @@ def run_stage(name, runner, test_ids, stdout_, trace_, output_, **args): last_id = None last_stdout = co.deque(maxlen=args.get('context', 5) + 1) last_assert = None - last_time = time.time() + last_runtime = time.time() try: while True: # parse a line for state changes @@ -1207,7 +1207,7 @@ def run_stage(name, runner, test_ids, stdout_, trace_, output_, **args): last_id = m.group('id') last_stdout.clear() last_assert = None - last_time = time.time() + last_runtime = time.time() elif op == 'powerloss': last_id = m.group('id') powerlosses += 1 @@ -1232,7 +1232,7 @@ def run_stage(name, runner, test_ids, stdout_, trace_, output_, **args): **defines, 'test_passed': '1/1', 'test_runtime': '%.6f' % ( - time.time() - last_time)}) + time.time() - last_runtime)}) elif op == 'skipped': locals.seen_perms += 1 elif op == 'assert':