Github/littlefs
1
Fork 0
Code Actions Activity

runners: bench: Added flags to control reading from bench probes

Browse Source 
- -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.
This commit is contained in:
Christopher Haster
2026-02-09 13:43:55 -06:00
parent 81d681cab2
commit 4af4cf3212
8 changed files with 773 additions and 378 deletions
Download Patch File Download Diff File Expand all files Collapse all files
benches/bench_rt.toml
+7 -7
View File
@@ -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;
}
}
benches/bench_wt.toml
+5 -5
View File
@@ -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;
}
}
runners/bench_runner.c
+511 -174
View File
@@ -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,27 +460,50 @@ 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;
if (!bench_trace_path || bench_trace_paused) {
goto done;
}
bench_trace_cycles += 1;
// 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);
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_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_time = now;
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) {
@@ -484,19 +512,19 @@ void bench_trace(const char *fmt, ...) {
// 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_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_time = now;
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;
goto done_;
}
} else {
fd = open(
@@ -504,7 +532,7 @@ void bench_trace(const char *fmt, ...) {
O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK,
0666);
if (fd < 0) {
goto done;
goto done_;
}
int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND);
assert(!err);
@@ -526,7 +554,7 @@ void bench_trace(const char *fmt, ...) {
if (res < 0) {
fclose(bench_trace_file);
bench_trace_file = NULL;
goto done;
goto done_;
}
if (bench_trace_backtrace) {
@@ -541,20 +569,31 @@ void bench_trace(const char *fmt, ...) {
if (res < 0) {
fclose(bench_trace_file);
bench_trace_file = NULL;
goto done;
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;
runners/bench_runner.h
+8 -1
View File
@@ -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;
runners/test_runner.c
+62 -43
View File
@@ -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,27 +472,34 @@ 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;
if (!test_trace_path || test_trace_paused) {
goto done;
}
test_trace_cycles += 1;
// 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);
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_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_time = now;
test_trace_runtime = now;
}
if (!test_trace_file) {
@@ -498,19 +508,19 @@ void test_trace(const char *fmt, ...) {
// 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_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_time = now;
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;
goto done_;
}
} else {
fd = open(
@@ -518,7 +528,7 @@ void test_trace(const char *fmt, ...) {
O_WRONLY | O_CREAT | O_APPEND | O_NONBLOCK,
0666);
if (fd < 0) {
goto done;
goto done_;
}
int err = fcntl(fd, F_SETFL, O_WRONLY | O_CREAT | O_APPEND);
assert(!err);
@@ -540,7 +550,7 @@ void test_trace(const char *fmt, ...) {
if (res < 0) {
fclose(test_trace_file);
test_trace_file = NULL;
goto done;
goto done_;
}
if (test_trace_backtrace) {
@@ -555,18 +565,30 @@ void test_trace(const char *fmt, ...) {
if (res < 0) {
fclose(test_trace_file);
test_trace_file = NULL;
goto done;
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);
runners/test_runner.h
+7
View File
@@ -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) \
scripts/bench.py
+28 -3
View File
@@ -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 "
scripts/test.py
+3 -3
View File
@@ -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':