Make Develop->Render Tests->Frame Profile dump JSON to a file too.

Make `LLGLSLShader::finishProfile()` accept a string pathname instead of a
bool and, in addition to logging statistics to the viewer log, output
statistics to that file as JSON. The calls that used to pass
`emit_report=false` now pass `report_name=std::string()`.

Make llviewerdisplay.cpp's `display()` function synthesize a profile filename
in the viewer's logs directory, and pass that filename to
`LLGLSLShader::finishProfile()`.

(cherry picked from commit d5712689d36a1ee1af32242706901fde7229b08d)
master
Nat Goodspeed 2024-09-11 12:29:18 -04:00
parent 27b8e6d576
commit f037cde7f4
5 changed files with 161 additions and 76 deletions

View File

@ -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
@ -101,9 +103,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 +119,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 +195,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;
F32 ms = mTimeElapsed / 1000000.f;
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_samples = (F32)((F64)mSamplesDrawn / (F64)sTotalSamplesDrawn) * 100.f;
F32 samples_sec = (F32)(mSamplesDrawn / 1000000000.0);
samples_sec /= seconds;
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() << mShaderFiles[i].first << LL_ENDL;
files.emplace_back(mShaderFiles[i].first);
}
LL_INFOS() << "=============================================" << LL_ENDL;
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 / mega);
tris_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;
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

View File

@ -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={});
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

View File

@ -393,7 +393,7 @@ F32 logExceptionBenchmark()
__except (msc_exception_filter(GetExceptionCode(), GetExceptionInformation()))
{
// HACK - ensure that profiling is disabled
LLGLSLShader::finishProfile(false);
LLGLSLShader::finishProfile();
// convert to C++ styled exception
char integer_string[32];

View File

@ -924,7 +924,7 @@ struct ShaderProfileHelper
}
~ShaderProfileHelper()
{
LLGLSLShader::finishProfile(false);
LLGLSLShader::finishProfile();
}
};

View File

@ -28,58 +28,69 @@
#include "llviewerdisplay.h"
#include "llgl.h"
#include "llrender.h"
#include "llglheaders.h"
#include "llgltfmateriallist.h"
#include "fsyspath.h"
#include "hexdump.h"
#include "llagent.h"
#include "llagentcamera.h"
#include "llviewercontrol.h"
#include "llappviewer.h"
#include "llcoord.h"
#include "llcriticaldamp.h"
#include "llcubemap.h"
#include "lldir.h"
#include "lldynamictexture.h"
#include "lldrawpoolalpha.h"
#include "lldrawpoolbump.h"
#include "lldrawpoolwater.h"
#include "lldynamictexture.h"
#include "llenvironment.h"
#include "llfasttimer.h"
#include "llfeaturemanager.h"
//#include "llfirstuse.h"
#include "llfloatertools.h"
#include "llfocusmgr.h"
#include "llgl.h"
#include "llglheaders.h"
#include "llgltfmateriallist.h"
#include "llhudmanager.h"
#include "llimagepng.h"
#include "llmachineid.h"
#include "llmemory.h"
#include "llparcel.h"
#include "llperfstats.h"
#include "llpostprocess.h"
#include "llrender.h"
#include "llscenemonitor.h"
#include "llselectmgr.h"
#include "llsky.h"
#include "llspatialpartition.h"
#include "llstartup.h"
#include "llstartup.h"
#include "lltooldraganddrop.h"
#include "lltoolfocus.h"
#include "lltoolmgr.h"
#include "lltooldraganddrop.h"
#include "lltoolpie.h"
#include "lltracker.h"
#include "lltrans.h"
#include "llui.h"
#include "lluuid.h"
#include "llversioninfo.h"
#include "llviewercamera.h"
#include "llviewercontrol.h"
#include "llviewernetwork.h"
#include "llviewerobjectlist.h"
#include "llviewerparcelmgr.h"
#include "llviewerregion.h"
#include "llviewershadermgr.h"
#include "llviewertexturelist.h"
#include "llviewerwindow.h"
#include "llvoavatarself.h"
#include "llvograss.h"
#include "llworld.h"
#include "pipeline.h"
#include "llspatialpartition.h"
#include "llappviewer.h"
#include "llstartup.h"
#include "llviewershadermgr.h"
#include "llfasttimer.h"
#include "llfloatertools.h"
#include "llviewertexturelist.h"
#include "llfocusmgr.h"
#include "llcubemap.h"
#include "llviewerregion.h"
#include "lldrawpoolwater.h"
#include "lldrawpoolbump.h"
#include "llpostprocess.h"
#include "llscenemonitor.h"
#include "llenvironment.h"
#include "llperfstats.h"
#include <boost/json.hpp>
#include <filesystem>
#include <iomanip>
#include <sstream>
#include <glm/glm.hpp>
#include <glm/gtc/matrix_transform.hpp>
@ -127,6 +138,8 @@ void render_ui_3d();
void render_ui_2d();
void render_disconnected_background();
std::string getProfileStatsFilename();
void display_startup()
{
if ( !gViewerWindow
@ -1027,10 +1040,49 @@ void display(bool rebuild, F32 zoom_factor, int subfield, bool for_snapshot)
if (gShaderProfileFrame)
{
gShaderProfileFrame = false;
LLGLSLShader::finishProfile();
LLGLSLShader::finishProfile(getProfileStatsFilename());
}
}
std::string getProfileStatsFilename()
{
std::ostringstream basebuff;
// viewer build
basebuff << "profile.v" << LLVersionInfo::instance().getBuild();
// machine ID: zero-initialize unique_id in case LLMachineID fails
unsigned char unique_id[MAC_ADDRESS_BYTES]{};
LLMachineID::getUniqueID(unique_id, sizeof(unique_id));
basebuff << ".m" << LL::hexdump(unique_id, sizeof(unique_id));
// region ID
LLViewerRegion *region = gAgent.getRegion();
basebuff << ".r" << (region? region->getRegionID() : LLUUID());
// local parcel ID
LLParcel* parcel = LLViewerParcelMgr::instance().getAgentParcel();
basebuff << ".p" << (parcel? parcel->getLocalID() : 0);
// date/time -- omit seconds for now
auto now = LLDate::now();
basebuff << ".t" << LLDate::now().toHTTPDateString("%Y-%m-%dT%H-%M-");
// put this candidate file in our logs directory
auto base = gDirUtilp->getExpandedFilename(LL_PATH_LOGS, basebuff.str());
S32 sec;
now.split(nullptr, nullptr, nullptr, nullptr, nullptr, &sec);
// Loop over finished filename, incrementing sec until we find one that
// doesn't yet exist. Should rarely loop (only if successive calls within
// same second), may produce (e.g.) sec==61, but avoids collisions and
// preserves chronological filename sort order.
std::string name;
std::error_code ec;
do
{
// base + missing 2-digit seconds, append ".json"
// post-increment sec in case we have to try again
name = stringize(base, std::setw(2), std::setfill('0'), sec++, ".json");
} while (std::filesystem::exists(fsyspath(name), ec));
// Ignoring ec means we might potentially return a name that does already
// exist -- but if we can't check its existence, what more can we do?
return name;
}
// WIP simplified copy of display() that does minimal work
void display_cube_face()
{