Add timeline style profiler (#1312)

* small speedups to extractor

* faster extraction

* add profiler

* spellin

* guess at windows includes

* windows nominmax garbage

common/CMakeLists.txt

@@ -6,7 +6,7 @@ add_library(common
         dma/dma.cpp
         dma/dma_copy.cpp
         dma/gs.cpp
-
+        global_profiler/GlobalProfiler.cpp
         goos/Interpreter.cpp
         goos/Object.cpp
         goos/ParseHelpers.cpp

common/global_profiler/GlobalProfiler.cpp

@@ -0,0 +1,181 @@
+#include "GlobalProfiler.h"
+
+#include <thread>
+#include <cstring>
+#include <chrono>
+#include "third-party/fmt/core.h"
+#include "third-party/json.hpp"
+#include "common/util/Assert.h"
+#include "common/util/FileUtil.h"
+
+#ifdef __linux__
+u32 get_current_tid() {
+  return (u32)pthread_self();
+}
+#else
+#define NOMINMAX
+#include <windows.h>
+#include "Processthreadsapi.h"
+u32 get_current_tid() {
+  return (u32)GetCurrentThreadId();
+}
+#endif
+
+u64 get_current_ts() {
+  return std::chrono::steady_clock::now().time_since_epoch().count();
+}
+
+GlobalProfiler::GlobalProfiler() {
+  m_t0 = get_current_ts();
+  set_max_events(65536);
+}
+
+void GlobalProfiler::set_max_events(size_t event_count) {
+  ASSERT(!m_enabled);
+  m_nodes.resize(event_count);
+}
+
+void GlobalProfiler::event(const char* name, ProfNode::Kind kind) {
+  if (!m_enabled) {
+    return;
+  }
+  size_t my_idx = (m_next_idx++ % m_nodes.size());
+  auto& node = m_nodes[my_idx];
+  node.ts = get_current_ts() - m_t0;
+  node.tid = get_current_tid();
+  node.kind = kind;
+  strncpy(node.name, name, sizeof(node.name));
+  node.name[sizeof(node.name) - 1] = '\0';
+}
+
+void GlobalProfiler::instant_event(const char* name) {
+  event(name, ProfNode::INSTANT);
+}
+
+void GlobalProfiler::begin_event(const char* name) {
+  event(name, ProfNode::BEGIN);
+}
+
+void GlobalProfiler::end_event() {
+  if (!m_enabled) {
+    return;
+  }
+  size_t my_idx = (m_next_idx++ % m_nodes.size());
+  auto& node = m_nodes[my_idx];
+  node.ts = get_current_ts() - m_t0;
+  node.tid = get_current_tid();
+  node.kind = ProfNode::END;
+  node.name[0] = '\0';
+}
+
+void GlobalProfiler::clear() {
+  m_next_idx = 0;
+}
+
+void GlobalProfiler::set_enable(bool en) {
+  m_enabled = en;
+}
+
+void GlobalProfiler::dump_to_json(const std::string& path) {
+  ASSERT(!m_enabled);
+
+  nlohmann::json json;
+  auto& trace_events = json["traceEvents"];
+  json["displayTimeUnit"] = "ms";
+
+  u64 lowest_ts = UINT64_MAX;
+  struct ThreadInfo {
+    size_t lowest_at_target = UINT64_MAX;
+    size_t highest_at_target = 0;
+    size_t debug = 0;
+    u32 short_id = 0;
+  };
+  std::unordered_map<u32, ThreadInfo> info_per_thread;
+
+  // first, find all the threads
+  std::string kRootName = "ROOT";
+  for (size_t offset = m_nodes.size(); offset-- > 0;) {
+    size_t idx = (m_next_idx + offset) % m_nodes.size();
+    const auto& event = m_nodes[idx];
+
+    if (event.kind != ProfNode::UNUSED) {
+      lowest_ts = std::min(event.ts, lowest_ts);
+    }
+    if (event.kind == ProfNode::INSTANT && kRootName == event.name) {
+      auto& info = info_per_thread[event.tid];
+      info.lowest_at_target = std::min(info.lowest_at_target, offset);
+      info.highest_at_target = std::max(info.highest_at_target, offset);
+    }
+  }
+
+  u32 i = 0;
+  for (auto& info : info_per_thread) {
+    info.second.short_id = i++;
+  }
+
+  for (size_t event_idx = 0; event_idx < m_nodes.size(); event_idx++) {
+    auto& event = m_nodes[(event_idx + m_next_idx) % m_nodes.size()];
+    if (event.kind == ProfNode::UNUSED) {
+      continue;
+    }
+    auto& info = info_per_thread.at(event.tid);
+    if (event_idx < info.lowest_at_target || event_idx > info.highest_at_target) {
+      continue;
+    }
+
+    auto& json_event = trace_events.emplace_back();
+    // name
+    if (event.kind != ProfNode::END) {
+      json_event["name"] = event.name;
+    }
+
+    // cat
+    // json_event["cat"] = "a";  // ??
+    // ph BEi
+    switch (event.kind) {
+      case ProfNode::END:
+        json_event["ph"] = "E";
+        break;
+      case ProfNode::BEGIN:
+        json_event["ph"] = "B";
+        break;
+      case ProfNode::INSTANT:
+        json_event["ph"] = "i";
+        break;
+      default:
+        ASSERT(false);
+    }
+    // pid
+    json_event["pid"] = 1;
+    // tid
+    json_event["tid"] = info.short_id;
+    // ts
+    json_event["ts"] = (event.ts - lowest_ts) / 1000.f;
+    if (event.ts < info.debug) {
+      fmt::print("out of order: {} {} {} ms\n", event.ts / 1000.f, info.debug / 1000.f,
+                 (info.debug - event.ts) / 1000000.f);
+      fmt::print("  idx: {}, range {} {}\n", event_idx, info.lowest_at_target,
+                 info.highest_at_target);
+      fmt::print("  now: {}\n", m_next_idx);
+    }
+    info.debug = event.ts;
+  }
+
+  for (auto& t : info_per_thread) {
+    fmt::print("thread: {}: {} -> {}\n", t.first, t.second.lowest_at_target,
+               t.second.highest_at_target);
+  }
+
+  file_util::write_text_file(path, json.dump());
+}
+
+GlobalProfiler gprof;
+GlobalProfiler& prof() {
+  return gprof;
+}
+
+ScopedEvent scoped_prof(const char* name) {
+  auto& p = prof();
+  p.begin_event(name);
+  return {&p};
+}

common/global_profiler/GlobalProfiler.h

@@ -0,0 +1,46 @@
+#pragma once
+
+#include "common/common_types.h"
+#include <vector>
+#include <string>
+#include <atomic>
+
+struct ProfNode {
+  u64 ts;
+  char name[32];
+  enum Kind : u8 { BEGIN, END, INSTANT, UNUSED } kind = UNUSED;
+  u32 tid;
+};
+
+class GlobalProfiler {
+ public:
+  GlobalProfiler();
+  void set_max_events(size_t event_count);
+  void instant_event(const char* name);
+  void begin_event(const char* name);
+  void event(const char* name, ProfNode::Kind kind);
+  void end_event();
+  void clear();
+  void set_enable(bool en);
+  void dump_to_json(const std::string& path);
+
+ private:
+  std::atomic_bool m_enabled = false;
+  u64 m_t0 = 0;
+  std::atomic_size_t m_next_idx = 0;
+  std::vector<ProfNode> m_nodes;
+};
+
+struct ScopedEvent {
+  ScopedEvent(const ScopedEvent&) = delete;
+  ScopedEvent& operator=(const ScopedEvent&) = delete;
+  GlobalProfiler* prof = nullptr;
+  ~ScopedEvent() {
+    if (prof) {
+      prof->end_event();
+    }
+  }
+};
+
+GlobalProfiler& prof();
+ScopedEvent scoped_prof(const char* name);

common/global_profiler/readme.md

@@ -0,0 +1,32 @@
+# Event Profiler
+The event profiler is a tool to analyze timing of multiple frames.  Unlike sampling-based profilers, this profile captures an exact timeline of what happens of what happens when.
+
+## Capturing a profile
+In the OpenGOAL window, click "Profiler" and check "Record" to start recording. The buffer has a fixed maximum size and it will automatically overwrite old data once it is full.
+
+When something interesting happens, click the "dump to file" button to save the buffer (currently a few seconds) to `prof.json` in `jak-project`.
+
+The idea is that you can leave this running as you play, and then when the game stutters or does something interesting, you can click the dump button and get the result.
+
+## Viewing a profile
+Open Google Chrome and go to `chrome://tracing`. Then click load and open the json file.  Or, just drag and drop the file into chrome.
+
+Press `1` for a box drawing tool. This lets you select a region of the flame chart and get a list of events inside the box.
+
+Press `2` for panning.
+
+Press `3` for zooming.
+
+## Adding an event
+The GOAL kernel automatically adds events for each process. If you want to add another event, you can use `(with-profiler "name-of-event" <body>)`. Do not call `suspend` or do a `return` inside of this. If you need more control over stopping/starting, there are functions in `gcommon.gc` to explicitly start/stop events. But you must match them up correctly yourself!
+
+In C++, the graphics profiler automatically adds a profiler nodes as events. To add an event, you can use 
+
+```auto p = scoped_prof("name-of-event");``` 
+
+The event is active from this call until the destruction of `p`.
+
+## Multiple threads
+The event profiler currently works on both the graphics and EE threads. Adding the events can safely be done from any thread, but enable/disable/dump should be done from a single thread at a time.
+
+Each thread should periodically insert a `ROOT` instant event when there are no active range events. This is required to make the retroactive dump feature work properly as the event buffer does not capture the tree structure fully, and it must be able to find a point in time when no events are active.

game/graphics/opengl_renderer/Profiler.h

@@ -6,6 +6,7 @@
 
 #include "common/common_types.h"
 #include "common/util/Timer.h"
+#include "common/global_profiler/GlobalProfiler.h"
 
 #include "game/graphics/opengl_renderer/buckets.h"
 
@@ -53,7 +54,8 @@ class ProfilerNode {
 
 class ScopedProfilerNode {
  public:
-  ScopedProfilerNode(ProfilerNode* node) : m_node(node) {}
+  ScopedProfilerNode(ProfilerNode* node)
+      : m_node(node), m_global_event(scoped_prof(node->name().c_str())) {}
   ScopedProfilerNode(const ScopedProfilerNode& other) = delete;
   ScopedProfilerNode& operator=(const ScopedProfilerNode& other) = delete;
   ProfilerNode* make_child(const std::string& name) { return m_node->make_child(name); }
@@ -68,6 +70,7 @@ class ScopedProfilerNode {
 
  private:
   ProfilerNode* m_node;
+  ScopedEvent m_global_event;
 };
 
 class Profiler {

game/graphics/opengl_renderer/debug_gui.cpp

@@ -116,6 +116,12 @@ void OpenGlDebugGui::draw(const DmaStats& dma_stats) {
       ImGui::Checkbox("Sleep in Frame Limiter", &sleep_in_frame_limiter);
       ImGui::EndMenu();
     }
+
+    if (ImGui::BeginMenu("Event Profiler")) {
+      ImGui::Checkbox("Record", &record_events);
+      ImGui::MenuItem("Dump to file", nullptr, &dump_events);
+      ImGui::EndMenu();
+    }
   }
   ImGui::EndMainMenuBar();
 

game/graphics/opengl_renderer/debug_gui.h

@@ -64,6 +64,8 @@ class OpenGlDebugGui {
   bool experimental_accurate_lag = false;
   bool sleep_in_frame_limiter = true;
   bool small_profiler = false;
+  bool record_events = false;
+  bool dump_events = false;
 
  private:
   FrameTimeRecorder m_frame_timer;

game/graphics/pipelines/opengl.cpp

@@ -28,6 +28,7 @@
 #include "common/util/FileUtil.h"
 #include "common/util/compress.h"
 #include "common/util/FrameLimiter.h"
+#include "common/global_profiler/GlobalProfiler.h"
 
 namespace {
 
@@ -222,6 +223,7 @@ void render_game_frame(int width, int height, int lbox_width, int lbox_height) {
   // wait for a copied chain.
   bool got_chain = false;
   {
+    auto p = scoped_prof("wait-for-dma");
     std::unique_lock<std::mutex> lock(g_gfx_data->dma_mutex);
     // note: there's a timeout here. If the engine is messed up and not sending us frames,
     // we still want to run the glfw loop.
@@ -248,6 +250,7 @@ void render_game_frame(int width, int height, int lbox_width, int lbox_height) {
       auto& chain = g_gfx_data->dma_copier.get_last_result();
       g_gfx_data->ogl_renderer.render(DmaFollower(chain.data.data(), chain.start_offset), options);
     } else {
+      auto p = scoped_prof("ogl-render");
       g_gfx_data->ogl_renderer.render(DmaFollower(g_gfx_data->dma_copier.get_last_input_data(),
                                                   g_gfx_data->dma_copier.get_last_input_offset()),
                                       options);
@@ -351,18 +354,36 @@ static void gl_screen_size(GfxDisplay* display,
   }
 }
 
+void update_global_profiler() {
+  if (g_gfx_data->debug_gui.dump_events) {
+    prof().set_enable(false);
+    g_gfx_data->debug_gui.dump_events = false;
+    prof().dump_to_json((file_util::get_jak_project_dir() / "prof.json").string());
+  }
+  prof().set_enable(g_gfx_data->debug_gui.record_events);
+}
+
+/*!
+ * Main function called to render graphics frames. This is called in a loop.
+ */
 static void gl_render_display(GfxDisplay* display) {
   GLFWwindow* window = display->window_glfw;
 
   // poll events
-  glfwPollEvents();
-  glfwMakeContextCurrent(window);
-  Pad::update_gamepads();
+  {
+    auto p = scoped_prof("poll-gamepads");
+    glfwPollEvents();
+    glfwMakeContextCurrent(window);
+    Pad::update_gamepads();
+  }
 
   // imgui start of frame
-  ImGui_ImplOpenGL3_NewFrame();
-  ImGui_ImplGlfw_NewFrame();
-  ImGui::NewFrame();
+  {
+    auto p = scoped_prof("imgui-init");
+    ImGui_ImplOpenGL3_NewFrame();
+    ImGui_ImplGlfw_NewFrame();
+    ImGui::NewFrame();
+  }
 
   // window size
   int width = Gfx::g_global_settings.lbox_w;
@@ -388,17 +409,25 @@ static void gl_render_display(GfxDisplay* display) {
 
   // render game!
   if (g_gfx_data->debug_gui.should_advance_frame()) {
+    auto p = scoped_prof("game-render");
     render_game_frame(width, height, lbox_w, lbox_h);
   }
 
   if (g_gfx_data->debug_gui.should_gl_finish()) {
+    auto p = scoped_prof("gl-finish");
     glFinish();
   }
 
-  // render imgui
-  g_gfx_data->debug_gui.draw(g_gfx_data->dma_copier.get_last_result().stats);
-  ImGui::Render();
-  ImGui_ImplOpenGL3_RenderDrawData(ImGui::GetDrawData());
+  // render debug
+  {
+    auto p = scoped_prof("debug-gui");
+    g_gfx_data->debug_gui.draw(g_gfx_data->dma_copier.get_last_result().stats);
+  }
+  {
+    auto p = scoped_prof("imgui-render");
+    ImGui::Render();
+    ImGui_ImplOpenGL3_RenderDrawData(ImGui::GetDrawData());
+  }
 
   // switch vsync modes, if requested
   bool req_vsync = g_gfx_data->debug_gui.get_vsync_flag();
@@ -409,13 +438,19 @@ static void gl_render_display(GfxDisplay* display) {
 
   // actual vsync
   g_gfx_data->debug_gui.finish_frame();
-  glfwSwapBuffers(window);
+  {
+    auto p = scoped_prof("swap-buffers");
+    glfwSwapBuffers(window);
+  }
   if (g_gfx_data->debug_gui.framelimiter) {
+    auto p = scoped_prof("frame-limiter");
     g_gfx_data->frame_limiter.run(
         g_gfx_data->debug_gui.target_fps, g_gfx_data->debug_gui.experimental_accurate_lag,
         g_gfx_data->debug_gui.sleep_in_frame_limiter, g_gfx_data->last_engine_time);
   }
   g_gfx_data->debug_gui.start_frame();
+  prof().instant_event("ROOT");
+  update_global_profiler();
 
   if (display->fullscreen_pending()) {
     display->fullscreen_flush();

game/kernel/kmachine.cpp

@@ -40,6 +40,7 @@
 #include "game/sce/libscf.h"
 #include "common/util/Assert.h"
 #include "game/discord.h"
+#include "common/global_profiler/GlobalProfiler.h"
 
 #include "svnrev.h"
 
@@ -866,6 +867,10 @@ void mkdir_path(u32 filepath) {
   file_util::create_dir_if_needed_for_file(filepath_str);
 }
 
+void prof_event(u32 name, u32 kind) {
+  prof().event(Ptr<String>(name).c()->data(), (ProfNode::Kind)kind);
+}
+
 u32 get_fullscreen() {
   switch (Gfx::get_fullscreen()) {
     default:
@@ -926,6 +931,9 @@ void InitMachine_PCPort() {
   make_function_symbol_from_c("pc-discord-rpc-set", (void*)set_discord_rpc);
   make_function_symbol_from_c("pc-discord-rpc-update", (void*)update_discord_rpc);
 
+  // profiler
+  make_function_symbol_from_c("pc-prof", (void*)prof_event);
+
   // init ps2 VM
   if (VM::use) {
     make_function_symbol_from_c("vm-ptr", (void*)VM::get_vm_ptr);

game/main.cpp

@@ -14,6 +14,10 @@
 // Discord RPC
 extern int64_t gStartTime;
 
+/*!
+ * Set up logging system to log to file.
+ * @param verbose : should we print debug-level messages to stdout?
+ */
 void setup_logging(bool verbose) {
   lg::set_file(file_util::get_file_path({"log/game.txt"}));
   if (verbose) {
@@ -21,22 +25,26 @@ void setup_logging(bool verbose) {
     lg::set_stdout_level(lg::level::debug);
     lg::set_flush_level(lg::level::debug);
   } else {
-    lg::set_file_level(lg::level::warn);
+    lg::set_file_level(lg::level::debug);
     lg::set_stdout_level(lg::level::warn);
     lg::set_flush_level(lg::level::warn);
   }
   lg::initialize();
 }
 
+/*!
+ * Entry point for the game.
+ */
 int main(int argc, char** argv) {
-  // do this as soon as possible - stuff like memcpy might use AVX instructions and we want to
-  // warn the user instead of just crashing.
+  // Figure out if the CPU has AVX2 to enable higher performance AVX2 versions of functions.
   setup_cpu_info();
+  // If the CPU doesn't have AVX, GOAL code won't work and we exit.
   if (!get_cpu_info().has_avx) {
     printf("Your CPU does not support AVX, which is required for OpenGOAL.\n");
     return -1;
   }
 
+  // parse arguments
   bool verbose = false;
   bool disable_avx2 = false;
   std::optional<std::filesystem::path> project_path_override = std::nullopt;
@@ -55,11 +63,14 @@ int main(int argc, char** argv) {
     }
   }
 
+  // set up file paths for resources. This is the full repository when developing, and the data
+  // directory (a subset of the full repo) in release versions
   if (!file_util::setup_project_path(project_path_override)) {
     return 1;
   }
 
-  gStartTime = time(0);
+  // set up discord stuff
+  gStartTime = time(nullptr);
   init_discord_rpc();
 
   if (disable_avx2) {

game/runtime.cpp

@@ -324,7 +324,6 @@ u32 exec_runtime(int argc, char** argv) {
 
   // step 4: wait for EE to signal a shutdown. meanwhile, run video loop on main thread.
   // TODO relegate this to its own function
-  // TODO also sync this up with how the game actually renders things (this is just a placeholder)
   if (enable_display) {
     Gfx::Loop([]() { return !MasterExit; });
     Gfx::Exit();

goal_src/engine/draw/drawable.gc

@@ -116,7 +116,7 @@
   "Is this thing visible? By draw-node id."
   ;; todo
   #t
-  
+
   #|
   (let* ((addr (scratchpad-ptr int8 :offset (+ #x3b80 (/ id 8)))) ;; address of the vis data
          (vis-byte (-> addr 0)) ;; vis byte
@@ -920,11 +920,11 @@
       )
     )
   "Function to be executed to set up for engine dma"
-  
+
   ;; update render enables from the debug menu
   (set! *vu1-enable-user* *vu1-enable-user-menu*)
   (set! *texture-enable-user* *texture-enable-user-menu*)
-  
+
   ;; reset and display dma memory stats.
   (when *debug-segment*
     (when (or *stats-memory* *stats-memory-short*)
@@ -938,138 +938,141 @@
       )
     (reset! *dma-mem-usage*)
     )
-  
+
   ;; todo shrub matrix
-  
+
   ;; initialize dma buckets that are generic sinks.
   ;; other renderers may output to these, so do them first.
   (generic-init-buffers)
-  
+
   ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
   ;; texture uploads
   ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-  
+
   ;; next we use the texture system to build DMA commands to load texture.
   ;; internally, add-tex-to-dma! has special logic to avoid loading textures
   ;; that won't be used. (though it's pretty basic, it doesn't actually track per-texture usage)
-  
+
   ;; level tfrag's upload if the level is running.
-  (when (logtest? *texture-enable-user* 1)
-    (dotimes (gp-1 (-> *level* length))
-      (let ((a1-2 (-> *level* level gp-1)))
-        (if (= (-> a1-2 status) 'active)
-            (add-tex-to-dma! *texture-pool* a1-2 0)
+  (with-profiler "texture-upload"
+    (when (logtest? *texture-enable-user* 1)
+      (dotimes (gp-1 (-> *level* length))
+        (let ((a1-2 (-> *level* level gp-1)))
+          (if (= (-> a1-2 status) 'active)
+              (add-tex-to-dma! *texture-pool* a1-2 0)
+              )
+          )
+        )
+      )
+    ;; level pris's upload if the level is running.
+    (when (logtest? *texture-enable-user* 2)
+      (dotimes (gp-2 (-> *level* length))
+        (let ((a1-3 (-> *level* level gp-2)))
+          (if (= (-> a1-3 status) 'active)
+              (add-tex-to-dma! *texture-pool* a1-3 1)
+              )
+          )
+        )
+      )
+
+    ;; level shrubs upload if the level is loading.
+    (when (logtest? *texture-enable-user* 4)
+      (dotimes (gp-3 (-> *level* length))
+        (let ((a1-4 (-> *level* level gp-3)))
+          (if (= (-> a1-4 status) 'active)
+              (add-tex-to-dma! *texture-pool* a1-4 2)
+              )
+          )
+        )
+      )
+
+    ;; alpha and common.
+    (when (logtest? *texture-enable-user* 8)
+      (let ((uploaded-common #f))
+        (dotimes (gp-4 (-> *level* length))
+          (let ((a1-5 (-> *level* level gp-4)))
+            (when (= (-> a1-5 status) 'active)
+              (add-tex-to-dma! *texture-pool* a1-5 3)
+              (when (not uploaded-common)
+                (upload-one-common! *texture-pool* (-> *level* level0))
+                (set! uploaded-common #t)
+                )
+              )
             )
+          )
+        (when (not uploaded-common)
+          (upload-one-common! *texture-pool* (-> *level* level0))
+          #t
+          )
+        )
+      )
+
+    ;; water.
+    (when (logtest? *texture-enable-user* 16)
+      (dotimes (gp-5 (-> *level* length))
+        (let ((a1-8 (-> *level* level gp-5)))
+          (if (= (-> a1-8 status) 'active)
+              (add-tex-to-dma! *texture-pool* a1-8 4)
+              )
+          )
         )
       )
     )
-  ;; level pris's upload if the level is running.
-  (when (logtest? *texture-enable-user* 2)
-    (dotimes (gp-2 (-> *level* length))
-      (let ((a1-3 (-> *level* level gp-2)))
-        (if (= (-> a1-3 status) 'active)
-            (add-tex-to-dma! *texture-pool* a1-3 1)
-            )
+
+  ;;;;;;;;;;;;;
+  ;; sky
+  ;;;;;;;;;;;;;
+  (with-profiler "sky"
+    (when (zero? (logand *vu1-enable-user* (vu1-renderer-mask sky)))
+      ;; the sky is disabled. Just draw a solid gradient on the whole screen.
+      (with-dma-buffer-add-bucket ((dma-buf (-> (current-frame) global-buf)) (bucket-id sky-draw))
+        (dma-buffer-add-gs-set dma-buf
+                               (zbuf-1 (new 'static 'gs-zbuf :zbp #x1c0 :psm (gs-psm ct24)))
+                               (test-1 (new 'static 'gs-test :ate #x1 :atst (gs-atest always) :zte #x1 :ztst (gs-ztest always)))
+                               (alpha-1 (new 'static 'gs-alpha :b #x1 :d #x1))
+                               )
+        (screen-gradient
+          dma-buf
+          (-> *display* bg-clear-color 0)
+          (-> *display* bg-clear-color 1)
+          (-> *display* bg-clear-color 2)
+          (-> *display* bg-clear-color 3)
+          )
         )
       )
-    )
-  
-  ;; level shrubs upload if the level is loading.
-  (when (logtest? *texture-enable-user* 4)
-    (dotimes (gp-3 (-> *level* length))
-      (let ((a1-4 (-> *level* level gp-3)))
-        (if (= (-> a1-4 status) 'active)
-            (add-tex-to-dma! *texture-pool* a1-4 2)
-            )
-        )
-      )
-    )
-  
-  ;; alpha and common.
-  (when (logtest? *texture-enable-user* 8)
-    (let ((uploaded-common #f))
-      (dotimes (gp-4 (-> *level* length))
-        (let ((a1-5 (-> *level* level gp-4)))
-          (when (= (-> a1-5 status) 'active)
-            (add-tex-to-dma! *texture-pool* a1-5 3)
-            (when (not uploaded-common)
-              (upload-one-common! *texture-pool* (-> *level* level0))
-              (set! uploaded-common #t)
+    (when (logtest? *vu1-enable-user* (vu1-renderer-mask sky))
+      ;; check if we want the sky, and if we actually have textures ready.
+      ;; we generate sky textures on the previous frame and they sit in vram (8160) until the next frame.
+      ;; on the first frame after we request sky, we draw the textures, but they aren't ready until the next frame.
+      (cond
+        ((and (-> *time-of-day-context* sky) *sky-drawn*)
+         (render-sky-tng *time-of-day-context*)
+         )
+        (else
+          ;; todo
+          (with-dma-buffer-add-bucket ((dma-buf (-> (current-frame) global-buf)) (bucket-id sky-draw))
+            (dma-buffer-add-gs-set dma-buf
+                                   (zbuf-1 (new 'static 'gs-zbuf :zbp #x1c0 :psm (gs-psm ct24)))
+                                   (test-1 (new 'static 'gs-test :ate #x1 :atst (gs-atest always) :zte #x1 :ztst (gs-ztest always)))
+                                   (alpha-1 (new 'static 'gs-alpha :b #x1 :d #x1))
+                                   )
+            (screen-gradient
+              dma-buf
+              (-> *time-of-day-context* erase-color)
+              (-> *time-of-day-context* erase-color)
+              (-> *time-of-day-context* erase-color)
+              (-> *time-of-day-context* erase-color)
               )
             )
           )
         )
-      (when (not uploaded-common)
-        (upload-one-common! *texture-pool* (-> *level* level0))
-        #t
-        )
       )
     )
-  
-  ;; water.
-  (when (logtest? *texture-enable-user* 16)
-    (dotimes (gp-5 (-> *level* length))
-      (let ((a1-8 (-> *level* level gp-5)))
-        (if (= (-> a1-8 status) 'active)
-            (add-tex-to-dma! *texture-pool* a1-8 4)
-            )
-        )
-      )
-    )
-  
-  ;;;;;;;;;;;;;
-  ;; sky
-  ;;;;;;;;;;;;;
-  
-  (when (zero? (logand *vu1-enable-user* (vu1-renderer-mask sky)))
-    ;; the sky is disabled. Just draw a solid gradient on the whole screen.
-    (with-dma-buffer-add-bucket ((dma-buf (-> (current-frame) global-buf)) (bucket-id sky-draw))
-      (dma-buffer-add-gs-set dma-buf
-                             (zbuf-1 (new 'static 'gs-zbuf :zbp #x1c0 :psm (gs-psm ct24)))
-                             (test-1 (new 'static 'gs-test :ate #x1 :atst (gs-atest always) :zte #x1 :ztst (gs-ztest always)))
-                             (alpha-1 (new 'static 'gs-alpha :b #x1 :d #x1))
-                             )
-      (screen-gradient
-        dma-buf
-        (-> *display* bg-clear-color 0)
-        (-> *display* bg-clear-color 1)
-        (-> *display* bg-clear-color 2)
-        (-> *display* bg-clear-color 3)
-        )
-      )
-    )
-  (when (logtest? *vu1-enable-user* (vu1-renderer-mask sky))
-    ;; check if we want the sky, and if we actually have textures ready.
-    ;; we generate sky textures on the previous frame and they sit in vram (8160) until the next frame.
-    ;; on the first frame after we request sky, we draw the textures, but they aren't ready until the next frame.
-    (cond
-      ((and (-> *time-of-day-context* sky) *sky-drawn*)
-       (render-sky-tng *time-of-day-context*)
-       )
-      (else
-        ;; todo
-        (with-dma-buffer-add-bucket ((dma-buf (-> (current-frame) global-buf)) (bucket-id sky-draw))
-          (dma-buffer-add-gs-set dma-buf
-                                 (zbuf-1 (new 'static 'gs-zbuf :zbp #x1c0 :psm (gs-psm ct24)))
-                                 (test-1 (new 'static 'gs-test :ate #x1 :atst (gs-atest always) :zte #x1 :ztst (gs-ztest always)))
-                                 (alpha-1 (new 'static 'gs-alpha :b #x1 :d #x1))
-                                 )
-          (screen-gradient
-            dma-buf
-            (-> *time-of-day-context* erase-color)
-            (-> *time-of-day-context* erase-color)
-            (-> *time-of-day-context* erase-color)
-            (-> *time-of-day-context* erase-color)
-            )
-          )
-        )
-      )
-    )
-  
-  
+
+
   ;; update mood lighting, draw sky textures.
-  (update-time-of-day *time-of-day-context*)
-  
+  (with-profiler "time-of-day" (update-time-of-day *time-of-day-context*))
+
   ;; reset the closest object and desired texture masks for all levels.
   ; (dotimes (v1-150 (-> *level* length))
   ;   (let ((a0-59 (-> *level* level v1-150)))
@@ -1084,87 +1087,106 @@
   (add-ee-profile-frame 'draw :r #x40 :b #x40 :a #x80)
 
   ;;;;;;; OCEAN
-  (update-ocean) ;; ocean map update
-  (draw-ocean)   ;; far, mid, near, transition, and texture.
+  (with-profiler "ocean"
+    (update-ocean) ;; ocean map update
+    (draw-ocean)   ;; far, mid, near, transition, and texture.
+    )
   (add-ee-profile-frame 'draw :b #xff :a #x80)
 
   ;; reset MERC
-  (set! (-> *merc-global-array* count) (the-as uint 0))
-  (set! *merc-globals* (the-as merc-globals (-> *merc-global-array* globals)))
-  (set! (-> *shadow-queue* cur-run) (the-as uint 0))
+  (with-profiler "merc"
+    (set! (-> *merc-global-array* count) (the-as uint 0))
+    (set! *merc-globals* (the-as merc-globals (-> *merc-global-array* globals)))
+    (set! (-> *shadow-queue* cur-run) (the-as uint 0))
+    )
 
   ;; draw the background!
-  (init-background)
-  (execute-connections *background-draw-engine* (-> *display* frames (-> *display* on-screen) frame))
+  (with-profiler "background"
+    (init-background)
+    (execute-connections *background-draw-engine* (-> *display* frames (-> *display* on-screen) frame))
 
-  ;; finish bg (most of the work is here)
-  (reset! (-> *perf-stats* data 3))
-  (finish-background)
-  (read! (-> *perf-stats* data 3))
-  (update-wait-stats (-> *perf-stats* data 3) (-> *background-work* wait-to-vu0) (the-as uint 0) (the-as uint 0))
-  
-  ;; perf stats are printed and restarted here, for some reason.
-  (end-perf-stat-collection)
-  (when (not (paused?))
-    (when *stats-poly*
-      (dotimes (gp-8 (-> *level* length))
-        (let ((v1-193 (-> *level* level gp-8)))
-          (if (= (-> v1-193 status) 'active)
-              (collect-stats (-> v1-193 bsp))
-              )
-          )
-        )
-      (print-terrain-stats)
-      )
-    (if *display-perf-stats*
-        (print-perf-stats)
-        )
+    ;; finish bg (most of the work is here)
+    (reset! (-> *perf-stats* data 3))
+    (finish-background)
+    (read! (-> *perf-stats* data 3))
+    (update-wait-stats (-> *perf-stats* data 3) (-> *background-work* wait-to-vu0) (the-as uint 0) (the-as uint 0))
+    )
+
+  ;; perf stats are printed and restarted here, for some reason.
+  (with-profiler "stats"
+    (end-perf-stat-collection)
+    (when (not (paused?))
+      (when *stats-poly*
+        (dotimes (gp-8 (-> *level* length))
+          (let ((v1-193 (-> *level* level gp-8)))
+            (if (= (-> v1-193 status) 'active)
+                (collect-stats (-> v1-193 bsp))
+                )
+            )
+          )
+        (print-terrain-stats)
+        )
+      (if *display-perf-stats*
+          (print-perf-stats)
+          )
+      )
+    (start-perf-stat-collection)
     )
-  (start-perf-stat-collection)
 
   ;; draw the foreground engines.
-  (foreground-engine-execute
-    (-> *level* level-default foreground-draw-engine 0)
-    (-> *display* frames (-> *display* on-screen) frame)
-    2
-    0
+  (with-profiler "foreground-engines"
+    (foreground-engine-execute
+      (-> *level* level-default foreground-draw-engine 0)
+      (-> *display* frames (-> *display* on-screen) frame)
+      2
+      0
+      )
+    (foreground-engine-execute
+      (-> *level* level-default foreground-draw-engine 1)
+      (-> *display* frames (-> *display* on-screen) frame)
+      2
+      1
+      )
     )
-  (foreground-engine-execute
-    (-> *level* level-default foreground-draw-engine 1)
-    (-> *display* frames (-> *display* on-screen) frame)
-    2
-    1
-    )
-  
+
   ;; handle extra processing for foreground
+
   (let ((gp-9 (-> *display* frames (-> *display* on-screen) frame global-buf)))
-    (bones-mtx-calc-execute)        ;; skinning matrix calculation
-    (generic-merc-execute-all gp-9) ;; mercneric conversion.
-    (shadow-execute-all gp-9 *shadow-queue*)
-    (update-eyes)
+    (with-profiler "bones" (bones-mtx-calc-execute)) ;; skinning matrix calculation
+    (with-profiler "gmerc" (generic-merc-execute-all gp-9)) ;; mercneric conversion.
+    (with-profiler "shadow" (shadow-execute-all gp-9 *shadow-queue*))
+    (with-profiler "eyes" (update-eyes))
     )
 
   ;; sprite draw
   (when (logtest? (vu1-renderer-mask sprite) *vu1-enable-user*)
-    (swap-fake-shadow-buffers)
-    (sprite-draw *display*)
+    (with-profiler "sprite"
+      (swap-fake-shadow-buffers)
+      (sprite-draw *display*)
+      )
     )
   ;; debug drawing
-  (when *debug-segment*
-    (debug-draw-actors *level* *display-actor-marks*)
-    (collide-shape-draw-debug-marks)
+  (with-profiler "debug-draw"
+    (when *debug-segment*
+      (debug-draw-actors *level* *display-actor-marks*)
+      (collide-shape-draw-debug-marks)
+      )
+    (render-boundaries)
     )
-  (render-boundaries)
-  
+
   ;; for some reason we clear the touching list here...
-  (send-events-for-touching-shapes *touching-list*)
-  (free-all-prim-nodes *touching-list*)
-  
+  (with-profiler "touching"
+    (send-events-for-touching-shapes *touching-list*)
+    (free-all-prim-nodes *touching-list*)
+    )
+
   (add-ee-profile-frame 'draw :r #x40 :b #x40 :a #x80)
   ;; spawn actors, compact heaps, etc.
-  (actors-update *level*)
+  (with-profiler "actors-update"
+    (actors-update *level*)
+    )
   (add-ee-profile-frame 'draw  :r #x80 :a #x80)
-  
+
   (when (not (paused?))
     (if *stats-collide*
         (print-collide-stats)

goal_src/engine/game/main.gc

@@ -583,7 +583,7 @@
     ;;;;;;;;;;;;;;;;;;;;;;;;;;;;
     ;; Pre loop initialization
     ;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-    
+
     ;; the size is 0, so this doesn't actually do anything.
     ;; (dma-send-to-spr (the-as uint #x70000000) (the-as uint *terrain-context*) (the-as uint 0) #t)
     (set! *teleport* #t)
@@ -595,104 +595,113 @@
     (blerc-init)
     ;; collide dma
     (suspend)
-    
-    
+
+
     (while *run*
       ;; start immediately after all process updates finish.
-      
+      (profiler-instant-event "display-loop-top")
+
       ;; drawing effects to be used in foreground drawing.
-      (blerc-execute)
-      (blerc-init)
-      (texscroll-execute)
-      (ripple-execute)
-      
+      (with-profiler "foreground-effects"
+        (blerc-execute)
+        (blerc-init)
+        (texscroll-execute)
+        (ripple-execute)
+        )
+
       ;;;;;;;;;;;;;;;;;;;;
       ;; AMBIENT
       ;;;;;;;;;;;;;;;;;;;;
-      
+
       ;; set defaults for weather/music/flava.
-      (set! *weather-off* #f)
-      (let ((v1-13 (-> *game-info* current-continue level)))
-        (dotimes (a0-8 (-> *level* length))
-          (let ((a1-6 (-> *level* level a0-8)))
-            (when (= (-> a1-6 status) 'active)
-              (if (and (= (-> a1-6 name) v1-13) (-> *level* play?))
-                  (set! (-> *setting-control* default music) (-> a1-6 info music-bank))
-                  )
+      (with-profiler "ambients"
+        (set! *weather-off* #f)
+        (let ((v1-13 (-> *game-info* current-continue level)))
+          (dotimes (a0-8 (-> *level* length))
+            (let ((a1-6 (-> *level* level a0-8)))
+              (when (= (-> a1-6 status) 'active)
+                (if (and (= (-> a1-6 name) v1-13) (-> *level* play?))
+                    (set! (-> *setting-control* default music) (-> a1-6 info music-bank))
+                    )
+                )
               )
             )
           )
-        )
-      
-      (set! (-> *setting-control* default sound-flava) (the-as uint 49))
-      (set! (-> *setting-control* default sound-flava-priority) 0.0)
-      
-      ;; find any ambients, and execute them.
-      (when (and *execute-ambients* (not (paused?)))
-        (if *target*
-            (set! (-> *target* draw secondary-interp) 0.0)
-            )
-        (let ((s5-1 (sphere<-vector+r! (new 'stack 'sphere) (ear-trans) 0.0)))
-          (let ((v1-28 (scratchpad-object terrain-context)))
-            (set! (-> v1-28 work ambient ambient-list num-items) 0)
-            )
-          (dotimes (s4-1 (-> *level* length))
-            (let ((v1-32 (-> *level* level s4-1)))
-              (when (= (-> v1-32 status) 'active)
-                  (collect-ambients (-> v1-32 bsp) s5-1 0 (-> (scratchpad-object terrain-context) work ambient ambient-list))
-                  )
+
+        (set! (-> *setting-control* default sound-flava) (the-as uint 49))
+        (set! (-> *setting-control* default sound-flava-priority) 0.0)
+
+        ;; find any ambients, and execute them.
+        (when (and *execute-ambients* (not (paused?)))
+          (if *target*
+              (set! (-> *target* draw secondary-interp) 0.0)
+              )
+          (let ((s5-1 (sphere<-vector+r! (new 'stack 'sphere) (ear-trans) 0.0)))
+            (let ((v1-28 (scratchpad-object terrain-context)))
+              (set! (-> v1-28 work ambient ambient-list num-items) 0)
+              )
+            (dotimes (s4-1 (-> *level* length))
+              (let ((v1-32 (-> *level* level s4-1)))
+                (when (= (-> v1-32 status) 'active)
+                    (collect-ambients (-> v1-32 bsp) s5-1 0 (-> (scratchpad-object terrain-context) work ambient ambient-list))
+                    )
+                )
+              )
+
+            (countdown (s4-2 (-> (scratchpad-object terrain-context) work ambient ambient-list num-items))
+              (execute-ambient (-> (scratchpad-object terrain-context) work ambient ambient-list items s4-2) s5-1)
               )
-            )
-          
-          (countdown (s4-2 (-> (scratchpad-object terrain-context) work ambient ambient-list num-items))
-            (execute-ambient (-> (scratchpad-object terrain-context) work ambient ambient-list items s4-2) s5-1)
             )
           )
         )
       (add-ee-profile-frame 'draw :r #x40 :b #x40) ;; actor update
-      
+
       ;; do math, before drawing
-      (execute-math-engine)
+      (with-profiler "math-engine" (execute-math-engine))
       ;; DEBUG PROF
       (add-ee-profile-frame 'draw :r #x80)
       (add-ee-profile-frame 'draw :r #x40 :b #x40)
       ;; debug hook
-      (*debug-hook*)
-      (main-cheats)
+      (with-profiler "debug" (*debug-hook*) (main-cheats))
       (add-ee-profile-frame 'draw :r #x20 :g #x20)
-      (update-camera)
+      (with-profiler "camera" (update-camera))
       (add-ee-profile-frame 'draw :r #x40 :b #x40)
-      (*draw-hook*)
+      (with-profiler "draw-hook" (*draw-hook*))
       (add-ee-profile-frame 'draw :g #x80)
 
-      (with-pc
-        (if (-> *pc-settings* display-sha)
-            (draw-build-revision)))
+      (with-profiler "menu"
+        (with-pc
+          (if (-> *pc-settings* display-sha)
+              (draw-build-revision)))
 
-      (*menu-hook*)
-      (add-ee-profile-frame 'draw :g #x40)
+        (*menu-hook*)
+        (add-ee-profile-frame 'draw :g #x40)
 
-      ;; finally, update hints/text
-      (make-current-level-available-to-progress)
-      (update-task-hints)
-      (load-level-text-files -1)
+        ;; finally, update hints/text
+        (make-current-level-available-to-progress)
+        (update-task-hints)
+        (load-level-text-files -1)
 
-      (add-ee-profile-frame 'unknown-cpu-time)
-      ;; collect perf stats
-      (read! (-> *perf-stats* data (perf-stat-bucket all-code)))
-
-      (when (nonzero? (sync-path 0 0))
-        (*dma-timeout-hook*)
-        (reset-vif1-path)
-        (if *debug-segment*
-            (format 0 "profile bar at ~D.~%" (-> (current-frame) profile-bar 1 profile-frame-count))
-            )
+        (add-ee-profile-frame 'unknown-cpu-time)
+        ;; collect perf stats
+        (read! (-> *perf-stats* data (perf-stat-bucket all-code)))
+        )
+
+      (with-profiler "dma-sync"
+        (when (nonzero? (sync-path 0 0))
+          (*dma-timeout-hook*)
+          (reset-vif1-path)
+          (if *debug-segment*
+              (format 0 "profile bar at ~D.~%" (-> (current-frame) profile-bar 1 profile-frame-count))
+              )
+          )
+        (reset! (-> *perf-stats* data (perf-stat-bucket all-code)))
         )
-      (reset! (-> *perf-stats* data (perf-stat-bucket all-code)))
 
       ;; depth cue
       ;; screen filter
 
+      (with-profiler "post-sync-draw"
       ;; add letterbox effect
       (when (or (movie?) (< (-> *display* base-frame-counter) (-> *game-info* letterbox-time)))
         (if (< (-> *game-info* letterbox-time) (-> *display* base-frame-counter))
@@ -882,12 +891,13 @@
 
       ;; console buffers
       (set! *stdcon* (clear *stdcon0*))
+      )
 
       ;; <--------------------------- SWAP DISPLAY!
       ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-      (swap-display disp)
+      (with-profiler "swap-display" (swap-display disp))
       ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
-      
+
       (set! (-> *time-of-day-context* title-updated) #f)
       (set! *teleport* #f)
       (when (nonzero? *teleport-count*)
@@ -897,21 +907,26 @@
 
       ;; perf stats
 
-      (process-particles)
-
+      (with-profiler "process-particles" (process-particles))
 
       ;; vif0 collide
       ;; swap sound
       ;; str play
-      (swap-sound-buffers (ear-trans) (camera-pos) (camera-angle))
-      (str-play-kick)
-      (level-update *level*) ;; also updates settings.
-      (mc-run)
-      (auto-save-check)
+      (with-profiler "sound-update"
+                     (swap-sound-buffers (ear-trans) (camera-pos) (camera-angle))
+                     (str-play-kick)
+                     )
+
+      (with-profiler "level-and-save"
+         (level-update *level*) ;; also updates settings.
+         (mc-run)
+         (auto-save-check)
+
+         (#when PC_PORT
+           (update *pc-settings*)
+           )
+         )
 
-      (#when PC_PORT
-        (update *pc-settings*)
-        )
 
       ;; suspend
       (suspend)

goal_src/engine/ps2/timer-h.gc

@@ -181,7 +181,6 @@
         )
        )
   )
-      
 
 ;; tentative name
 (defmethod get-last-frame-time-stamp profile-bar ((obj profile-bar))

goal_src/kernel-defs.gc

@@ -340,6 +340,14 @@
 (define-extern pc-filepath-exists? (function string symbol))
 (define-extern pc-mkdir-file-path (function string none))
 
+(defenum pc-prof-event
+  (begin 0)
+  (end 1)
+  (instant 2)
+  )
+
+(define-extern pc-prof (function string pc-prof-event none))
+
 ;; Constants generated within the C++ runtime
 (define-extern *pc-user-dir-base-path* string)
 (define-extern *pc-settings-folder* string)

goal_src/kernel/gcommon.gc

@@ -24,6 +24,9 @@
 ;; are monitored in the runtime for debugging.
 (defglobalconstant USE_VM #t)
 
+(defglobalconstant PC_PROFILER_ENABLE #t)
+
+
 (defmacro get-vm-ptr (ptr)
   "Turn an EE register address into a valid PS2 VM address"
   `(#cond
@@ -119,7 +122,7 @@
   )
 
 (defun ash ((value int) (shift-amount int))
-  "Arithmetic shift value by shift-amount.  
+  "Arithmetic shift value by shift-amount.
   A positive shift-amount will shift to the left and a negative will shift to the right.
   "
   ;; OpenGOAL does not support ash in the compiler, so we implement it here as an inline function.
@@ -133,7 +136,7 @@
 (defun mod ((a int) (b int))
   "Compute mod.  It does what you expect for positive numbers.  For negative numbers, nobody knows what to expect.
   This is a 32-bit operation.  It uses an idiv on x86 and gets the remainder."
-  
+
   ;; The original implementation is div, mfhi
   ;; todo - verify this is exactly the same as the PS2.
   (mod a b)
@@ -142,7 +145,7 @@
 
 (defun rem ((a int) (b int))
   "Compute remainder (32-bit).  It is identical to mod. It uses a idiv and gets the remainder"
-  
+
   ;; The original implementation is div, mfhi
   ;; todo - verify this is exactly the same as the PS2.
   (mod a b)
@@ -150,9 +153,9 @@
 
 (defun abs ((a int))
   "Take the absolute value of an integer"
-  
+
   (declare (inline))
-  
+
   ;; OpenGOAL doesn't support abs, so we implement it here.
   (if (> a 0) ;; condition is "a > 0"
       a       ;; true case, return a
@@ -162,7 +165,7 @@
 
 (defun min ((a int) (b int))
   "Compute minimum."
-  
+
   ;; The original implementation was inline assembly, to take advantage of branch delay slots:
   ;;  (or v0 a0 r0)    ;; move first arg to output (case of second arg being min)
   ;;  (or v1 a1 r0)    ;; move second arg to v1 (likely strange coloring)
@@ -307,7 +310,7 @@
 
 (defmethod asize-of type ((obj type))
   "Get the size in memory of a type"
-  ;; The 28 is 8 bytes too large. It's also strange that types have a 16-byte aligned size always, 
+  ;; The 28 is 8 bytes too large. It's also strange that types have a 16-byte aligned size always,
   ;; but this matches what the runtime does as well. There's no reason that I can see for this,
   ;; as other basics don't require 16-byte aligned sizes.
   ;; - maybe the 16-byte aligned size was a requirement if types were stored in the symbol table?
@@ -486,7 +489,7 @@
   )
 
 (defun nassoc ((item-name string) (alist object))
-  "Is there an entry named item-name in the association list alist? 
+  "Is there an entry named item-name in the association list alist?
    Checks name with nmember or name= so you can have multiple keys.
    Returns the ([key|(key..)] . value) pair."
   (while (not (or (null? alist)
@@ -670,9 +673,9 @@
    ;; children of inline-array-class should define their own data which overlays this one.
    (_data            uint8  :dynamic :offset 16)
    )
-  
+
   (:methods (new (symbol type int) _type_ 0))
-  
+
   :method-count-assert 9
   :size-assert         #x10
   :flag-assert         #x900000010
@@ -760,7 +763,7 @@
   (format #t "#(")
   (cond
    ((type-type? (-> obj content-type) integer)
-    (case (-> obj content-type symbol) 
+    (case (-> obj content-type symbol)
      (('int32)
        (dotimes (s5-0 (-> obj length))
         (format #t (if (zero? s5-0)
@@ -894,7 +897,7 @@
   (format #t "~Tdata[~D]: @ #x~X~%" (-> obj allocated-length) (-> obj data))
   (cond
    ((type-type? (-> obj content-type) integer)
-    (case (-> obj content-type symbol) 
+    (case (-> obj content-type symbol)
      (('int32)
        (dotimes (s5-0 (-> obj length))
         (format #t "~T  [~D] ~D~%" s5-0 (-> (the-as (array int32) obj) s5-0))
@@ -1425,3 +1428,35 @@
 (defmacro empty-form ()
   `(none)
   )
+
+(defmacro profiler-instant-event (name)
+  `(#when PC_PROFILER_ENABLE
+     (pc-prof ,name (pc-prof-event instant))
+     )
+  )
+
+(defmacro profiler-start-event (name)
+  `(#when PC_PROFILER_ENABLE
+     (pc-prof ,name (pc-prof-event begin))
+     )
+  )
+
+(defmacro profiler-end-event ()
+  `(#when PC_PROFILER_ENABLE
+     (pc-prof "" (pc-prof-event end))
+     )
+  )
+
+(defmacro with-profiler (name &rest body)
+  `(#if PC_PROFILER_ENABLE
+        (begin
+          (pc-prof ,name (pc-prof-event begin))
+          ,@body
+          (pc-prof ,name (pc-prof-event end))
+          )
+
+        (begin
+          ,@body
+          )
+        )
+  )

goal_src/pc/pckernel.gc

@@ -171,7 +171,7 @@
     (set! (-> info status) "Playing Jak and Daxter: The Precursor Legacy™")
     (set! (-> info level) (symbol->string (-> (level-get-target-inside *level*) name))) ;; grab the name of level we're in
     (set! (-> info cutscene?) (-> obj movie?))
-    (pc-discord-rpc-update info)
+    (with-profiler "discord-update" (pc-discord-rpc-update info))
     )
 
   (when (not (-> obj use-vis?))