From 404236d337e09cd2f2c12212b746798c02d5f438 Mon Sep 17 00:00:00 2001 From: Swung0x48 Date: Mon, 10 Aug 2026 05:16:24 -0400 Subject: [PATCH] [Test] (MG_Util, MG_State): TEMP stage-timing probes for the async-compile campaign - remove before merge --- .../GLState/ProgramState/ProgramLinkTask.cpp | 50 ++++++-- .../ProgramState/ShaderCompileTask.cpp | 22 +++- MobileGL/MG_Util/Debug/TempStageProbe.h | 117 ++++++++++++++++++ .../ShaderTranspiler/ShaderCompiler.cpp | 15 ++- 4 files changed, 193 insertions(+), 11 deletions(-) create mode 100644 MobileGL/MG_Util/Debug/TempStageProbe.h diff --git a/MobileGL/MG_State/GLState/ProgramState/ProgramLinkTask.cpp b/MobileGL/MG_State/GLState/ProgramState/ProgramLinkTask.cpp index 681940e2..bffc2083 100644 --- a/MobileGL/MG_State/GLState/ProgramState/ProgramLinkTask.cpp +++ b/MobileGL/MG_State/GLState/ProgramState/ProgramLinkTask.cpp @@ -13,6 +13,7 @@ #include #include #include +#include // TEMP-STAGE-PROBE #include #include #include @@ -293,6 +294,15 @@ namespace MobileGL::MG_State::GLState { const GlslangThreadAllocatorGuard glslangGuard; using namespace MG_Util::ShaderTranspiler; + // TEMP-STAGE-PROBE: "linktask-total" (whole link body, superset of glslang-link / + // spirv-gen / spirv-opt / reflection / spvc-routing / the ConsumeShaders re-parse) + // plus the every-25-links running-total dump of every stage. + // Declared FIRST so it is destroyed LAST: the dump then already includes this link's + // own contribution to every stage, including "linktask-total". + const MG_Util::Debug::TempStageProbeLinkTick tempStageProbeLinkTick; + const MG_Util::Debug::TempStageProbeScope tempStageProbeLinkTask( + MG_Util::Debug::kTempStageProbeLinkTaskTotal); + MOBILEGL_ASSERT(in.env != nullptr, "ProgramLinkTask: the CompileEnv snapshot is missing"); const CompileEnv& env = *in.env; @@ -332,7 +342,12 @@ namespace MobileGL::MG_State::GLState { .explicitOpaqueUniformBindings = &artifacts.explicitOpaqueUniformBindings}; MGLOG_D("ProgramObject %u: Calling ShaderCompiler::LinkProgram", in.externalIndex); - auto result = ShaderCompiler::LinkProgram(attrib); + // TEMP-STAGE-PROBE: "glslang-link" - TProgram::link + mapIO. + auto result = [&] { + const MG_Util::Debug::TempStageProbeScope tempStageProbeGlslangLink( + MG_Util::Debug::kTempStageProbeGlslangLink); + return ShaderCompiler::LinkProgram(attrib); + }(); if (result) { artifacts.linkStatus = true; artifacts.program = result.value(); @@ -375,14 +390,25 @@ namespace MobileGL::MG_State::GLState { GenerateSpirv(); MGLOG_D("ProgramObject %u: Starting reflection", in.externalIndex); - if (!DoReflection(env)) { + // TEMP-STAGE-PROBE: "reflection" - buildReflection + the GL location assignment. + const bool tempStageProbeReflectionOk = [&] { + const MG_Util::Debug::TempStageProbeScope tempStageProbeReflection( + MG_Util::Debug::kTempStageProbeReflection); + return static_cast(DoReflection(env)); + }(); + if (!tempStageProbeReflectionOk) { DeferLog(std::format("ProgramObject {}: Link failed during reflection: {}", in.externalIndex, artifacts.infoLog)); return; } MGLOG_D("ProgramObject %u: Building global-UBO routing tables", in.externalIndex); - BuildGlobalUboRouting(); + { + // TEMP-STAGE-PROBE: "spvc-routing" - the SPIRV-Cross session per SPIR-V module. + const MG_Util::Debug::TempStageProbeScope tempStageProbeSpvcRouting( + MG_Util::Debug::kTempStageProbeSpvcRouting); + BuildGlobalUboRouting(); + } MGLOG_D("ProgramObject %u: Reflection done (linkStatus=%d)", in.externalIndex, (int)artifacts.linkStatus); if (!ValidateFragmentOutputLocations()) { return; @@ -867,7 +893,12 @@ namespace MobileGL::MG_State::GLState { .program = *artifacts.program, }; MGLOG_D("ProgramObject %u: GenerateSpirv - requesting SPIR-V binary from program", in.externalIndex); - auto binaryResult = ShaderCompiler::GetSpirvBinaryFromProgram(binaryAttrib); + // TEMP-STAGE-PROBE: "spirv-gen" - GlslangToSpv for every stage of this program. + auto binaryResult = [&] { + const MG_Util::Debug::TempStageProbeScope tempStageProbeSpirvGen( + MG_Util::Debug::kTempStageProbeSpirvGen); + return ShaderCompiler::GetSpirvBinaryFromProgram(binaryAttrib); + }(); if (!binaryResult) { DeferLog(std::format("ProgramObject {}: GenerateSpirv - GetSpirvBinaryFromProgram failed", in.externalIndex)); @@ -878,9 +909,14 @@ namespace MobileGL::MG_State::GLState { artifacts.generatedSpirv.size()); // Linked SPIR-V generated, sanitize and optimize it - for (auto& spv : artifacts.generatedSpirv) { - auto success = ShaderCompiler::SanitizeAndOptimizeBinary(spv, spv); - MOBILEGL_ASSERT(success, "SanitizeBinary failed"); + { + // TEMP-STAGE-PROBE: "spirv-opt" - the spirv-tools optimizer run over every module. + const MG_Util::Debug::TempStageProbeScope tempStageProbeSpirvOpt( + MG_Util::Debug::kTempStageProbeSpirvOpt); + for (auto& spv : artifacts.generatedSpirv) { + auto success = ShaderCompiler::SanitizeAndOptimizeBinary(spv, spv); + MOBILEGL_ASSERT(success, "SanitizeBinary failed"); + } } } diff --git a/MobileGL/MG_State/GLState/ProgramState/ShaderCompileTask.cpp b/MobileGL/MG_State/GLState/ProgramState/ShaderCompileTask.cpp index 70165f11..7ac9bf1f 100644 --- a/MobileGL/MG_State/GLState/ProgramState/ShaderCompileTask.cpp +++ b/MobileGL/MG_State/GLState/ProgramState/ShaderCompileTask.cpp @@ -9,6 +9,7 @@ #include "ShaderCompileTask.h" #include +#include // TEMP-STAGE-PROBE #include #include #include @@ -155,7 +156,13 @@ namespace { MobileGL::MG_State::GLState::ShaderPreprocessResult result; result.preprocessedSource = source; - PreprocessShaderSource(stage, result.preprocessedSource, env); + { + // TEMP-STAGE-PROBE: "preprocess". Only reached on a ShaderPreprocessCache miss, + // so its call count is the miss count, not the glCompileShader count. + const MobileGL::MG_Util::Debug::TempStageProbeScope tempStageProbePreprocess( + MobileGL::MG_Util::Debug::kTempStageProbePreprocess); + PreprocessShaderSource(stage, result.preprocessedSource, env); + } if (stage == ShaderStage::Compute) { if (const std::optional localSizeError = @@ -207,6 +214,10 @@ namespace MobileGL::MG_State::GLState { // status + log, so turn a throw into exactly that - a completed job whose result // is "this shader did not compile", with a log the application can read. // (JobNode still catches: it is the last resort for anything below.) + // TEMP-STAGE-PROBE: "compiletask-total" - whole ShaderCompileTask body (superset of + // "preprocess" + "parse"); the difference is the task's own bookkeeping. + const MG_Util::Debug::TempStageProbeScope tempStageProbeCompileTask( + MG_Util::Debug::kTempStageProbeCompileTaskTotal); try { RunCompilePipeline(); } catch (const std::exception& e) { @@ -327,7 +338,14 @@ namespace MobileGL::MG_State::GLState { // Re-parse against the SAME environment the original parse used, // not against whatever the backend reports now. .env = artifacts.env.get()}; - auto result = ShaderCompiler::CompileShader(attrib); + // TEMP-STAGE-PROBE: "parse-reparse" - the link-time consume-once re-parse. This goes + // through ShaderCompiler::CompileShader, so it is ALSO counted in "parse"; it is + // recorded separately so the "parse" total can be split into first-parse vs re-parse. + auto result = [&] { + const MG_Util::Debug::TempStageProbeScope tempStageProbeReparse( + MG_Util::Debug::kTempStageProbeParseReparse); + return ShaderCompiler::CompileShader(attrib); + }(); if (!result) { // Should be unreachable: the same source parsed successfully at Compile(). outReparseLog = result.error().log; diff --git a/MobileGL/MG_Util/Debug/TempStageProbe.h b/MobileGL/MG_Util/Debug/TempStageProbe.h new file mode 100644 index 00000000..9537e5cf --- /dev/null +++ b/MobileGL/MG_Util/Debug/TempStageProbe.h @@ -0,0 +1,117 @@ +// MobileGL - MobileGL/MG_Util/Debug/TempStageProbe.h +// Copyright (c) 2025-2026 MobileGL-Dev +// Licensed under the GNU Lesser General Public License v3.0: +// https://www.gnu.org/licenses/gpl-3.0.txt +// https://www.gnu.org/licenses/lgpl-3.0.txt +// SPDX-License-Identifier: LGPL-3.0-only +// End of Source File Header +// +// TEMP-STAGE-PROBE: TEMPORARY instrumentation. Measures the per-stage wall time of the +// shader frontend (preprocess / glslang parse / glslang link+mapIO / SPIR-V generation / +// spirv-tools optimize / reflection / SPIRV-Cross global-UBO routing) so a shaderpack load +// can be attributed stage by stage. Delete this file together with every call site marked +// TEMP-STAGE-PROBE when the measurement is finished. Every identifier is spelled +// tempStageProbe* / TempStageProbe* / kTempStageProbe* so both spellings are greppable. + +#pragma once + +#include + +#include +#include + +namespace MobileGL::MG_Util::Debug { + // TEMP-STAGE-PROBE: stage ids. The two *Total entries are SUPERSETS of the stages above + // them (they time the whole task body), kept so the residue inside a task body is + // visible; kTempStageProbeParseReparse is a SUBSET of kTempStageProbeParse (the link's + // consume-once re-parse goes through the same ShaderCompiler::CompileShader). + enum TempStageProbeStageId : int { + kTempStageProbePreprocess = 0, + kTempStageProbeParse, + kTempStageProbeParseReparse, + kTempStageProbeGlslangLink, + kTempStageProbeSpirvGen, + kTempStageProbeSpirvOpt, + kTempStageProbeReflection, + kTempStageProbeSpvcRouting, + kTempStageProbeCompileTaskTotal, + kTempStageProbeLinkTaskTotal, + kTempStageProbeStageCount + }; + + inline const char* const kTempStageProbeStageNames[kTempStageProbeStageCount] = { + "preprocess", + "parse", + "parse-reparse[subset-of-parse]", + "glslang-link", + "spirv-gen", + "spirv-opt", + "reflection", + "spvc-routing", + "compiletask-total[superset]", + "linktask-total[superset]", + }; + + inline std::atomic tempStageProbeMicros[kTempStageProbeStageCount] = {}; + inline std::atomic tempStageProbeCalls[kTempStageProbeStageCount] = {}; + inline std::atomic tempStageProbeLinkCount{0}; + inline std::atomic tempStageProbeLastDumpNanos{0}; + + // TEMP-STAGE-PROBE: scoped accumulator. Relaxed atomics only - nothing here orders any + // other memory, and the probe must not perturb what it measures. + class TempStageProbeScope { + public: + explicit TempStageProbeScope(int tempStageProbeStageId) + : tempStageProbeStage(tempStageProbeStageId), + tempStageProbeStart(std::chrono::steady_clock::now()) {} + ~TempStageProbeScope() { + const auto tempStageProbeElapsedUs = std::chrono::duration_cast( + std::chrono::steady_clock::now() - tempStageProbeStart) + .count(); + tempStageProbeMicros[tempStageProbeStage].fetch_add( + static_cast(tempStageProbeElapsedUs), std::memory_order_relaxed); + tempStageProbeCalls[tempStageProbeStage].fetch_add(1ull, std::memory_order_relaxed); + } + TempStageProbeScope(const TempStageProbeScope&) = delete; + TempStageProbeScope& operator=(const TempStageProbeScope&) = delete; + + private: + int tempStageProbeStage; + std::chrono::steady_clock::time_point tempStageProbeStart; + }; + + // TEMP-STAGE-PROBE: one MGLOG_I line per stage carrying the running cumulative total. + inline void TempStageProbeDumpTotals(unsigned long long tempStageProbeLinkIndex) { + for (int tempStageProbeIdx = 0; tempStageProbeIdx < kTempStageProbeStageCount; ++tempStageProbeIdx) { + const unsigned long long tempStageProbeUs = + tempStageProbeMicros[tempStageProbeIdx].load(std::memory_order_relaxed); + const unsigned long long tempStageProbeN = + tempStageProbeCalls[tempStageProbeIdx].load(std::memory_order_relaxed); + MGLOG_I("TEMP-STAGE-PROBE: %s total %llu.%03llu ms over %llu calls (after %llu links)", + kTempStageProbeStageNames[tempStageProbeIdx], tempStageProbeUs / 1000ull, + tempStageProbeUs % 1000ull, tempStageProbeN, tempStageProbeLinkIndex); + } + } + + // TEMP-STAGE-PROBE: ticks the program-link counter on scope exit (so a link that returns + // early still counts) and dumps every stage's running total every 25 links. The 3-second + // fallback exists so the LAST link of a load also publishes totals - the process is + // force-stopped afterwards, so there is no exit hook to rely on. + class TempStageProbeLinkTick { + public: + ~TempStageProbeLinkTick() { + const unsigned long long tempStageProbeIndex = + tempStageProbeLinkCount.fetch_add(1ull, std::memory_order_relaxed) + 1ull; + const long long tempStageProbeNowNanos = + std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count(); + const long long tempStageProbeLastNanos = tempStageProbeLastDumpNanos.load(std::memory_order_relaxed); + const bool tempStageProbeDueByCount = (tempStageProbeIndex % 25ull) == 0ull; + const bool tempStageProbeDueByTime = tempStageProbeNowNanos - tempStageProbeLastNanos > 3000000000LL; + if (!tempStageProbeDueByCount && !tempStageProbeDueByTime) return; + tempStageProbeLastDumpNanos.store(tempStageProbeNowNanos, std::memory_order_relaxed); + TempStageProbeDumpTotals(tempStageProbeIndex); + } + }; +} // namespace MobileGL::MG_Util::Debug diff --git a/MobileGL/MG_Util/ShaderTranspiler/ShaderCompiler.cpp b/MobileGL/MG_Util/ShaderTranspiler/ShaderCompiler.cpp index 095fa235..27baf7ff 100644 --- a/MobileGL/MG_Util/ShaderTranspiler/ShaderCompiler.cpp +++ b/MobileGL/MG_Util/ShaderTranspiler/ShaderCompiler.cpp @@ -32,6 +32,7 @@ #include #include #include +#include // TEMP-STAGE-PROBE #include namespace MobileGL { @@ -224,8 +225,18 @@ namespace MobileGL { return std::unexpected(r); } + // TEMP-STAGE-PROBE: "parse" - one glslang TShader::parse. Both the first + // attempt and the legacy-#version retry below go through here, and so does + // ProgramLinkTask's consume-once re-parse (separately counted there as + // "parse-reparse") and ShaderCompiler::PrewarmBuiltins' three warm-up parses. + const auto tempStageProbeParseShaderSource = [&](const String& tempStageProbeSource) { + const MobileGL::MG_Util::Debug::TempStageProbeScope tempStageProbeParse( + MobileGL::MG_Util::Debug::kTempStageProbeParse); + return ParseShaderSource(lang, shaderType, tempStageProbeSource, attrib.flags, attrib.env); + }; + const String source(attrib.sourceStr); - auto result = ParseShaderSource(lang, shaderType, source, attrib.flags, attrib.env); + auto result = tempStageProbeParseShaderSource(source); if (result) return result; // Legacy desktop sources are normalized to "#version 330 core" (with a marker on the @@ -241,7 +252,7 @@ namespace MobileGL { return result; } - auto retryResult = ParseShaderSource(lang, shaderType, retrySource, attrib.flags, attrib.env); + auto retryResult = tempStageProbeParseShaderSource(retrySource); // TEMP-STAGE-PROBE if (!retryResult) return result; MGLOG_D("CompileShader: %s only parsed after retargeting its legacy #version to 460",