Merge pull request #5098 from aws-lumberyard-dev/Atom/santorac/ShaderReloadDebugImprovements

Made some improvements for debugging shader hot reload issues.

Made ShaderReloadDebugTracker store its static data in Environment system variables, so they are shared across dlls. This fixes issues with inconsistent indenting when debug operations are performed in different libraries.
New ShaderReloadDebugTracker operations in FullscreenTrianglePass.
Added a ShaderReloadDebugTracker message to Shader::GetVariant that includes asset built timestamp infromation, which I think will be really helpful in sorting out reload issues.
Renamed some functions and variables to remove a redundant "ShaderAsset" term.

Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/Shader.h

@@ -154,6 +154,8 @@ namespace AZ
 
             ConstPtr<RHI::PipelineLibraryData> LoadPipelineLibrary() const;
             void SavePipelineLibrary() const;
+            
+            const ShaderVariant& GetVariantInternal(ShaderVariantStableId shaderVariantStableId);
 
             ///////////////////////////////////////////////////////////////////
             /// AssetBus overrides

Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h

@@ -24,6 +24,9 @@ namespace AZ
         class ShaderReloadDebugTracker final
         {
         public:
+            static void Init();
+            static void Shutdown();
+
             static bool IsEnabled();
 
             //! Begin a code section. Will print a "[BEGIN] <sectionName>" header, and all subsequent calls will be indented.
@@ -34,8 +37,8 @@ namespace AZ
                 if (IsEnabled())
                 {
                     const AZStd::string sectionName = AZStd::string::format(sectionNameFormat, args...);
-                    AZ_TracePrintf("ShaderReloadDebug", "%*s [BEGIN] %s \n", s_indent, "", sectionName.c_str());
-                    s_indent += IndentSpaces;
+                    AZ_TracePrintf("ShaderReloadDebug", "%*s [BEGIN] %s \n", GetIndent(), "", sectionName.c_str());
+                    AddIndent();
                 }
 #endif
             }
@@ -48,8 +51,8 @@ namespace AZ
                 if (IsEnabled())
                 {
                     const AZStd::string sectionName = AZStd::string::format(sectionNameFormat, args...);
-                    s_indent -= IndentSpaces;
-                    AZ_TracePrintf("ShaderReloadDebug", "%*s [_END_] %s \n", s_indent, "", sectionName.c_str());
+                    RemoveIndent();
+                    AZ_TracePrintf("ShaderReloadDebug", "%*s [_END_] %s \n", GetIndent(), "", sectionName.c_str());
                 }
 #endif
             }
@@ -63,7 +66,7 @@ namespace AZ
                 {
                     const AZStd::string message = AZStd::string::format(format, args...);
 
-                    AZ_TracePrintf("ShaderReloadDebug", "%*s %s \n", s_indent, "", message.c_str());
+                    AZ_TracePrintf("ShaderReloadDebug", "%*s %s \n", GetIndent(), "", message.c_str());
                 }
 #endif
             }
@@ -86,9 +89,12 @@ namespace AZ
             };
 
         private:
-            static bool s_enabled;
-            static int s_indent;
             static constexpr int IndentSpaces = 4;
+
+            static void MakeReady();
+            static void AddIndent();
+            static void RemoveIndent();
+            static int GetIndent();
         };
 
     } // namespace RPI

Gems/Atom/RPI/Code/Include/Atom/RPI.Reflect/Shader/ShaderAsset.h

@@ -96,7 +96,7 @@ namespace AZ
 
             //! Return the timestamp when the shader asset was built.
             //! This is used to synchronize versions of the ShaderAsset and ShaderVariantTreeAsset, especially during hot-reload.
-            AZStd::sys_time_t GetShaderAssetBuildTimestamp() const;
+            AZStd::sys_time_t GetBuildTimestamp() const;
 
             //! Returns the shader option group layout.
             const ShaderOptionGroupLayout* GetShaderOptionGroupLayout() const;
@@ -297,7 +297,7 @@ namespace AZ
             Name m_drawListName;
 
             //! Use to synchronize versions of the ShaderAsset and ShaderVariantTreeAsset, especially during hot-reload.
-            AZStd::sys_time_t m_shaderAssetBuildTimestamp = 0; 
+            AZStd::sys_time_t m_buildTimestamp = 0; 
 
 
             ///////////////////////////////////////////////////////////////////

Gems/Atom/RPI/Code/Source/RPI.Public/Pass/FullscreenTrianglePass.cpp

@@ -9,6 +9,7 @@
 #include <Atom/RPI.Public/Pass/FullscreenTrianglePass.h>
 #include <Atom/RPI.Public/Pass/PassUtils.h>
 #include <Atom/RPI.Public/RPIUtils.h>
+#include <Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h>
 
 #include <Atom/RPI.Reflect/Pass/FullscreenTrianglePassData.h>
 #include <Atom/RPI.Reflect/Pass/PassTemplate.h>
@@ -46,16 +47,19 @@ namespace AZ
 
         void FullscreenTrianglePass::OnShaderReinitialized(const Shader&)
         {
+            ShaderReloadDebugTracker::ScopedSection reloadSection("{%p}->FullscreenTrianglePass::OnShaderReinitialized", this);
             LoadShader();
         }
 
         void FullscreenTrianglePass::OnShaderAssetReinitialized(const Data::Asset<ShaderAsset>&)
         {
+            ShaderReloadDebugTracker::ScopedSection reloadSection("{%p}->FullscreenTrianglePass::OnShaderAssetReinitialized", this);
             LoadShader();
         }
 
         void FullscreenTrianglePass::OnShaderVariantReinitialized(const ShaderVariant&)
         {
+            ShaderReloadDebugTracker::ScopedSection reloadSection("{%p}->FullscreenTrianglePass::OnShaderVariantReinitialized", this);
             LoadShader();
         }
 
@@ -129,6 +133,8 @@ namespace AZ
         void FullscreenTrianglePass::InitializeInternal()
         {
             RenderPass::InitializeInternal();
+            
+            ShaderReloadDebugTracker::ScopedSection reloadSection("{%p}->FullscreenTrianglePass::InitializeInternal", this);
 
             // This draw item purposefully does not reference any geometry buffers.
             // Instead it's expected that the extended class uses a vertex shader 

Gems/Atom/RPI/Code/Source/RPI.Public/Shader/Shader.cpp

@@ -320,6 +320,30 @@ namespace AZ
         }
 
         const ShaderVariant& Shader::GetVariant(ShaderVariantStableId shaderVariantStableId)
+        {
+            const ShaderVariant& variant = GetVariantInternal(shaderVariantStableId);
+            
+            if (ShaderReloadDebugTracker::IsEnabled())
+            {
+                auto makeTimeString = [](AZStd::sys_time_t timestamp, AZStd::sys_time_t now)
+                {
+                    AZStd::sys_time_t elapsedMicroseconds = now - timestamp;
+                    double elapsedSeconds = aznumeric_cast<double>(elapsedMicroseconds / 1'000'000);
+                    AZStd::string timeString = AZStd::string::format("%lld (%f seconds ago)", timestamp, elapsedSeconds);
+                    return timeString;
+                };
+
+                AZStd::sys_time_t now = AZStd::GetTimeNowMicroSecond();
+
+                ShaderReloadDebugTracker::Printf("{%p}->Shader::GetVariant for shader '%s' [build time %s] found variant '%s' [build time %s]", this,
+                    m_asset.GetHint().c_str(), makeTimeString(m_asset->GetBuildTimestamp(), now).c_str(),
+                    variant.GetShaderVariantAsset().GetHint().c_str(), makeTimeString(variant.GetShaderVariantAsset()->GetBuildTimestamp(), now).c_str());
+            }
+
+            return variant;
+        }
+
+        const ShaderVariant& Shader::GetVariantInternal(ShaderVariantStableId shaderVariantStableId)
         {
             if (!shaderVariantStableId.IsValid() || shaderVariantStableId == ShaderAsset::RootShaderVariantStableId)
             {
@@ -336,7 +360,7 @@ namespace AZ
                     // reloaded, but some (or all) shader variants haven't been built yet. Since we want to use the latest version of the
                     // shader code, ignore the old variants and fall back to the newer root variant instead. There's no need to report a
                     // warning here because m_asset->GetVariant below will report one.
-                    if (findIt->second.GetBuildTimestamp() >= m_asset->GetShaderAssetBuildTimestamp())
+                    if (findIt->second.GetBuildTimestamp() >= m_asset->GetBuildTimestamp())
                     {
                         return findIt->second;
                     }
@@ -359,7 +383,7 @@ namespace AZ
             auto findIt = m_shaderVariants.find(shaderVariantStableId);
             if (findIt != m_shaderVariants.end())
             {
-                if (findIt->second.GetBuildTimestamp() >= m_asset->GetShaderAssetBuildTimestamp())
+                if (findIt->second.GetBuildTimestamp() >= m_asset->GetBuildTimestamp())
                 {
                     return findIt->second;
                 }

Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderReloadDebugTracker.cpp

@@ -7,24 +7,75 @@
  */
 
 #include <Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h>
+#include <AzCore/Module/Environment.h>
 
 namespace AZ
 {
     namespace RPI
     {
-        bool ShaderReloadDebugTracker::s_enabled = false;
-        int ShaderReloadDebugTracker::s_indent = 0;
+        namespace ShaderReloadDebugTrackerInternal
+        {
+            static const char EnabledVariableName[] = "ShaderReloadDebugTracker enabled";
+            static const char IndentVariableName[] = "ShaderReloadDebugTracker indent";
+
+            static EnvironmentVariable<bool> s_enabled;
+            static EnvironmentVariable<int> s_indent;
+        }
+
+        void ShaderReloadDebugTracker::Init()
+        {
+            ShaderReloadDebugTrackerInternal::s_enabled = AZ::Environment::CreateVariable<bool>(ShaderReloadDebugTrackerInternal::EnabledVariableName);
+            ShaderReloadDebugTrackerInternal::s_indent = AZ::Environment::CreateVariable<int>(ShaderReloadDebugTrackerInternal::IndentVariableName);
+
+            ShaderReloadDebugTrackerInternal::s_enabled.Get() = false;
+            ShaderReloadDebugTrackerInternal::s_indent.Get() = 0;
+        }
+
+        void ShaderReloadDebugTracker::Shutdown()
+        {
+            ShaderReloadDebugTrackerInternal::s_enabled.Reset();
+            ShaderReloadDebugTrackerInternal::s_indent.Reset();
+        }
+        
+        void ShaderReloadDebugTracker::MakeReady()
+        {
+            if (!ShaderReloadDebugTrackerInternal::s_enabled.IsValid())
+            {
+                ShaderReloadDebugTrackerInternal::s_enabled = AZ::Environment::FindVariable<bool>(ShaderReloadDebugTrackerInternal::EnabledVariableName);
+                ShaderReloadDebugTrackerInternal::s_indent = AZ::Environment::FindVariable<int>(ShaderReloadDebugTrackerInternal::IndentVariableName);
+            }
+        }
 
         bool ShaderReloadDebugTracker::IsEnabled()
         {
 #ifdef AZ_ENABLE_SHADER_RELOAD_DEBUG_TRACKER
+            MakeReady();
+
             // Set this to true in the debugger to turn on hot reload tracing.
             // If needed, we could hook this up to a CVar.
-            return s_enabled;
+            return ShaderReloadDebugTrackerInternal::s_enabled.Get();
 #else
             return false;
 #endif
         }
+        
+        void ShaderReloadDebugTracker::AddIndent()
+        {
+            MakeReady();
+            ShaderReloadDebugTrackerInternal::s_indent.Get() += IndentSpaces;
+        }
+
+        void ShaderReloadDebugTracker::RemoveIndent()
+        {
+            MakeReady();
+            ShaderReloadDebugTrackerInternal::s_indent.Get() -= IndentSpaces;
+        }
+        
+        int ShaderReloadDebugTracker::GetIndent()
+        {
+            MakeReady();
+            return ShaderReloadDebugTrackerInternal::s_indent.Get();
+        }
 
         ShaderReloadDebugTracker::ScopedSection::~ScopedSection()
         {

Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderSystem.cpp

@@ -10,6 +10,7 @@
 #include <Atom/RPI.Public/Shader/Shader.h>
 #include <Atom/RPI.Public/Shader/ShaderResourceGroup.h>
 #include <Atom/RPI.Public/Shader/ShaderResourceGroupPool.h>
+#include <Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h>
 
 #include <Atom/RPI.Reflect/Asset/AssetHandler.h>
 #include <Atom/RPI.Reflect/Asset/AssetUtils.h>
@@ -86,10 +87,13 @@ namespace AZ
                 };
                 Data::InstanceDatabase<ShaderResourceGroupPool>::Create(azrtti_typeid<ShaderResourceGroupPool>(), handler, false);
             }
+
+            ShaderReloadDebugTracker::Init();
         }
 
         void ShaderSystem::Shutdown()
         {
+            ShaderReloadDebugTracker::Shutdown();
             Data::InstanceDatabase<Shader>::Destroy();
             Data::InstanceDatabase<ShaderResourceGroup>::Destroy();
             Data::InstanceDatabase<ShaderResourceGroupPool>::Destroy();

Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAsset.cpp

@@ -100,7 +100,7 @@ namespace AZ
                     ->Field("pipelineStateType", &ShaderAsset::m_pipelineStateType)
                     ->Field("shaderOptionGroupLayout", &ShaderAsset::m_shaderOptionGroupLayout)
                     ->Field("drawListName", &ShaderAsset::m_drawListName)
-                    ->Field("shaderAssetBuildTimestamp", &ShaderAsset::m_shaderAssetBuildTimestamp)
+                    ->Field("shaderAssetBuildTimestamp", &ShaderAsset::m_buildTimestamp)
                     ->Field("perAPIShaderData", &ShaderAsset::m_perAPIShaderData)
                     ;
             }
@@ -134,11 +134,11 @@ namespace AZ
             return m_drawListName;
         }
 
-        AZStd::sys_time_t ShaderAsset::GetShaderAssetBuildTimestamp() const
+        AZStd::sys_time_t ShaderAsset::GetBuildTimestamp() const
         {
-            return m_shaderAssetBuildTimestamp;
+            return m_buildTimestamp;
         }
-
+        
         void ShaderAsset::SetReady()
         {
             m_status = AssetStatus::Ready;
@@ -256,7 +256,7 @@ namespace AZ
                 }
                 return GetRootVariant(supervariantIndex);
             }
-            else if (variant->GetBuildTimestamp() >= m_shaderAssetBuildTimestamp)
+            else if (variant->GetBuildTimestamp() >= m_buildTimestamp)
             {
                 return variant;
             }

Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAssetCreator.cpp

@@ -21,7 +21,7 @@ namespace AZ
         {
             if (ValidateIsReady())
             {
-                m_asset->m_shaderAssetBuildTimestamp = shaderAssetBuildTimestamp;
+                m_asset->m_buildTimestamp = shaderAssetBuildTimestamp;
             }
         }
 
@@ -390,7 +390,7 @@ namespace AZ
             m_asset->m_pipelineStateType = sourceShaderAsset.m_pipelineStateType;
             m_asset->m_drawListName = sourceShaderAsset.m_drawListName;
             m_asset->m_shaderOptionGroupLayout = sourceShaderAsset.m_shaderOptionGroupLayout;
-            m_asset->m_shaderAssetBuildTimestamp = sourceShaderAsset.m_shaderAssetBuildTimestamp;
+            m_asset->m_buildTimestamp = sourceShaderAsset.m_buildTimestamp;
 
             // copy root variant assets
             for (auto& perAPIShaderData : sourceShaderAsset.m_perAPIShaderData)