[Test] (MG_Util, MG_State): TEMP stage-timing probes for the async-compile campaign - remove before merge

MobileGL/MG_State/GLState/ProgramState/ProgramLinkTask.cpp

@@ -13,6 +13,7 @@
 #include <MG_Util/Converters/GLToStr/GLEnumConverter.h>
 #include <MG_Util/Converters/MGToGL/ProgramEnumConverter.h>
 #include <MG_Util/Converters/SPIRVCrossToGL/SpvcTypeConverter.h>
+#include <MG_Util/Debug/TempStageProbe.h> // TEMP-STAGE-PROBE
 #include <MG_Util/ShaderTranspiler/ShaderCompiler.h>
 #include <MG_Util/ShaderTranspiler/ShaderSourceProcessor.h>
 #include <MG_Util/ShaderTranspiler/Types.h>
@@ -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<bool>(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);
+            // TEMP-STAGE-PROBE: "spirv-opt" - the spirv-tools optimizer run over every module.
-            MOBILEGL_ASSERT(success, "SanitizeBinary failed");
+            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");
+            }
         }
     }
 

MobileGL/MG_State/GLState/ProgramState/ShaderCompileTask.cpp

@@ -9,6 +9,7 @@
 #include "ShaderCompileTask.h"
 
 #include <MG_Util/Converters/MGToGL/ProgramEnumConverter.h>
+#include <MG_Util/Debug/TempStageProbe.h> // TEMP-STAGE-PROBE
 #include <MG_Util/ShaderTranspiler/ShaderCompiler.h>
 #include <MG_Util/ShaderTranspiler/ShaderSourceProcessor.h>
 #include <MG_Util/ShaderTranspiler/Types.h>
@@ -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<String> 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;

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 <MG_Util/Debug/Log.h>
+
+#include <atomic>
+#include <chrono>
+
+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<unsigned long long> tempStageProbeMicros[kTempStageProbeStageCount] = {};
+    inline std::atomic<unsigned long long> tempStageProbeCalls[kTempStageProbeStageCount] = {};
+    inline std::atomic<unsigned long long> tempStageProbeLinkCount{0};
+    inline std::atomic<long long> 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::microseconds>(
+                                                     std::chrono::steady_clock::now() - tempStageProbeStart)
+                                                     .count();
+            tempStageProbeMicros[tempStageProbeStage].fetch_add(
+                static_cast<unsigned long long>(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::nanoseconds>(
+                    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

MobileGL/MG_Util/ShaderTranspiler/ShaderCompiler.cpp

@@ -32,6 +32,7 @@
 #include <MG_Backend/BackendObjects.h>
 #include <MG_Util/Converters/GLToStr/GLEnumConverter.h>
 #include <MG_Util/Converters/GLToGlslang/ProgramEnumConverter.h>
+#include <MG_Util/Debug/TempStageProbe.h> // TEMP-STAGE-PROBE
 #include <cstdlib>
 
 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",