From 7a3786a598236a638facf1755fcfcef791131938 Mon Sep 17 00:00:00 2001 From: Adam Malczewski Date: Mon, 15 Jun 2026 05:40:30 +0900 Subject: spike(kernel): Stage-0 perf instrumentation (per-phase split + GPU timer) Closes out Phase 0 with the measurement that explains the ~30fps: a per-frame budget breakdown and a non-blocking GPU timer query. - GlBridge: load EXT_disjoint_timer_query (glGenQueriesEXT/Begin/End/ GetQueryObject*), gated by the GL extension string; report gpu_timer in the bring-up line. Absent -> graceful 'n/a'. - PresentTarget::render(ctx, RenderTimings*): time clear/update/render-submit/ present (CPU wall-clock) and bracket ctx->Render() with a 2-deep timer-query ring read back a frame late, so the REAL GPU fill time is measured without a glFinish stall. delete_queries in teardown. - composite_frame: time the import+layout loop; accumulate all phases; emit a [perf-split] line (per-rendered-frame averages) alongside [perf]. Result (headless 1080p, Haswell+crocus == CF-AX3 GPU class): CPU work ~2ms (import 0.7 / update 0.7 / render-submit 0.8), GPU fill (ctx->Render) ~10-15ms, present dominated by the blocking fence wait. -> fill-bound; the whole-output composite is the wall. Damage limiting is the lever, to be built properly in the Phase 1 compositor (not hacked into this throwaway). --verify ALL PASS, kernel suite green. --- .../kernel/src/spike/rml_compositing_spike_run.cpp | 45 +++++++++- packages/kernel/src/spike/spike_gl.hpp | 99 +++++++++++++++++++++- 2 files changed, 140 insertions(+), 4 deletions(-) diff --git a/packages/kernel/src/spike/rml_compositing_spike_run.cpp b/packages/kernel/src/spike/rml_compositing_spike_run.cpp index eb27123..189582a 100644 --- a/packages/kernel/src/spike/rml_compositing_spike_run.cpp +++ b/packages/kernel/src/spike/rml_compositing_spike_run.cpp @@ -327,6 +327,18 @@ struct Runner { int frames_skipped_idle = 0; double last_report = 0.0; + // Stage-0 per-phase budget accumulators (summed per rendered frame, averaged + // and reset in the ~1s [perf] report). `import` = client buffer re-import + + // element layout; the rest come from PresentTarget::render's RenderTimings. + // gpu_ms is summed only over frames that produced a timer-query result. + double sum_import_ms = 0.0; + double sum_clear_ms = 0.0; + double sum_update_ms = 0.0; + double sum_render_ms = 0.0; + double sum_present_ms = 0.0; + double sum_gpu_ms = 0.0; + int gpu_samples = 0; + // Commit/present heartbeat (criterion B): a count of output commits so the // log shows the present loop is actually ticking even on a static scene. long commits = 0; @@ -609,6 +621,7 @@ auto composite_frame(Runner& r, bool force) -> double { const double t0 = spike::now_sec(); const bool cur = r.gl.make_current(); + const double t_import0 = spike::now_sec(); for (LiveSurface& s : r.surfaces) { if (!s.mapped || s.surface == nullptr) { continue; @@ -646,7 +659,9 @@ auto composite_frame(Runner& r, bool force) -> double { layout_surface_element(r, s); } } - wlr_buffer* presented = r.present.render(r.ctx); + const double t_import_ms = (spike::now_sec() - t_import0) * 1000.0; + spike::RenderTimings tm; + wlr_buffer* presented = r.present.render(r.ctx, &tm); if (cur) { r.gl.restore_current(); } @@ -654,6 +669,16 @@ auto composite_frame(Runner& r, bool force) -> double { wlr_scene_buffer_set_buffer(r.present_node, presented); } + r.sum_import_ms += t_import_ms; + r.sum_clear_ms += tm.clear_ms; + r.sum_update_ms += tm.update_ms; + r.sum_render_ms += tm.render_ms; + r.sum_present_ms += tm.present_ms; + if (tm.gpu_ms >= 0.0) { + r.sum_gpu_ms += tm.gpu_ms; + ++r.gpu_samples; + } + const double dt_ms = (spike::now_sec() - t0) * 1000.0; r.frame_ms.push_back(dt_ms); ++r.frames_rendered; @@ -1276,6 +1301,24 @@ void on_frame(Runner& r) { "(~%.0f fps budget)", r.frames_rendered, r.frames_skipped_idle, r.commits, avg, p95, v.back(), avg > 0 ? 1000.0 / avg : 0.0); + // Stage-0 budget split (per-rendered-frame averages over this window). + // CPU phases are submit wall-clock; gpu= is the REAL GPU fill from a timer + // query (the number that tells us if we're fill-bound and damage limiting + // will pay off). 'n/a' if EXT_disjoint_timer_query is unavailable. + const std::size_t nf = v.size(); + char gpu[24]; + if (r.gpu_samples > 0) { + std::snprintf(gpu, sizeof(gpu), "%.2fms", r.sum_gpu_ms / r.gpu_samples); + } else { + std::snprintf(gpu, sizeof(gpu), "n/a"); + } + slog("[perf-split] per-frame CPU: import=%.2f clear=%.2f update=%.2f render=%.2f " + "present=%.2f ms | GPU fill (ctx->Render)=%s", + r.sum_import_ms / nf, r.sum_clear_ms / nf, r.sum_update_ms / nf, r.sum_render_ms / nf, + r.sum_present_ms / nf, gpu); + r.sum_import_ms = r.sum_clear_ms = r.sum_update_ms = 0.0; + r.sum_render_ms = r.sum_present_ms = r.sum_gpu_ms = 0.0; + r.gpu_samples = 0; r.frame_ms.clear(); r.last_report = t; (void)dt; diff --git a/packages/kernel/src/spike/spike_gl.hpp b/packages/kernel/src/spike/spike_gl.hpp index 6efef85..1ad6819 100644 --- a/packages/kernel/src/spike/spike_gl.hpp +++ b/packages/kernel/src/spike/spike_gl.hpp @@ -119,6 +119,17 @@ struct GlBridge { PFNEGLCLIENTWAITSYNCKHRPROC wait_sync = nullptr; PFNEGLDESTROYSYNCKHRPROC destroy_sync = nullptr; + // GPU timer queries (EXT_disjoint_timer_query) — Stage-0 perf instrumentation. + // Used to measure the REAL GPU cost of ctx->Render() without a glFinish stall + // (results read back a frame late, non-blocking). nullptr/false when absent. + bool timer_ok = false; + PFNGLGENQUERIESEXTPROC gen_queries = nullptr; + PFNGLDELETEQUERIESEXTPROC delete_queries = nullptr; + PFNGLBEGINQUERYEXTPROC begin_query = nullptr; + PFNGLENDQUERYEXTPROC end_query = nullptr; + PFNGLGETQUERYOBJECTUIVEXTPROC get_query_uiv = nullptr; + PFNGLGETQUERYOBJECTUI64VEXTPROC get_query_ui64v = nullptr; + auto make_current() -> bool { saved_ctx = eglGetCurrentContext(); saved_draw = eglGetCurrentSurface(EGL_DRAW); @@ -177,6 +188,23 @@ struct GlBridge { fence_ok = exts != nullptr && std::strstr(exts, "EGL_KHR_fence_sync") != nullptr && create_sync != nullptr && wait_sync != nullptr && destroy_sync != nullptr; + gen_queries = + reinterpret_cast(eglGetProcAddress("glGenQueriesEXT")); + delete_queries = + reinterpret_cast(eglGetProcAddress("glDeleteQueriesEXT")); + begin_query = + reinterpret_cast(eglGetProcAddress("glBeginQueryEXT")); + end_query = reinterpret_cast(eglGetProcAddress("glEndQueryEXT")); + get_query_uiv = reinterpret_cast( + eglGetProcAddress("glGetQueryObjectuivEXT")); + get_query_ui64v = reinterpret_cast( + eglGetProcAddress("glGetQueryObjectui64vEXT")); + const char* gl_exts = reinterpret_cast(glGetString(GL_EXTENSIONS)); + timer_ok = gl_exts != nullptr && + std::strstr(gl_exts, "GL_EXT_disjoint_timer_query") != nullptr && + gen_queries != nullptr && delete_queries != nullptr && begin_query != nullptr && + end_query != nullptr && get_query_uiv != nullptr && get_query_ui64v != nullptr; + if (!RmlGL3::Initialize(nullptr)) { restore_current(); return false; @@ -198,8 +226,8 @@ struct GlBridge { } restore_current(); ok = true; - std::fprintf(stderr, "[spike] GL bridge up (dmabuf_import=%d fence=%d)\n", dmabuf_ok, - fence_ok); + std::fprintf(stderr, "[spike] GL bridge up (dmabuf_import=%d fence=%d gpu_timer=%d)\n", + dmabuf_ok, fence_ok, timer_ok); return true; } @@ -384,6 +412,18 @@ struct LiveTexture { }; // --- The RmlUi-FBO -> wlr_buffer present target (criterion 7) ----------------- +// Stage-0 per-frame budget breakdown (milliseconds). CPU phases are wall-clock +// around the GL calls (the submit cost, not the GPU work); `gpu_ms` is the REAL +// GPU time of ctx->Render() from a timer query, read back a frame late so it +// never stalls the pipeline (-1 until the first result lands / if unsupported). +struct RenderTimings { + double clear_ms = 0.0; + double update_ms = 0.0; + double render_ms = 0.0; // CPU submit time of BeginFrame+Render+EndFrame + double present_ms = 0.0; + double gpu_ms = -1.0; +}; + struct PresentTarget { GlBridge* gl = nullptr; wlr_allocator* allocator = nullptr; @@ -395,6 +435,14 @@ struct PresentTarget { wlr_swapchain* swapchain = nullptr; std::unordered_map> slot_gl; + // GPU timer-query ring (2-deep): begin/end around ctx->Render() each frame, + // read the OTHER slot's result non-blocking so the answer is one frame late + // but never serializes the GPU. last_gpu_ms holds the most recent reading. + GLuint gpu_q[2] = {0, 0}; + bool gpu_q_active[2] = {false, false}; + int gpu_q_write = 0; + double last_gpu_ms = -1.0; + DataBuffer* shm = nullptr; std::vector readback; @@ -406,6 +454,9 @@ struct PresentTarget { width = w; height = h; glGenFramebuffers(1, &fbo); + if (gl->timer_ok) { + gl->gen_queries(2, gpu_q); + } if (gl->dmabuf_ok && (allocator->buffer_caps & WLR_BUFFER_CAP_DMABUF) != 0) { wlr_drm_format fmt{}; fmt.format = kArgb8888; @@ -437,7 +488,7 @@ struct PresentTarget { return true; } - auto render(Rml::Context* ctx) -> wlr_buffer* { + auto render(Rml::Context* ctx, RenderTimings* tm = nullptr) -> wlr_buffer* { GLuint target = fbo; wlr_buffer* dmabuf_target = nullptr; if (dmabuf) { @@ -491,16 +542,49 @@ struct PresentTarget { glBindFramebuffer(GL_FRAMEBUFFER, 0); } + const double t_clear0 = now_sec(); gl->render->SetViewport(width, height); gl->render->SetOutputFramebuffer(target, /*flip_y=*/true); glBindFramebuffer(GL_FRAMEBUFFER, target); glClearColor(0.f, 0.f, 0.f, 0.f); glClear(GL_COLOR_BUFFER_BIT); glBindFramebuffer(GL_FRAMEBUFFER, 0); + + const double t_update0 = now_sec(); ctx->Update(); + + // Drain the previous frame's GPU timer (non-blocking) before opening a new + // one, then bracket the actual draw (BeginFrame..EndFrame == the fill). + if (gl->timer_ok) { + const int prev = gpu_q_write ^ 1; + if (gpu_q_active[prev]) { + GLuint avail = 0; + gl->get_query_uiv(gpu_q[prev], GL_QUERY_RESULT_AVAILABLE_EXT, &avail); + if (avail != 0) { + GLuint64 ns = 0; + gl->get_query_ui64v(gpu_q[prev], GL_QUERY_RESULT_EXT, &ns); + last_gpu_ms = static_cast(ns) / 1.0e6; + gpu_q_active[prev] = false; + } + } + gl->begin_query(GL_TIME_ELAPSED_EXT, gpu_q[gpu_q_write]); + } + const double t_render0 = now_sec(); gl->render->BeginFrame(); ctx->Render(); gl->render->EndFrame(); + if (gl->timer_ok) { + gl->end_query(GL_TIME_ELAPSED_EXT); + gpu_q_active[gpu_q_write] = true; + gpu_q_write ^= 1; + } + const double t_present0 = now_sec(); + if (tm != nullptr) { + tm->clear_ms = (t_update0 - t_clear0) * 1000.0; + tm->update_ms = (t_render0 - t_update0) * 1000.0; + tm->render_ms = (t_present0 - t_render0) * 1000.0; + tm->gpu_ms = last_gpu_ms; + } if (dmabuf) { gl->submit_sync(); @@ -508,6 +592,9 @@ struct PresentTarget { wlr_scene_buffer_set_buffer(scene_buffer, dmabuf_target); } wlr_buffer_unlock(dmabuf_target); + if (tm != nullptr) { + tm->present_ms = (now_sec() - t_present0) * 1000.0; + } return dmabuf_target; } glBindFramebuffer(GL_FRAMEBUFFER, fbo); @@ -523,6 +610,9 @@ struct PresentTarget { if (scene_buffer != nullptr) { wlr_scene_buffer_set_buffer(scene_buffer, &shm->base); } + if (tm != nullptr) { + tm->present_ms = (now_sec() - t_present0) * 1000.0; + } return &shm->base; } @@ -542,6 +632,9 @@ struct PresentTarget { } } slot_gl.clear(); + if (gl != nullptr && gl->timer_ok && gpu_q[0] != 0) { + gl->delete_queries(2, gpu_q); + } if (shm_tex != 0) { glDeleteTextures(1, &shm_tex); } -- cgit v1.2.3