Add instruction counters to CPU profiler

Keeps track of instructions (including operands) that are executed,
to see if there are any hotspots that could be optimized or fastpaths
that should be added.

Also adds a mode where CPU profiler data is periodically output, to
make it easier to get at these instruction counts during startup.

cpu/ppc/ppcexec.cpp

@@ -23,6 +23,7 @@ along with this program.  If not, see <https://www.gnu.org/licenses/>.
 #include <loguru.hpp>
 #include "ppcemu.h"
 #include "ppcmmu.h"
+#include "ppcdisasm.h"
 
 #include <algorithm>
 #include <cstring>
@@ -109,6 +110,9 @@ uint64_t num_supervisor_instrs;
 uint64_t num_int_loads;
 uint64_t num_int_stores;
 uint64_t exceptions_processed;
+#ifdef CPU_PROFILING_OPS
+std::unordered_map<uint32_t, uint64_t> num_opcodes;
+#endif
 
 #include "utils/profiler.h"
 #include <memory>
@@ -139,6 +143,30 @@ public:
         vars.push_back({.name = "Exceptions processed",
                         .format = ProfileVarFmt::DEC,
                         .value = exceptions_processed});
+
+        // Generate top N op counts with readable names.
+#ifdef CPU_PROFILING_OPS
+        PPCDisasmContext ctx;
+        ctx.instr_addr = 0;
+        ctx.simplified = false;
+        std::vector<std::pair<std::string, uint64_t>> op_name_counts;
+        for (const auto& pair : num_opcodes) {
+            ctx.instr_code = pair.first;
+            auto op_name = disassemble_single(&ctx);
+            op_name_counts.emplace_back(op_name, pair.second);
+        }
+        size_t top_ops_size = std::min(op_name_counts.size(), size_t(20));
+        std::partial_sort(op_name_counts.begin(), op_name_counts.begin() + top_ops_size, op_name_counts.end(), [](const auto& a, const auto& b) {
+            return b.second < a.second;
+        });
+        op_name_counts.resize(top_ops_size);
+        for (const auto& pair : op_name_counts) {
+            vars.push_back({.name = "Instruction " + pair.first,
+                            .format = ProfileVarFmt::COUNT,
+                            .value = pair.second,
+                            .count_total = num_executed_instrs});
+        }
+#endif
     };
 
     void reset() {
@@ -147,6 +175,9 @@ public:
         num_int_loads = 0;
         num_int_stores = 0;
         exceptions_processed = 0;
+#ifdef CPU_PROFILING_OPS
+        num_opcodes.clear();
+#endif
     };
 };
 
@@ -289,6 +320,9 @@ void ppc_main_opcode()
 {
 #ifdef CPU_PROFILING
     num_executed_instrs++;
+#if defined(CPU_PROFILING_OPS)
+    num_opcodes[ppc_cur_instruction]++;
+#endif
 #endif
     OpcodeGrabber[(ppc_cur_instruction >> 26) & 0x3F]();
 }

main.cpp

@@ -62,7 +62,7 @@ static string appDescription = string(
     "\n"
 );
 
-void run_machine(std::string machine_str, std::string bootrom_path, uint32_t execution_mode);
+void run_machine(std::string machine_str, std::string bootrom_path, uint32_t execution_mode, uint32_t profiling_interval_ms);
 
 int main(int argc, char** argv) {
 
@@ -85,6 +85,12 @@ int main(int argc, char** argv) {
     app.add_option("-b,--bootrom", bootrom_path, "Specifies BootROM path")
         ->check(CLI::ExistingFile);
 
+    uint32_t profiling_interval_ms = 0;
+#ifdef CPU_PROFILING
+    app.add_option("--profiling-interval-ms", profiling_interval_ms,
+        "Specifies periodic interval (in ms) at which to output CPU profiling information");
+#endif
+
     CLI::Option* machine_opt = app.add_option("-m,--machine",
         machine_str, "Specify machine ID");
 
@@ -188,7 +194,7 @@ int main(int argc, char** argv) {
     signal(SIGABRT, sigabrt_handler);
 
     while (true) {
-        run_machine(machine_str, bootrom_path, execution_mode);
+        run_machine(machine_str, bootrom_path, execution_mode, profiling_interval_ms);
         if (power_off_reason == po_restarting) {
             LOG_F(INFO, "Restarting...");
             power_on = true;
@@ -202,7 +208,7 @@ int main(int argc, char** argv) {
     return 0;
 }
 
-void run_machine(std::string machine_str, std::string bootrom_path, uint32_t execution_mode) {
+void run_machine(std::string machine_str, std::string bootrom_path, uint32_t execution_mode, uint32_t profiling_interval_ms) {
     if (MachineFactory::create_machine_for_id(machine_str, bootrom_path) < 0) {
         return;
     }
@@ -213,6 +219,15 @@ void run_machine(std::string machine_str, std::string bootrom_path, uint32_t exe
         EventManager::get_instance()->poll_events();
     });
 
+#ifdef CPU_PROFILING
+    uint32_t profiling_timer;
+    if (profiling_interval_ms > 0) {
+        profiling_timer = TimerManager::get_instance()->add_cyclic_timer(MSECS_TO_NSECS(profiling_interval_ms), [] {
+            gProfilerObj->print_profile("PPC_CPU");
+        });
+    }
+#endif
+
     switch (execution_mode) {
     case interpreter:
         power_off_reason = po_starting_up;
@@ -229,6 +244,11 @@ void run_machine(std::string machine_str, std::string bootrom_path, uint32_t exe
 
     LOG_F(INFO, "Cleaning up...");
     TimerManager::get_instance()->cancel_timer(event_timer);
+#ifdef CPU_PROFILING
+    if (profiling_interval_ms > 0) {
+        TimerManager::get_instance()->cancel_timer(profiling_timer);
+    }
+#endif
     EventManager::get_instance()->disconnect_handlers();
     delete gMachineObj.release();
 }

utils/profiler.cpp

@@ -20,6 +20,7 @@ along with this program.  If not, see <https://www.gnu.org/licenses/>.
 */
 
 #include "profiler.h"
+#include <iomanip>
 #include <iostream>
 #include <vector>
 
@@ -50,6 +51,11 @@ void Profiler::print_profile(std::string name)
         return;
     }
 
+    // Set a locale so we get thousands separators when outputting numbers.
+    // Would be nice if we could use the default locale, but that does not
+    // appear to work.
+    std::cout.imbue(std::locale("en_US.UTF-8"));
+
     std::cout << std::endl;
     std::cout << "Summary of the profile '" << name << "':" << std::endl;
     std::cout << "------------------------------------------" << std::endl;
@@ -61,13 +67,24 @@ void Profiler::print_profile(std::string name)
     // ask the corresponding profile class to fill its variables for us
     prof_it->second->populate_variables(vars);
 
+    int name_width = 10;
     for (auto& var : vars) {
+        name_width = std::max(name_width, int(var.name.length()));
+    }
+
+    for (auto& var : vars) {
+        std::cout << std::left << std::setw(name_width) << var.name << " : ";
         switch(var.format) {
         case ProfileVarFmt::DEC:
-            std::cout << var.name << " : " << var.value << std::endl;
+            std::cout << var.value << std::endl;
             break;
         case ProfileVarFmt::HEX:
-            std::cout << var.name << " : " << std::hex << var.value << std::endl;
+            std::cout << std::hex << var.value << std::endl;
+            break;
+        case ProfileVarFmt::COUNT:
+            std::cout << var.value << std::fixed << std::setprecision(2) << " ("
+                      << (double(var.value) / double(var.count_total) * 100)
+                      << "%)" << std::endl;
             break;
         default:
             std::cout << "Unknown value in variable " << var.name << std::endl;

utils/profiler.h

@@ -31,13 +31,14 @@ along with this program.  If not, see <https://www.gnu.org/licenses/>.
 #include <string>
 #include <vector>
 
-enum class ProfileVarFmt { DEC, HEX };
+enum class ProfileVarFmt { DEC, HEX, COUNT };
 
 /** Define a special data type for profile variables. */
 typedef struct ProfileVar {
     std::string     name;
     ProfileVarFmt   format;
     uint64_t        value;
+    uint64_t        count_total;
 } ProfileVar;
 
 /** Base class for user-defined profiles. */