Merge pull request #2548 from secondlife/lua-frame-profile

Make Develop->Render Tests->Frame Profile dump JSON to a file too (#2412)

2 files changed, 85 insertions, 46 deletions

diff --git a/indra/llrender/llglslshader.cpp b/indra/llrender/llglslshader.cpp
index a157bfee21..56f1533708 100644
--- a/indra/llrender/llglslshader.cpp
+++ b/indra/llrender/llglslshader.cpp
@@ -41,6 +41,8 @@
 #include "OpenGL/OpenGL.h"
 #endif
 
+#include <fstream>
+
  // Print-print list of shader included source files that are linked together via glAttachShader()
  // i.e. On macOS / OSX the AMD GLSL linker will display an error if a varying is left in an undefined state.
 #define DEBUG_SHADER_INCLUDES 0
@@ -63,6 +65,7 @@ U64 LLGLSLShader::sTotalTimeElapsed = 0;
 U32 LLGLSLShader::sTotalTrianglesDrawn = 0;
 U64 LLGLSLShader::sTotalSamplesDrawn = 0;
 U32 LLGLSLShader::sTotalBinds = 0;
+std::string LLGLSLShader::sDefaultReportName;
 
 //UI shader -- declared here so llui_libtest will link properly
 LLGLSLShader    gUIProgram;
@@ -101,9 +104,9 @@ void LLGLSLShader::initProfile()
     sTotalSamplesDrawn = 0;
     sTotalBinds = 0;
 
-    for (std::set<LLGLSLShader*>::iterator iter = sInstances.begin(); iter != sInstances.end(); ++iter)
+    for (auto ptr : sInstances)
     {
-        (*iter)->clearStats();
+        ptr->clearStats();
     }
 }
 
@@ -117,48 +120,71 @@ struct LLGLSLShaderCompareTimeElapsed
 };
 
 //static
-void LLGLSLShader::finishProfile(bool emit_report)
+void LLGLSLShader::finishProfile(const std::string& report_name)
 {
     sProfileEnabled = false;
 
-    if (emit_report)
+    if (! report_name.empty())
     {
-        std::vector<LLGLSLShader*> sorted;
-
-        for (std::set<LLGLSLShader*>::iterator iter = sInstances.begin(); iter != sInstances.end(); ++iter)
-        {
-            sorted.push_back(*iter);
-        }
-
+        std::vector<LLGLSLShader*> sorted(sInstances.begin(), sInstances.end());
         std::sort(sorted.begin(), sorted.end(), LLGLSLShaderCompareTimeElapsed());
 
+        boost::json::object stats;
+        auto shadersit = stats.emplace("shaders", boost::json::array_kind).first;
+        auto& shaders = shadersit->value().as_array();
         bool unbound = false;
-        for (std::vector<LLGLSLShader*>::iterator iter = sorted.begin(); iter != sorted.end(); ++iter)
+        for (auto ptr : sorted)
         {
-            (*iter)->dumpStats();
-            if ((*iter)->mBinds == 0)
+            if (ptr->mBinds == 0)
             {
                 unbound = true;
             }
+            else
+            {
+                auto& shaderit = shaders.emplace_back(boost::json::object_kind);
+                ptr->dumpStats(shaderit.as_object());
+            }
         }
 
+        constexpr float mega = 1'000'000.f;
+        float totalTimeMs = sTotalTimeElapsed / mega;
         LL_INFOS() << "-----------------------------------" << LL_ENDL;
-        LL_INFOS() << "Total rendering time: " << llformat("%.4f ms", sTotalTimeElapsed / 1000000.f) << LL_ENDL;
-        LL_INFOS() << "Total samples drawn: " << llformat("%.4f million", sTotalSamplesDrawn / 1000000.f) << LL_ENDL;
-        LL_INFOS() << "Total triangles drawn: " << llformat("%.3f million", sTotalTrianglesDrawn / 1000000.f) << LL_ENDL;
+        LL_INFOS() << "Total rendering time: " << llformat("%.4f ms", totalTimeMs) << LL_ENDL;
+        LL_INFOS() << "Total samples drawn: " << llformat("%.4f million", sTotalSamplesDrawn / mega) << LL_ENDL;
+        LL_INFOS() << "Total triangles drawn: " << llformat("%.3f million", sTotalTrianglesDrawn / mega) << LL_ENDL;
         LL_INFOS() << "-----------------------------------" << LL_ENDL;
-
+        auto totalsit = stats.emplace("totals", boost::json::object_kind).first;
+        auto& totals = totalsit->value().as_object();
+        totals.emplace("time", totalTimeMs / 1000.0);
+        totals.emplace("binds", sTotalBinds);
+        totals.emplace("samples", sTotalSamplesDrawn);
+        totals.emplace("triangles", sTotalTrianglesDrawn);
+
+        auto unusedit = stats.emplace("unused", boost::json::array_kind).first;
+        auto& unused = unusedit->value().as_array();
         if (unbound)
         {
             LL_INFOS() << "The following shaders were unused: " << LL_ENDL;
-            for (std::vector<LLGLSLShader*>::iterator iter = sorted.begin(); iter != sorted.end(); ++iter)
+            for (auto ptr : sorted)
             {
-                if ((*iter)->mBinds == 0)
+                if (ptr->mBinds == 0)
                 {
-                    LL_INFOS() << (*iter)->mName << LL_ENDL;
+                    LL_INFOS() << ptr->mName << LL_ENDL;
+                    unused.emplace_back(ptr->mName);
                 }
             }
         }
+
+        std::ofstream outf(report_name);
+        if (! outf)
+        {
+            LL_WARNS() << "Couldn't write to " << std::quoted(report_name) << LL_ENDL;
+        }
+        else
+        {
+            outf << stats;
+            LL_INFOS() << "(also dumped to " << std::quoted(report_name) << ")" << LL_ENDL;
+        }
     }
 }
 
@@ -170,36 +196,43 @@ void LLGLSLShader::clearStats()
     mBinds = 0;
 }
 
-void LLGLSLShader::dumpStats()
+void LLGLSLShader::dumpStats(boost::json::object& stats)
 {
-    if (mBinds > 0)
+    stats.emplace("name", mName);
+    auto filesit = stats.emplace("files", boost::json::array_kind).first;
+    auto& files = filesit->value().as_array();
+    LL_INFOS() << "=============================================" << LL_ENDL;
+    LL_INFOS() << mName << LL_ENDL;
+    for (U32 i = 0; i < mShaderFiles.size(); ++i)
     {
-        LL_INFOS() << "=============================================" << LL_ENDL;
-        LL_INFOS() << mName << LL_ENDL;
-        for (U32 i = 0; i < mShaderFiles.size(); ++i)
-        {
-            LL_INFOS() << mShaderFiles[i].first << LL_ENDL;
-        }
-        LL_INFOS() << "=============================================" << LL_ENDL;
+        LL_INFOS() << mShaderFiles[i].first << LL_ENDL;
+        files.emplace_back(mShaderFiles[i].first);
+    }
+    LL_INFOS() << "=============================================" << LL_ENDL;
 
-        F32 ms = mTimeElapsed / 1000000.f;
-        F32 seconds = ms / 1000.f;
+    constexpr float  mega = 1'000'000.f;
+    constexpr double giga = 1'000'000'000.0;
+    F32 ms = mTimeElapsed / mega;
+    F32 seconds = ms / 1000.f;
 
-        F32 pct_tris = (F32)mTrianglesDrawn / (F32)sTotalTrianglesDrawn * 100.f;
-        F32 tris_sec = (F32)(mTrianglesDrawn / 1000000.0);
-        tris_sec /= seconds;
+    F32 pct_tris = (F32)mTrianglesDrawn / (F32)sTotalTrianglesDrawn * 100.f;
+    F32 tris_sec = (F32)(mTrianglesDrawn / mega);
+    tris_sec /= seconds;
 
-        F32 pct_samples = (F32)((F64)mSamplesDrawn / (F64)sTotalSamplesDrawn) * 100.f;
-        F32 samples_sec = (F32)(mSamplesDrawn / 1000000000.0);
-        samples_sec /= seconds;
+    F32 pct_samples = (F32)((F64)mSamplesDrawn / (F64)sTotalSamplesDrawn) * 100.f;
+    F32 samples_sec = (F32)(mSamplesDrawn / giga);
+    samples_sec /= seconds;
 
-        F32 pct_binds = (F32)mBinds / (F32)sTotalBinds * 100.f;
+    F32 pct_binds = (F32)mBinds / (F32)sTotalBinds * 100.f;
 
-        LL_INFOS() << "Triangles Drawn: " << mTrianglesDrawn << " " << llformat("(%.2f pct of total, %.3f million/sec)", pct_tris, tris_sec) << LL_ENDL;
-        LL_INFOS() << "Binds: " << mBinds << " " << llformat("(%.2f pct of total)", pct_binds) << LL_ENDL;
-        LL_INFOS() << "SamplesDrawn: " << mSamplesDrawn << " " << llformat("(%.2f pct of total, %.3f billion/sec)", pct_samples, samples_sec) << LL_ENDL;
-        LL_INFOS() << "Time Elapsed: " << mTimeElapsed << " " << llformat("(%.2f pct of total, %.5f ms)\n", (F32)((F64)mTimeElapsed / (F64)sTotalTimeElapsed) * 100.f, ms) << LL_ENDL;
-    }
+    LL_INFOS() << "Triangles Drawn: " << mTrianglesDrawn << " " << llformat("(%.2f pct of total, %.3f million/sec)", pct_tris, tris_sec) << LL_ENDL;
+    LL_INFOS() << "Binds: " << mBinds << " " << llformat("(%.2f pct of total)", pct_binds) << LL_ENDL;
+    LL_INFOS() << "SamplesDrawn: " << mSamplesDrawn << " " << llformat("(%.2f pct of total, %.3f billion/sec)", pct_samples, samples_sec) << LL_ENDL;
+    LL_INFOS() << "Time Elapsed: " << mTimeElapsed << " " << llformat("(%.2f pct of total, %.5f ms)\n", (F32)((F64)mTimeElapsed / (F64)sTotalTimeElapsed) * 100.f, ms) << LL_ENDL;
+    stats.emplace("time", seconds);
+    stats.emplace("binds", mBinds);
+    stats.emplace("samples", mSamplesDrawn);
+    stats.emplace("triangles", mTrianglesDrawn);
 }
 
 //static
diff --git a/indra/llrender/llglslshader.h b/indra/llrender/llglslshader.h
index 27c8f0b7d0..a9b9bfafa8 100644
--- a/indra/llrender/llglslshader.h
+++ b/indra/llrender/llglslshader.h
@@ -30,6 +30,7 @@
 #include "llgl.h"
 #include "llrender.h"
 #include "llstaticstringtable.h"
+#include <boost/json.hpp>
 #include <unordered_map>
 
 class LLShaderFeatures
@@ -169,14 +170,14 @@ public:
     static U32 sMaxGLTFNodes;
 
     static void initProfile();
-    static void finishProfile(bool emit_report = true);
+    static void finishProfile(const std::string& report_name=sDefaultReportName);
 
     static void startProfile();
     static void stopProfile();
 
     void unload();
     void clearStats();
-    void dumpStats();
+    void dumpStats(boost::json::object& stats);
 
     // place query objects for profiling if profiling is enabled
     // if for_runtime is true, will place timer query only whether or not profiling is enabled
@@ -363,6 +364,11 @@ public:
 
 private:
     void unloadInternal();
+    // This must be static because finishProfile() is called at least once
+    // within a __try block. If we default its report_name parameter to a
+    // temporary std::string, that temporary must be destroyed when the stack
+    // is unwound, which __try forbids.
+    static std::string sDefaultReportName;
 };
 
 //UI shader (declared here so llui_libtest will link properly)