wip frame pacing code

Summary:

Test Plan:

src/main/debug-overlay/dllmain.c

@@ -0,0 +1,3 @@
+// TODO have a separate dll that acts as a debug
+// overlay for btools in general providing stuff
+// like frame graph, text sections for IO timings etc.

src/main/iidxhook-d3d9/Module.mk

@@ -6,3 +6,4 @@ libs_iidxhook-d3d9     := \
 
 src_iidxhook-d3d9     := \
     bb-scale-hd.c \
+    frame-pace.c \

src/main/iidxhook-d3d9/frame-pace.c

@@ -0,0 +1,194 @@
+#define LOG_MODULE "iidxhook-d3d-frame-pace"
+
+#include <windows.h>
+
+#include <stdbool.h>
+
+#include "hook/table.h"
+
+#include "util/log.h"
+
+#include "frame-pace.h"
+
+static void STDCALL my_Sleep(DWORD dwMilliseconds);
+static void (STDCALL *real_Sleep)(DWORD dwMilliseconds);
+
+static DWORD STDCALL my_SleepEx(DWORD dwMilliseconds, BOOL bAlertable);
+static DWORD (STDCALL *real_SleepEx)(DWORD dwMilliseconds, BOOL bAlertable);
+
+static const struct hook_symbol iidxhok_d3d9_frame_pace_hook_syms[] = {
+    {
+        .name = "Sleep",
+        .patch = my_Sleep,
+        .link = (void **) &real_Sleep,
+    },
+    {
+        .name = "SleepEx",
+        .patch = my_SleepEx,
+        .link = (void **) &real_SleepEx,
+    },
+};
+
+static bool iidxhook_d3d9_frame_pace_initialized;
+
+static DWORD iidxhook_d3d9_frame_pace_main_thread_id = -1;
+
+static int64_t iidxhook_d3d9_frame_pace_target_frame_time_cpu_ticks;
+static int64_t iidxhook_d3d9_frame_pace_frame_time_start_cpu_ticks;
+
+static uint64_t iidxhook_d3d9_frame_pace_get_cpu_tick_frequency()
+{
+    LARGE_INTEGER freq;
+
+    QueryPerformanceFrequency(&freq);
+
+    return freq.QuadPart;
+}
+
+static uint64_t iidxhook_d3d9_frame_pace_get_cpu_ticks()
+{
+    LARGE_INTEGER tick;
+
+    QueryPerformanceCounter(&tick);
+
+    return tick.QuadPart;
+}
+
+// Source and reference implementation:
+// https://github.com/PCSX2/pcsx2/blob/f26031cada6893ac306af73255d337e50a8f73f9/pcsx2/Counters.cpp#L563
+static void iidxhook_d3d9_frame_pace_do_post_frame()
+{
+    // -----------------------------------------------------------------------
+
+    const int64_t m_iTicks = iidxhook_d3d9_frame_pace_target_frame_time_cpu_ticks;
+    int64_t m_iStart = iidxhook_d3d9_frame_pace_frame_time_start_cpu_ticks;
+
+    // Compute when we would expect this frame to end, assuming everything goes perfectly perfect.
+    const uint64_t uExpectedEnd = m_iStart + m_iTicks;
+    // The current tick we actually stopped on.
+	const uint64_t iEnd = iidxhook_d3d9_frame_pace_get_cpu_ticks();   
+    // The diff between when we stopped and when we expected to.
+	const int64_t sDeltaTime = iEnd - uExpectedEnd;    
+
+	// If frame ran too long...
+	if (sDeltaTime >= m_iTicks)
+	{
+		// ... Fudge the next frame start over a bit. Prevents fast forward zoomies.
+		m_iStart += (sDeltaTime / m_iTicks) * m_iTicks;
+        iidxhook_d3d9_frame_pace_frame_time_start_cpu_ticks = m_iStart;
+		return;
+	}
+
+	// Conversion of delta from CPU ticks (microseconds) to milliseconds
+	int32_t msec = (int32_t) ((sDeltaTime * -1000) / (int64_t) iidxhook_d3d9_frame_pace_get_cpu_tick_frequency());
+
+	// If any integer value of milliseconds exists, sleep it off.
+	// Prior comments suggested that 1-2 ms sleeps were inaccurate on some OSes;
+	// further testing suggests instead that this was utter bullshit.
+	if (msec > 1)
+	{
+		real_Sleep(msec - 1);
+	}
+
+	// Conversion to milliseconds loses some precision; after sleeping off whole milliseconds,
+	// spin the thread without sleeping until we finally reach our expected end time.
+	while (iidxhook_d3d9_frame_pace_get_cpu_ticks() < uExpectedEnd)
+	{
+		// SKREEEEEEEE
+	}
+
+	// Finally, set our next frame start to when this one ends
+	m_iStart = uExpectedEnd;
+    iidxhook_d3d9_frame_pace_frame_time_start_cpu_ticks = m_iStart;
+}
+
+// TODO must be renamed to framerate monitor with smoother/pacer
+// TODO have feature flag to print framerate performance counters etc every X seconds
+// as misc debug log output
+// TODO make sure to record a decent amount of data/frame time accordingly over these
+// seconds to report proper avg. frame time/rate, min, max, p95, p99, p999
+// TODO move this to a separate module that can be re-used on d3d9ex
+
+// fill up unused frametime on short frames to simulate hardware accuracy
+// and match the timing of the target monitor's refresh rate as close as possible
+// this fixes frame pacing issues with too short frames not being smoothened
+// correctly by the game which either relies entirely on the hardware/GPU driver
+// to do that or on tricoro+ era games, on SleepEx which only has max of 1 ms
+// accuracy. the further the target monitor refresh rate is away from the desired
+// refresh rate, e.g. 60 hz vsync, the more apparent the frame pacing issues
+// become in the form of "random stuttering during gameplay"
+
+static void STDCALL my_Sleep(DWORD dwMilliseconds)
+{
+    // Heuristic, but seems to kill the poorly implemented frame pacing code
+    // fairly reliable without impacting other parts of the code negatively
+    if (iidxhook_d3d9_frame_pace_main_thread_id == GetCurrentThreadId()) {
+        if (dwMilliseconds <= 16) {
+            return;
+        }
+    }
+
+    real_Sleep(dwMilliseconds);
+}
+
+static DWORD STDCALL my_SleepEx(DWORD dwMilliseconds, BOOL bAlertable)
+{
+    // Heuristic, but applies only in two spots
+    // - frame pacing code (dynamic value)
+    // - Another spot with sleep time set to 1 -> reduces CPU banging
+    if (iidxhook_d3d9_frame_pace_main_thread_id == GetCurrentThreadId()) {
+        if (dwMilliseconds <= 16) {
+            return 0;
+        }
+    }
+
+    return real_SleepEx(dwMilliseconds, bAlertable);
+}
+
+static void iidxhook_d3d9_frame_pace_timings_init(double target_frame_rate_hz)
+{
+    double tick_rate;
+
+    tick_rate = iidxhook_d3d9_frame_pace_get_cpu_tick_frequency();
+    iidxhook_d3d9_frame_pace_target_frame_time_cpu_ticks = (int64_t) (tick_rate / target_frame_rate_hz);
+    iidxhook_d3d9_frame_pace_frame_time_start_cpu_ticks = iidxhook_d3d9_frame_pace_get_cpu_ticks();
+}
+
+void iidxhook_d3d9_frame_pace_init(DWORD main_thread_id, double target_frame_rate_hz)
+{
+    log_assert(main_thread_id != -1);
+
+    iidxhook_d3d9_frame_pace_timings_init(target_frame_rate_hz);
+
+    iidxhook_d3d9_frame_pace_main_thread_id = main_thread_id;
+
+    iidxhook_d3d9_frame_pace_initialized = true;
+
+    hook_table_apply(
+            NULL, "kernel32.dll", iidxhok_d3d9_frame_pace_hook_syms, lengthof(iidxhok_d3d9_frame_pace_hook_syms));
+
+    log_info("Initialized, target frame rate in hz %f, target frame time in cpu ticks %llu", target_frame_rate_hz, iidxhook_d3d9_frame_pace_target_frame_time_cpu_ticks);
+}
+
+HRESULT iidxhook_d3d9_frame_pace_d3d9_irp_handler(struct hook_d3d9_irp *irp)
+{
+    HRESULT hr;
+
+    log_assert(irp);
+
+    if (!iidxhook_d3d9_frame_pace_initialized) {
+        return hook_d3d9_irp_invoke_next(irp);
+    }
+
+    if (irp->op == HOOK_D3D9_IRP_OP_DEV_PRESENT) {
+        hr = hook_d3d9_irp_invoke_next(irp);
+
+        if (hr == S_OK) {
+            iidxhook_d3d9_frame_pace_do_post_frame();
+        }
+
+        return hr;
+    } else {
+        return hook_d3d9_irp_invoke_next(irp);
+    }
+}

src/main/iidxhook-d3d9/frame-pace.h

@@ -0,0 +1,13 @@
+#ifndef IIDXHOOK_D3D9_FRAME_PACE_H
+#define IIDXHOOK_D3D9_FRAME_PCE_H
+
+#include <stdbool.h>
+#include <stdint.h>
+
+#include "hook/d3d9.h"
+
+void iidxhook_d3d9_frame_pace_init(DWORD main_thread_id, double target_frame_rate_hz);
+
+HRESULT iidxhook_d3d9_frame_pace_d3d9_irp_handler(struct hook_d3d9_irp *irp);
+
+#endif

src/main/iidxhook-util/Module.mk

@@ -16,5 +16,6 @@ src_iidxhook-util     := \
     d3d9.c \
     eamuse.c \
     effector.c \
+    frame-graph.c \
     log-server.c \
     settings.c \

src/main/iidxhook-util/d3d9.c

@@ -13,6 +13,7 @@
 #include "hook/table.h"
 
 #include "iidxhook-util/d3d9.h"
+#include "iidxhook-util/frame-graph.h"
 #include "iidxhook-util/vertex-shader.h"
 
 #include "util/defs.h"
@@ -232,7 +233,7 @@ iidxhook_util_d3d9_log_create_device_params(struct hook_d3d9_irp *irp)
         "hDeviceWindow %p, Windowed %d, "
         "EnableAutoDepthStencil "
         "%d, AutoDepthStencilFormat %d, Flags %lX, "
-        "FullScreen_RefreshRateInHz %d",
+        "FullScreen_RefreshRateInHz %d, PresentationInterval %d",
         irp->args.ctx_create_device.pp->BackBufferWidth,
         irp->args.ctx_create_device.pp->BackBufferHeight,
         irp->args.ctx_create_device.pp->BackBufferFormat,
@@ -244,7 +245,8 @@ iidxhook_util_d3d9_log_create_device_params(struct hook_d3d9_irp *irp)
         irp->args.ctx_create_device.pp->EnableAutoDepthStencil,
         irp->args.ctx_create_device.pp->AutoDepthStencilFormat,
         irp->args.ctx_create_device.pp->Flags,
-        irp->args.ctx_create_device.pp->FullScreen_RefreshRateInHz);
+        irp->args.ctx_create_device.pp->FullScreen_RefreshRateInHz,
+        irp->args.ctx_create_device.pp->PresentationInterval);
 }
 
 static void
@@ -267,6 +269,9 @@ static void iidxhook_util_d3d9_fix_create_device_apply_window_mode(
     log_assert(irp->op == HOOK_D3D9_IRP_OP_CTX_CREATE_DEVICE);
     D3DPRESENT_PARAMETERS *pp = irp->args.ctx_create_device.pp;
 
+    // TODO temporarily remove vsync for testing
+    pp->PresentationInterval = D3DPRESENT_INTERVAL_IMMEDIATE;
+
     if (iidxhook_util_d3d9_config.windowed) {
         pp->Windowed = TRUE;
         pp->FullScreen_RefreshRateInHz = 0;
@@ -1190,7 +1195,14 @@ iidxhook_util_d3d9_irp_handler(struct hook_d3d9_irp *irp)
 
             return hook_d3d9_irp_invoke_next(irp);
 
+        // TODO is there always ever just a single scene being rendered?
+        case HOOK_D3D9_IRP_OP_DEV_END_SCENE:
+            DrawFrameGraph(irp->args.dev_present.self);
+
+            return hook_d3d9_irp_invoke_next(irp);
+
         case HOOK_D3D9_IRP_OP_DEV_PRESENT:
+            
             iidxhook_util_d3d9_scale_render_target_to_back_buffer(irp);
             iidxhook_util_d3d9_set_back_buffer_rt(irp);
 

src/main/iidxhook-util/frame-graph.c

@@ -0,0 +1,374 @@
+#include <windows.h>
+#include <d3d9.h>
+#include <d3dx9.h>
+#include <stdio.h>
+#include <stdint.h>
+#include <stdbool.h>
+#include <math.h>
+
+#include "util/log.h"
+#include "util/time.h"
+
+#define MAX_SAMPLES 600  // 10 seconds at 60 FPS
+#define GRAPH_WIDTH 300
+#define GRAPH_HEIGHT 100
+#define GRAPH_X 300      // Left position of graph
+#define GRAPH_Y 30      // Top position of graph
+#define AXIS_COLOR D3DCOLOR_XRGB(128, 128, 128)  // Gray color for axes
+#define GRAPH_COLOR D3DCOLOR_XRGB(255, 255, 0)   // Yellow color for the graph
+#define TEXT_COLOR D3DCOLOR_XRGB(255, 255, 0)    // Yellow color for text
+
+// // TODO have a separate module that wraps all of these somewhat
+typedef HRESULT WINAPI (*func_D3DXCreateFontA)(
+    struct IDirect3DDevice9 *device,
+    INT height,
+    UINT width,
+    UINT weight,
+    UINT miplevels,
+    BOOL italic,
+    DWORD charset,
+    DWORD precision,
+    DWORD quality,
+    DWORD pitchandfamily,
+    const char *facename,
+    struct ID3DXFont **font);
+
+typedef HRESULT WINAPI (*func_D3DXCreateLine)(
+    struct IDirect3DDevice9 *device,
+    struct ID3DXLine **line);
+
+typedef struct {
+    double frameTimes[MAX_SAMPLES];
+    int currentIndex;
+    double minTime;
+    double maxTime;
+    double avgTime;
+    int sampleCount;
+    
+    ID3DXFont* font;        // For regular text
+    ID3DXFont* smallFont;   // For axis labels
+    ID3DXLine* line;
+    bool resourcesInitialized;
+} PerfMetrics;
+
+PerfMetrics g_metrics = {0};
+
+static HRESULT createLine(
+    IDirect3DDevice9 *dev,
+    struct ID3DXLine **line)
+{
+    HMODULE d3d9_24;
+
+    d3d9_24 = GetModuleHandleA("d3dx9_24.dll");
+
+    if (d3d9_24 == NULL) {
+        log_fatal(
+            "Failed to load d3dx9_24.dll to create a font for displaying "
+            "framerate on monitor check.");
+        return 0;
+    }
+
+    func_D3DXCreateLine d3dxCreateLine =
+        (func_D3DXCreateLine) GetProcAddress(d3d9_24, "D3DXCreateLine");
+
+    if (d3dxCreateLine == NULL) {
+        log_fatal("Failed to find function D3DXCreateLine");
+        return 0;
+    }
+
+    return d3dxCreateLine(
+        dev,
+        line);
+}
+
+static HRESULT createFontA(
+    IDirect3DDevice9 *dev,
+    INT height,
+    UINT width,
+    UINT weight,
+    UINT miplevels,
+    BOOL italic,
+    DWORD charset,
+    DWORD precision,
+    DWORD quality,
+    DWORD pitchandfamily,
+    const char *facename,
+    ID3DXFont **font)
+{
+    HMODULE d3d9_24;
+
+    d3d9_24 = GetModuleHandleA("d3dx9_24.dll");
+
+    if (d3d9_24 == NULL) {
+        log_fatal(
+            "Failed to load d3dx9_24.dll to create a font for displaying "
+            "framerate on monitor check.");
+        return 0;
+    }
+
+    func_D3DXCreateFontA d3dxCreateFontA =
+        (func_D3DXCreateFontA) GetProcAddress(d3d9_24, "D3DXCreateFontA");
+
+    if (d3dxCreateFontA == NULL) {
+        log_fatal("Failed to find function D3DXCreateFontA");
+        return 0;
+    }
+
+    return d3dxCreateFontA(
+        dev,
+        height,
+        width,
+        weight,
+        miplevels,
+        italic,
+        charset,
+        precision,
+        quality,
+        pitchandfamily,
+        facename,
+        font);
+}
+
+// Update performance metrics with new frame time
+void UpdateMetrics(double frameTime) {
+    g_metrics.frameTimes[g_metrics.currentIndex] = frameTime;
+    g_metrics.currentIndex = (g_metrics.currentIndex + 1) % MAX_SAMPLES;
+    
+    if (g_metrics.sampleCount < MAX_SAMPLES)
+        g_metrics.sampleCount++;
+        
+    // Update min/max/avg
+    g_metrics.minTime = frameTime;
+    g_metrics.maxTime = frameTime;
+    g_metrics.avgTime = 0;
+    
+    for (int i = 0; i < g_metrics.sampleCount; i++) {
+        double time = g_metrics.frameTimes[i];
+        g_metrics.minTime = min(g_metrics.minTime, time);
+        g_metrics.maxTime = max(g_metrics.maxTime, time);
+        g_metrics.avgTime += time;
+    }
+    
+    g_metrics.avgTime /= g_metrics.sampleCount;
+}
+
+bool InitializeOverlayResources(IDirect3DDevice9* device) {
+    if (g_metrics.resourcesInitialized) return true;
+    
+    // Create main font (larger, for FPS display)
+    if (FAILED(createFontA(device, 20, 0, FW_BOLD, 1, FALSE, DEFAULT_CHARSET,
+        OUT_DEFAULT_PRECIS, DEFAULT_QUALITY, DEFAULT_PITCH | FF_DONTCARE,
+        "Arial", &g_metrics.font))) {
+        return false;
+    }
+    
+    // Create smaller font for axis labels
+    if (FAILED(createFontA(device, 12, 0, FW_NORMAL, 1, FALSE, DEFAULT_CHARSET,
+        OUT_DEFAULT_PRECIS, DEFAULT_QUALITY, DEFAULT_PITCH | FF_DONTCARE,
+        "Arial", &g_metrics.smallFont))) {
+        ID3DXFont_Release(g_metrics.font);
+        return false;
+    }
+    
+    if (FAILED(createLine(device, &g_metrics.line))) {
+        ID3DXFont_Release(g_metrics.font);
+        ID3DXFont_Release(g_metrics.smallFont);
+        return false;
+    }
+    
+    g_metrics.resourcesInitialized = true;
+    return true;
+}
+
+void DrawGraph(IDirect3DDevice9* device) {
+    // Draw the frame time graph
+    D3DXVECTOR2 points[MAX_SAMPLES];
+    float xStep = (float)GRAPH_WIDTH / (MAX_SAMPLES - 1);
+    
+    // Find min/max times in current sample range
+    double minTime = g_metrics.frameTimes[0];
+    double maxTime = g_metrics.frameTimes[0];
+    for (int i = 0; i < g_metrics.sampleCount; i++) {
+        int idx = (g_metrics.currentIndex - g_metrics.sampleCount + i + MAX_SAMPLES) % MAX_SAMPLES;
+        double time = g_metrics.frameTimes[idx];
+        minTime = min(minTime, time);
+        maxTime = max(maxTime, time); 
+    }
+    
+    // Add small padding to prevent graph from touching edges
+    double padding = (maxTime - minTime) * 0.1;
+    maxTime += padding;
+    minTime = max(0, minTime - padding);
+    
+    float yScale = (float)GRAPH_HEIGHT / (maxTime - minTime);
+    
+    for (int i = 0; i < g_metrics.sampleCount; i++) {
+        int idx = (g_metrics.currentIndex - g_metrics.sampleCount + i + MAX_SAMPLES) % MAX_SAMPLES;
+        points[i].x = GRAPH_X + i * xStep;
+        points[i].y = GRAPH_Y + GRAPH_HEIGHT - (g_metrics.frameTimes[idx] - minTime) * yScale;
+    }
+    
+    ID3DXLine_SetWidth(g_metrics.line, 1.0f);
+    ID3DXLine_Draw(g_metrics.line, points, g_metrics.sampleCount, GRAPH_COLOR);
+}
+
+// TODO add option to have fixed min and max for the Y scale (so that the graph doesn't scale when the frame rate changes)
+// keep this an option though with uncapped to also see really bad frame times on screen
+void DrawOverlay(IDirect3DDevice9* device) {
+    if (!InitializeOverlayResources(device))
+        return;
+    
+    // Draw black background
+    D3DRECT rect = {GRAPH_X, GRAPH_Y - 30, GRAPH_X + GRAPH_WIDTH, GRAPH_Y + GRAPH_HEIGHT};
+    IDirect3DDevice9_Clear(device, 1, &rect, D3DCLEAR_TARGET, D3DCOLOR_ARGB(255, 0, 0, 0), 0, 0);
+    
+    // Draw X and Y axes
+    D3DXVECTOR2 xAxis[] = {
+        { .x = GRAPH_X, .y = GRAPH_Y + GRAPH_HEIGHT },
+        { .x = GRAPH_X + GRAPH_WIDTH, .y = GRAPH_Y + GRAPH_HEIGHT }
+    };
+    
+    D3DXVECTOR2 yAxis[] = {
+        { .x = GRAPH_X, .y = GRAPH_Y },
+        { .x = GRAPH_X, .y = GRAPH_Y + GRAPH_HEIGHT }
+    };
+    
+    ID3DXLine_SetWidth(g_metrics.line, 1.0f);
+    ID3DXLine_Draw(g_metrics.line, xAxis, 2, AXIS_COLOR);
+    ID3DXLine_Draw(g_metrics.line, yAxis, 2, AXIS_COLOR);
+    
+    // Draw X axis labels (time)
+    char buffer[32];
+    RECT textRect;
+    for (int i = 0; i <= 10; i++) {
+        float x = GRAPH_X + (GRAPH_WIDTH * i / 10.0f);
+        sprintf(buffer, "%.1fs", (10.0f - i));
+        textRect.left = (LONG)x - 15;
+        textRect.top = GRAPH_Y + GRAPH_HEIGHT + 5;
+        textRect.right = (LONG)x + 15;
+        textRect.bottom = GRAPH_Y + GRAPH_HEIGHT + 20;
+        ID3DXFont_DrawTextA(g_metrics.smallFont, NULL, buffer, -1, &textRect, DT_CENTER, AXIS_COLOR);
+    }
+
+    // Find min/max times in current sample range
+    double minTime = g_metrics.frameTimes[0];
+    double maxTime = g_metrics.frameTimes[0];
+    for (int i = 0; i < g_metrics.sampleCount; i++) {
+        int idx = (g_metrics.currentIndex - g_metrics.sampleCount + i + MAX_SAMPLES) % MAX_SAMPLES;
+        double time = g_metrics.frameTimes[idx];
+        minTime = min(minTime, time);
+        maxTime = max(maxTime, time); 
+    }
+
+    float yScale = (float)GRAPH_HEIGHT / (maxTime - minTime);
+    
+    // Draw Y axis labels (frame time)
+    for (int i = 0; i <= 8; i++) {
+        float y = GRAPH_Y + GRAPH_HEIGHT - (GRAPH_HEIGHT * i / 8.0f);
+        float ms = minTime + ((maxTime - minTime) * i / 8.0f);
+        sprintf(buffer, "%.1fms", ms);
+        textRect.left = GRAPH_X - 45;
+        textRect.top = (LONG)y - 6;
+        textRect.right = GRAPH_X - 5;
+        textRect.bottom = (LONG)y + 6;
+        ID3DXFont_DrawTextA(g_metrics.smallFont, NULL, buffer, -1, &textRect, DT_RIGHT, AXIS_COLOR);
+    }
+
+    // TODO add some kind of coloring to the frame rate graph/line whenever the line is above or below a certain threshold of the reference line
+
+    // Draw 60 FPS reference line (16.67ms)
+    const float targetFrameTime = 1000.0f/60.0f; // 16.67ms
+    float y60fps = GRAPH_Y + GRAPH_HEIGHT - ((targetFrameTime - minTime) * yScale);
+    
+    // Only draw reference line if it's within the visible range
+    if (targetFrameTime >= minTime && targetFrameTime <= maxTime) {
+        D3DXVECTOR2 refLine[2];
+        refLine[0].x = GRAPH_X;
+        refLine[0].y = y60fps;
+        refLine[1].x = GRAPH_X + GRAPH_WIDTH;
+        refLine[1].y = y60fps;
+        
+        ID3DXLine_SetWidth(g_metrics.line, 1.0f);
+        ID3DXLine_Draw(g_metrics.line, refLine, 2, D3DCOLOR_ARGB(128, 255, 255, 0)); // Semi-transparent yellow
+
+        // Draw reference line label
+        char refBuffer[32];
+        sprintf(refBuffer, "16.67ms (60 FPS)");
+        RECT refTextRect;
+        refTextRect.left = GRAPH_X + GRAPH_WIDTH + 5;
+        refTextRect.top = y60fps - 8;  // Center text vertically with line
+        refTextRect.right = refTextRect.left + 100;
+        refTextRect.bottom = refTextRect.top + 16;
+        ID3DXFont_DrawTextA(g_metrics.smallFont, NULL, refBuffer, -1, &refTextRect, DT_LEFT, D3DCOLOR_ARGB(128, 255, 255, 0));
+    }
+
+    // -------------------------------------------------------------------------
+
+    // Draw the frame time graph
+    D3DXVECTOR2 points[MAX_SAMPLES];
+    float xStep = (float)GRAPH_WIDTH / (MAX_SAMPLES - 1);
+    
+    // Add small padding to prevent graph from touching edges
+    double padding = (maxTime - minTime) * 0.1;
+    maxTime += padding;
+    minTime = max(0, minTime - padding);
+    
+    for (int i = 0; i < g_metrics.sampleCount; i++) {
+        int idx = (g_metrics.currentIndex - g_metrics.sampleCount + i + MAX_SAMPLES) % MAX_SAMPLES;
+        points[i].x = GRAPH_X + i * xStep;
+        points[i].y = GRAPH_Y + GRAPH_HEIGHT - (g_metrics.frameTimes[idx] - minTime) * yScale;
+    }
+    
+    ID3DXLine_SetWidth(g_metrics.line, 1.0f);
+    ID3DXLine_Draw(g_metrics.line, points, g_metrics.sampleCount, GRAPH_COLOR);
+
+    // -------------------------------------------------------------------------
+
+    // Calculate current FPS
+    double currentFrameTime = g_metrics.frameTimes[(g_metrics.currentIndex - 1 + MAX_SAMPLES) % MAX_SAMPLES];
+    double fps = 1000.0 / currentFrameTime;
+    
+    // Draw FPS text
+    sprintf(buffer, "%.3f FPS", fps);
+    textRect.left = GRAPH_X + GRAPH_WIDTH - 100; 
+    textRect.top = GRAPH_Y - 25;
+    textRect.right = GRAPH_X + GRAPH_WIDTH;
+    textRect.bottom = GRAPH_Y - 5;
+    ID3DXFont_DrawTextA(g_metrics.font, NULL, buffer, -1, &textRect, DT_RIGHT, TEXT_COLOR);
+
+    // Draw current frame time in ms
+    sprintf(buffer, "%.3f ms", currentFrameTime);
+    textRect.left = GRAPH_X + GRAPH_WIDTH - 200; // Position to the left of FPS
+    textRect.top = GRAPH_Y - 25;
+    textRect.right = GRAPH_X + GRAPH_WIDTH - 110; // Leave space for FPS text
+    textRect.bottom = GRAPH_Y - 5;
+    ID3DXFont_DrawTextA(g_metrics.font, NULL, buffer, -1, &textRect, DT_RIGHT, TEXT_COLOR);
+
+    // TODO draw derivation graph and average derivation time over the current frame scope
+    
+    // Draw "Framerate" label
+    textRect.left = GRAPH_X;
+    textRect.top = GRAPH_Y - 25;
+    textRect.right = GRAPH_X + 100;
+    textRect.bottom = GRAPH_Y - 5;
+    ID3DXFont_DrawTextA(g_metrics.font, NULL, "Framerate", -1, &textRect, DT_LEFT, TEXT_COLOR);
+}
+
+// Hooked Present function
+void DrawFrameGraph(IDirect3DDevice9* device) {
+    
+    static uint64_t lastTime = 0;
+    uint64_t currentTime = time_get_counter();
+    
+    if (lastTime != 0) {
+        uint64_t frameTime = currentTime - lastTime;
+        double frameTimeMs = time_get_elapsed_us(frameTime) / 1000.0;
+        UpdateMetrics(frameTimeMs);
+    }
+    
+    lastTime = currentTime;
+    
+    //IDirect3DDevice9_BeginScene(device);
+    DrawOverlay(device);
+    //IDirect3DDevice9_EndScene(device);
+}

src/main/iidxhook-util/frame-graph.h

@@ -0,0 +1,10 @@
+#ifndef IIDXHOOK_FRAME_GRAPH_H
+#define IIDXHOOK_FRAME_GRAPH_H
+
+#include <windows.h>
+#include <d3d9.h>
+#include <d3dx9.h>
+
+void DrawFrameGraph(IDirect3DDevice9* device);
+
+#endif

src/main/iidxhook-util/log-server.c

@@ -118,15 +118,15 @@ log_post(char level, const char *module, const char *fmt, va_list ap)
 {
     // TODO test if this addresses performance issues and stuttering
     // TODO measure time how long waiting takes here?
-    // if (WaitForSingleObject(log_rv_producer, INFINITE)) {
+    if (WaitForSingleObject(log_rv_producer, INFINITE)) {
-    //     return;
+        return;
-    // }
+    }
 
-    // log_rv_level = level;
+    log_rv_level = level;
-    // log_rv_module = module;
+    log_rv_module = module;
-    // str_vformat(log_rv_buffer, sizeof(log_rv_buffer), fmt, ap);
+    str_vformat(log_rv_buffer, sizeof(log_rv_buffer), fmt, ap);
 
-    // ReleaseSemaphore(log_rv_consumer, 1, NULL);
+    ReleaseSemaphore(log_rv_consumer, 1, NULL);
 }
 
 #define LOG_POST_IMPL(name, level)                             \

src/main/iidxhook3/Module.mk

@@ -6,6 +6,7 @@ ldflags_iidxhook3   := \
 
 libs_iidxhook3      := \
     iidxhook-util \
+    iidxhook-d3d9 \
     ezusb-emu \
     ezusb-iidx-16seg-emu \
     ezusb2-emu \

src/main/iidxhook3/dllmain.c

@@ -27,6 +27,8 @@
 #include "hooklib/rs232.h"
 #include "hooklib/setupapi.h"
 
+#include "iidxhook-d3d9/frame-pace.h"
+
 #include "iidxhook-util/acio.h"
 #include "iidxhook-util/chart-patch.h"
 #include "iidxhook-util/clock.h"
@@ -52,6 +54,9 @@
 
 static const hook_d3d9_irp_handler_t iidxhook_d3d9_handlers[] = {
     iidxhook_util_d3d9_irp_handler,
+    // Order is important for performance, frame pacing must come at the very end
+    // to include all timings from any prior hooks
+    //iidxhook_d3d9_frame_pace_d3d9_irp_handler,
 };
 
 static HANDLE STDCALL my_OpenProcess(DWORD, BOOL, DWORD);
@@ -69,6 +74,8 @@ iidxhook3_setup_d3d9_hooks(const struct iidxhook_config_gfx *config_gfx)
 {
     struct iidxhook_util_d3d9_config d3d9_config;
 
+    iidxhook_d3d9_frame_pace_init(GetCurrentThreadId(), 60.0);
+
     iidxhook_util_d3d9_init_config(&d3d9_config);
 
     d3d9_config.windowed = config_gfx->windowed;
@@ -246,8 +253,7 @@ skip:
 BOOL WINAPI DllMain(HMODULE mod, DWORD reason, void *ctx)
 {
     if (reason == DLL_PROCESS_ATTACH) {
-        // TODO switched to null writer to see if it addresses performance issues
+        log_to_writer(log_writer_debug, NULL);
-        log_to_writer(log_writer_null, NULL);
 
         /* Bootstrap hook for further init tasks (see above) */