From ecae08fa955c7852c87a52f24c46bac215b5b2ea Mon Sep 17 00:00:00 2001 From: santorac <55155825+santorac@users.noreply.github.com> Date: Thu, 28 Oct 2021 12:05:56 -0700 Subject: [PATCH] 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. Signed-off-by: santorac <55155825+santorac@users.noreply.github.com> --- .../Include/Atom/RPI.Public/Shader/Shader.h | 2 + .../Shader/ShaderReloadDebugTracker.h | 20 ++++--- .../Atom/RPI.Reflect/Shader/ShaderAsset.h | 4 +- .../Pass/FullscreenTrianglePass.cpp | 6 ++ .../Code/Source/RPI.Public/Shader/Shader.cpp | 28 ++++++++- .../Shader/ShaderReloadDebugTracker.cpp | 57 ++++++++++++++++++- .../Source/RPI.Public/Shader/ShaderSystem.cpp | 4 ++ .../Source/RPI.Reflect/Shader/ShaderAsset.cpp | 10 ++-- .../RPI.Reflect/Shader/ShaderAssetCreator.cpp | 4 +- 9 files changed, 114 insertions(+), 21 deletions(-) diff --git a/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/Shader.h b/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/Shader.h index e2568f3b61..bae9c4d8cc 100644 --- a/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/Shader.h +++ b/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/Shader.h @@ -154,6 +154,8 @@ namespace AZ ConstPtr LoadPipelineLibrary() const; void SavePipelineLibrary() const; + + const ShaderVariant& GetVariantInternal(ShaderVariantStableId shaderVariantStableId); /////////////////////////////////////////////////////////////////// /// AssetBus overrides diff --git a/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h b/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h index 27c43afd12..dcbc4a5774 100644 --- a/Gems/Atom/RPI/Code/Include/Atom/RPI.Public/Shader/ShaderReloadDebugTracker.h +++ b/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] " 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 diff --git a/Gems/Atom/RPI/Code/Include/Atom/RPI.Reflect/Shader/ShaderAsset.h b/Gems/Atom/RPI/Code/Include/Atom/RPI.Reflect/Shader/ShaderAsset.h index 2c24d6052a..5da990eedb 100644 --- a/Gems/Atom/RPI/Code/Include/Atom/RPI.Reflect/Shader/ShaderAsset.h +++ b/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; /////////////////////////////////////////////////////////////////// diff --git a/Gems/Atom/RPI/Code/Source/RPI.Public/Pass/FullscreenTrianglePass.cpp b/Gems/Atom/RPI/Code/Source/RPI.Public/Pass/FullscreenTrianglePass.cpp index 40dce7d138..0bd32344d6 100644 --- a/Gems/Atom/RPI/Code/Source/RPI.Public/Pass/FullscreenTrianglePass.cpp +++ b/Gems/Atom/RPI/Code/Source/RPI.Public/Pass/FullscreenTrianglePass.cpp @@ -9,6 +9,7 @@ #include #include #include +#include #include #include @@ -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&) { + 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 diff --git a/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/Shader.cpp b/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/Shader.cpp index 51dd9c36d3..bee9200c07 100644 --- a/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/Shader.cpp +++ b/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(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; } diff --git a/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderReloadDebugTracker.cpp b/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderReloadDebugTracker.cpp index 6b97e43cbd..3e7ff826cf 100644 --- a/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderReloadDebugTracker.cpp +++ b/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderReloadDebugTracker.cpp @@ -7,24 +7,75 @@ */ #include +#include 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 s_enabled; + static EnvironmentVariable s_indent; + } + + void ShaderReloadDebugTracker::Init() + { + ShaderReloadDebugTrackerInternal::s_enabled = AZ::Environment::CreateVariable(ShaderReloadDebugTrackerInternal::EnabledVariableName); + ShaderReloadDebugTrackerInternal::s_indent = AZ::Environment::CreateVariable(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(ShaderReloadDebugTrackerInternal::EnabledVariableName); + ShaderReloadDebugTrackerInternal::s_indent = AZ::Environment::FindVariable(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() { diff --git a/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderSystem.cpp b/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderSystem.cpp index ec6aeb3771..2e66aaca99 100644 --- a/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderSystem.cpp +++ b/Gems/Atom/RPI/Code/Source/RPI.Public/Shader/ShaderSystem.cpp @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -86,10 +87,13 @@ namespace AZ }; Data::InstanceDatabase::Create(azrtti_typeid(), handler, false); } + + ShaderReloadDebugTracker::Init(); } void ShaderSystem::Shutdown() { + ShaderReloadDebugTracker::Shutdown(); Data::InstanceDatabase::Destroy(); Data::InstanceDatabase::Destroy(); Data::InstanceDatabase::Destroy(); diff --git a/Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAsset.cpp b/Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAsset.cpp index 84757d58ab..9fa76ac5ee 100644 --- a/Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAsset.cpp +++ b/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; } diff --git a/Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAssetCreator.cpp b/Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAssetCreator.cpp index 87338f2185..5df37aa211 100644 --- a/Gems/Atom/RPI/Code/Source/RPI.Reflect/Shader/ShaderAssetCreator.cpp +++ b/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)