include wait_time in metrics

This commit is contained in:
folkert van heusden 2024-04-08 01:08:46 +02:00
parent 276a149d8e
commit f3522adb9b
Signed by untrusted user who does not match committer: folkert
GPG key ID: 6B6455EDFEED3BD1
4 changed files with 25 additions and 18 deletions

17
cpu.cpp
View file

@ -40,7 +40,7 @@ void cpu::emulation_start()
{
instruction_count = 0;
running_since = get_ms();
running_since = get_us();
wait_time = 0;
}
@ -64,7 +64,7 @@ std::set<uint16_t> cpu::list_breakpoints()
return breakpoints;
}
uint64_t cpu::get_instructions_executed_count()
uint64_t cpu::get_instructions_executed_count() const
{
// this may wreck havoc as it is not protected by a mutex
// but a mutex would slow things down too much (as would
@ -72,21 +72,21 @@ uint64_t cpu::get_instructions_executed_count()
return instruction_count;
}
std::tuple<double, double, uint64_t, uint32_t, double> cpu::get_mips_rel_speed(const std::optional<uint64_t> instruction_count, const bool t_diff_1s)
std::tuple<double, double, uint64_t, uint32_t, double> cpu::get_mips_rel_speed(const std::optional<uint64_t> & instruction_count, const std::optional<uint64_t> & t_diff_in) const
{
uint64_t instr_count = instruction_count.has_value() ? instruction_count.value() : get_instructions_executed_count();
uint32_t t_diff = t_diff_1s ? 1000 : (get_ms() - running_since - (wait_time / 1000));
uint64_t t_diff = t_diff_in.has_value() ? t_diff_in.value() : (get_us() - running_since - wait_time);
double mips = instr_count / (1000.0 * t_diff);
double mips = instr_count / double(t_diff);
// see https://retrocomputing.stackexchange.com/questions/6960/what-was-the-clock-speed-and-ips-for-the-original-pdp-11
constexpr double pdp11_clock_cycle = 150; // ns, for the 11/70
constexpr double pdp11_mhz = 1000.0 / pdp11_clock_cycle;
constexpr double pdp11_MHz = 1000.0 / pdp11_clock_cycle;
constexpr double pdp11_avg_cycles_per_instruction = (1 + 5) / 2.0;
constexpr double pdp11_estimated_mips = pdp11_mhz / pdp11_avg_cycles_per_instruction;
constexpr double pdp11_estimated_mips = pdp11_MHz / pdp11_avg_cycles_per_instruction;
return { mips, mips * 100 / pdp11_estimated_mips, instr_count, t_diff, wait_time / 1000. };
return { mips, mips * 100 / pdp11_estimated_mips, instr_count, t_diff, wait_time };
}
void cpu::reset()
@ -1317,7 +1317,6 @@ bool cpu::single_operand_instructions(const uint16_t instr)
if (dst_mode == 0)
setRegister(dst_reg, v, rm_prev);
else {
int prev_run_mode = getPSW_prev_runmode();
auto a = getGAMAddress(dst_mode, dst_reg, wm_word);
b->mmudebug(a.addr.value());

5
cpu.h
View file

@ -101,8 +101,9 @@ public:
bus *getBus() { return b; }
void emulation_start();
uint64_t get_instructions_executed_count();
std::tuple<double, double, uint64_t, uint32_t, double> get_mips_rel_speed(const std::optional<uint64_t> instruction_count, const bool t_diff_1s);
uint64_t get_instructions_executed_count() const;
uint64_t get_wait_time() const { return wait_time; }
std::tuple<double, double, uint64_t, uint32_t, double> get_mips_rel_speed(const std::optional<uint64_t> & instruction_count, const std::optional<uint64_t> & t_diff_1s) const;
void reset();

View file

@ -213,7 +213,7 @@ void show_run_statistics(console *const cnsl, cpu *const c)
{
auto stats = c->get_mips_rel_speed({ }, false);
cnsl->put_string_lf(format("Executed %zu instructions in %u ms of which %.2f ms idle", size_t(std::get<2>(stats)), std::get<3>(stats), std::get<4>(stats)));
cnsl->put_string_lf(format("Executed %zu instructions in %.2f ms of which %.2f ms idle", size_t(std::get<2>(stats)), std::get<3>(stats) / 1000., std::get<4>(stats) / 1000.));
cnsl->put_string_lf(format("MIPS: %.2f, relative speed: %.2f%%", std::get<0>(stats), std::get<1>(stats)));
}

View file

@ -231,25 +231,32 @@ int run_cpu_validation(const std::string & filename)
void get_metrics(cpu *const c)
{
uint64_t previous_instruction_count = c->get_instructions_executed_count();
uint64_t previous_ts = get_us();
uint64_t previous_idle_time = c->get_wait_time();
while(event != EVENT_TERMINATE) {
sleep(1);
uint64_t ts = get_us();
uint64_t idle_time = c->get_wait_time();
uint64_t current_instruction_count = c->get_instructions_executed_count();
auto stats = c->get_mips_rel_speed(current_instruction_count - previous_instruction_count, true);
uint64_t current_idle_duration = idle_time - previous_idle_time;
auto stats = c->get_mips_rel_speed(current_instruction_count - previous_instruction_count, ts - previous_ts - current_idle_duration);
FILE *fh = fopen("kek-metrics.csv", "a+");
if (fh) {
fseek(fh, 0, SEEK_END);
if (ftell(fh) == 0)
fprintf(fh, "timestamp,MIPS,relative speed in %%,instructions executed count\n");
fprintf(fh, "%.06f, %.2f, %.2f%%, %" PRIu64 "\n", ts / 1000., std::get<0>(stats), std::get<1>(stats), std::get<2>(stats));
fprintf(fh, "timestamp,MIPS,relative speed in %%,instructions executed count,idle time\n");
fprintf(fh, "%.06f, %.2f, %.2f%%, %" PRIu64 ", %.3f\n", ts / 1000., std::get<0>(stats), std::get<1>(stats), std::get<2>(stats), current_idle_duration / 1000000.);
fclose(fh);
}
previous_idle_time = idle_time;
previous_instruction_count = current_instruction_count;
previous_ts = ts;
}
}
@ -545,7 +552,7 @@ int main(int argc, char *argv[])
}
auto stats = c->get_mips_rel_speed({ }, false);
cnsl->put_string_lf(format("MIPS: %.2f, relative speed: %.2f%%, instructions executed: %lu", std::get<0>(stats), std::get<1>(stats), std::get<2>(stats)));
cnsl->put_string_lf(format("MIPS: %.2f, relative speed: %.2f%%, instructions executed: %" PRIu64 " in %.2f seconds", std::get<0>(stats), std::get<1>(stats), std::get<2>(stats), std::get<3>(stats) / 1000000.));
}
event = EVENT_TERMINATE;