Adds simple stats tracking to AssetProcessor (#5573)
* Adds simple stats tracking to AssetProcessor The system captures cumulative and individual processing times. It avoids touching any part of the app which affects decision making or flow, or altering any structures such as JobEntry which are involved in processing, in order to keep it as simple and small as possible. Signed-off-by: lawsonamzn <70027408+lawsonamzn@users.noreply.github.com>
This commit is contained in:
Nicholas Lawson
GitHub
@@ -105,6 +105,8 @@ set(FILES
|
||||
native/utilities/PlatformConfiguration.cpp
|
||||
native/utilities/PlatformConfiguration.h
|
||||
native/utilities/PotentialDependencies.h
|
||||
native/utilities/StatsCapture.cpp
|
||||
native/utilities/StatsCapture.h
|
||||
native/utilities/SpecializedDependencyScanner.h
|
||||
native/utilities/ThreadHelper.cpp
|
||||
native/utilities/ThreadHelper.h
|
||||
|
||||
@@ -36,6 +36,7 @@ set(FILES
|
||||
native/tests/platformconfiguration/platformconfigurationtests.h
|
||||
native/tests/utilities/JobModelTest.cpp
|
||||
native/tests/utilities/JobModelTest.h
|
||||
native/tests/utilities/StatsCaptureTest.cpp
|
||||
native/tests/AssetCatalog/AssetCatalogUnitTests.cpp
|
||||
native/tests/assetscanner/AssetScannerTests.h
|
||||
native/tests/assetscanner/AssetScannerTests.cpp
|
||||
|
||||
@@ -25,6 +25,7 @@
|
||||
|
||||
#include <native/AssetManager/PathDependencyManager.h>
|
||||
#include <native/utilities/BuilderConfigurationBus.h>
|
||||
#include <native/utilities/StatsCapture.h>
|
||||
|
||||
#include "AssetRequestHandler.h"
|
||||
|
||||
@@ -123,6 +124,9 @@ namespace AssetProcessor
|
||||
{
|
||||
if (status == AssetProcessor::AssetScanningStatus::Started)
|
||||
{
|
||||
// capture scanning stats:
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("AssetScanning");
|
||||
|
||||
// Ensure that the source file list is populated before a scan begins
|
||||
m_sourceFilesInDatabase.clear();
|
||||
m_fileModTimes.clear();
|
||||
@@ -176,6 +180,8 @@ namespace AssetProcessor
|
||||
(status == AssetProcessor::AssetScanningStatus::Stopped))
|
||||
{
|
||||
m_isCurrentlyScanning = false;
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("AssetScanning");
|
||||
|
||||
// we cannot invoke this immediately - the scanner might be done, but we aren't actually ready until we've processed all remaining messages:
|
||||
QMetaObject::invokeMethod(this, "CheckMissingFiles", Qt::QueuedConnection);
|
||||
}
|
||||
@@ -209,13 +215,24 @@ namespace AssetProcessor
|
||||
}
|
||||
else
|
||||
{
|
||||
QString statKey = QString("ProcessJob,%1,%2,%3").arg(jobEntry.m_databaseSourceName).arg(jobEntry.m_jobKey).arg(jobEntry.m_platformInfo.m_identifier.c_str());
|
||||
|
||||
if (status == JobStatus::InProgress)
|
||||
{
|
||||
//update to in progress status
|
||||
m_jobRunKeyToJobInfoMap[jobEntry.m_jobRunKey].m_status = JobStatus::InProgress;
|
||||
// stats tracking. Start accumulating time.
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat(statKey.toUtf8().constData());
|
||||
|
||||
}
|
||||
else //if failed or succeeded remove from the map
|
||||
{
|
||||
// note that sometimes this gets called twice, once by the RCJobs thread and once by the AP itself,
|
||||
// because sometimes jobs take a short cut from "started" -> "failed" or "started" -> "complete
|
||||
// without going thru the RC.
|
||||
// as such, all the code in this block should be crafted to work regardless of whether its double called.
|
||||
AssetProcessor::StatsCapture::EndCaptureStat(statKey.toUtf8().constData());
|
||||
|
||||
m_jobRunKeyToJobInfoMap.erase(jobEntry.m_jobRunKey);
|
||||
Q_EMIT SourceFinished(sourceUUID, legacySourceUUID);
|
||||
Q_EMIT JobComplete(jobEntry, status);
|
||||
@@ -3355,8 +3372,13 @@ namespace AssetProcessor
|
||||
AZStd::string logFileName = AssetUtilities::ComputeJobLogFileName(createJobsRequest);
|
||||
{
|
||||
AssetUtilities::JobLogTraceListener jobLogTraceListener(logFileName, runKey, true);
|
||||
// track the time it takes to createJobs. We can perform analysis later to present it by extension and other stats.
|
||||
QString statKey = QString("CreateJobs,%1,%2").arg(actualRelativePath).arg(builderInfo.m_name.c_str());
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat(statKey.toUtf8().constData());
|
||||
builderInfo.m_createJobFunction(createJobsRequest, createJobsResponse);
|
||||
AssetProcessor::StatsCapture::EndCaptureStat(statKey.toUtf8().constData());
|
||||
}
|
||||
|
||||
AssetProcessor::SetThreadLocalJobId(0);
|
||||
|
||||
bool isBuilderMissingFingerprint = (createJobsResponse.m_result == AssetBuilderSDK::CreateJobsResultCode::Success
|
||||
@@ -4839,5 +4861,7 @@ namespace AssetProcessor
|
||||
}
|
||||
return filesFound;
|
||||
}
|
||||
|
||||
|
||||
} // namespace AssetProcessor
|
||||
|
||||
|
||||
@@ -0,0 +1,200 @@
|
||||
/*
|
||||
* Copyright (c) Contributors to the Open 3D Engine Project.
|
||||
* For complete copyright and license terms please see the LICENSE at the root of this distribution.
|
||||
*
|
||||
* SPDX-License-Identifier: Apache-2.0 OR MIT
|
||||
*
|
||||
*/
|
||||
|
||||
#include <native/tests/AssetProcessorTest.h>
|
||||
#include <native/utilities/StatsCapture.h>
|
||||
#include <AzCore/std/containers/vector.h>
|
||||
#include <AzCore/std/string/string.h>
|
||||
#include <AzCore/Settings/SettingsRegistry.h>
|
||||
#include <AzCore/Debug/TraceMessageBus.h>
|
||||
#include <AzCore/StringFunc/StringFunc.h>
|
||||
|
||||
// the simple stats capture system has a trivial interface and only writes to printf.
|
||||
// So the simplest tests we can do is make sure it only asserts when it should
|
||||
// and doesn't assert in cases when it shouldn't, and that the stats are reasonable
|
||||
// in printf format.
|
||||
|
||||
namespace AssetProcessor
|
||||
{
|
||||
// Its okay to talk to this system when unintialized, you can gain some perf
|
||||
// by not intializing it at all
|
||||
TEST_F(AssetProcessorTest, StatsCaptureTest_UninitializedSystemDoesNotAssert)
|
||||
{
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("Test");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("Test");
|
||||
AssetProcessor::StatsCapture::Dump();
|
||||
AssetProcessor::StatsCapture::Shutdown();
|
||||
}
|
||||
|
||||
// Double-intiailize is an error
|
||||
TEST_F(AssetProcessorTest, StatsCaptureTest_DoubleInitializeIsAnAssert)
|
||||
{
|
||||
m_errorAbsorber->Clear();
|
||||
|
||||
AssetProcessor::StatsCapture::Initialize();
|
||||
AssetProcessor::StatsCapture::Initialize();
|
||||
|
||||
EXPECT_EQ(m_errorAbsorber->m_numErrorsAbsorbed, 0);
|
||||
EXPECT_EQ(m_errorAbsorber->m_numAssertsAbsorbed, 1); // not allowed to assert on this
|
||||
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("Test");
|
||||
AssetProcessor::StatsCapture::Shutdown();
|
||||
}
|
||||
|
||||
class StatsCaptureOutputTest : public AssetProcessorTest, public AZ::Debug::TraceMessageBus::Handler
|
||||
{
|
||||
public:
|
||||
void SetUp() override
|
||||
{
|
||||
AssetProcessorTest::SetUp();
|
||||
AssetProcessor::StatsCapture::Initialize();
|
||||
}
|
||||
|
||||
// dump but also capture the dump as a vector of lines:
|
||||
void Dump()
|
||||
{
|
||||
AZ::Debug::TraceMessageBus::Handler::BusConnect();
|
||||
AssetProcessor::StatsCapture::Dump();
|
||||
AZ::Debug::TraceMessageBus::Handler::BusDisconnect();
|
||||
}
|
||||
|
||||
virtual bool OnPrintf(const char* /*window*/, const char* message)
|
||||
{
|
||||
m_gatheredMessages.emplace_back(message);
|
||||
AZ::StringFunc::TrimWhiteSpace(m_gatheredMessages.back(), true, true);
|
||||
return false;
|
||||
}
|
||||
|
||||
void TearDown() override
|
||||
{
|
||||
m_gatheredMessages = {};
|
||||
|
||||
AssetProcessor::StatsCapture::Shutdown();
|
||||
AssetProcessorTest::TearDown();
|
||||
}
|
||||
|
||||
AZStd::vector<AZStd::string> m_gatheredMessages;
|
||||
};
|
||||
|
||||
// turning off machine and human readable mode, should not dump anything.
|
||||
TEST_F(StatsCaptureOutputTest, StatsCaptureTest_DisabledByRegset_DumpsNothing)
|
||||
{
|
||||
auto registry = AZ::SettingsRegistry::Get();
|
||||
ASSERT_NE(registry, nullptr);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/HumanReadable", false);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/MachineReadable", false);
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("Test");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("Test");
|
||||
Dump();
|
||||
EXPECT_EQ(m_gatheredMessages.size(), 0);
|
||||
}
|
||||
|
||||
// turning on Human Readable, turn off Machine Readable, should not output any machine readable stats.
|
||||
TEST_F(StatsCaptureOutputTest, StatsCaptureTest_HumanReadableOnly_DumpsNoMachineReadable)
|
||||
{
|
||||
auto registry = AZ::SettingsRegistry::Get();
|
||||
ASSERT_NE(registry, nullptr);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/HumanReadable", true);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/MachineReadable", false);
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("Test");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("Test");
|
||||
Dump();
|
||||
EXPECT_GT(m_gatheredMessages.size(), 0);
|
||||
for (const auto& message : m_gatheredMessages)
|
||||
{
|
||||
// we expect to see ZERO "Machine Readable" lines
|
||||
EXPECT_FALSE(message.contains("MachineReadableStat:")) << "Found unexpected line in output: " << message.c_str();
|
||||
}
|
||||
}
|
||||
|
||||
// Turn on Machine Readable, Turn off Human Readable, ensure only Machine Readable stats emitted.
|
||||
TEST_F(StatsCaptureOutputTest, StatsCaptureTest_MachineReadableOnly_DumpsNoHumanReadable)
|
||||
{
|
||||
auto registry = AZ::SettingsRegistry::Get();
|
||||
ASSERT_NE(registry, nullptr);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/HumanReadable", false);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/MachineReadable", true);
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("Test");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("Test");
|
||||
Dump();
|
||||
for (const auto& message : m_gatheredMessages)
|
||||
{
|
||||
// we expect to see ONLY "Machine Readable" lines
|
||||
EXPECT_TRUE(message.contains("MachineReadableStat:")) << "Found unexpected line in output: " << message.c_str();
|
||||
}
|
||||
EXPECT_GT(m_gatheredMessages.size(), 0);
|
||||
}
|
||||
|
||||
|
||||
// The interface for StatsCapture just captures and then dumps.
|
||||
// For us to test this, we thus have to capture and parse the dump output.
|
||||
TEST_F(StatsCaptureOutputTest, StatsCaptureTest_Sanity)
|
||||
{
|
||||
auto registry = AZ::SettingsRegistry::Get();
|
||||
ASSERT_NE(registry, nullptr);
|
||||
|
||||
// Make it output in "machine raadable" format so that it is simpler to parse.
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/HumanReadable", false);
|
||||
registry->Set("/Amazon/AssetProcessor/Settings/Stats/MachineReadable", true);
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("CreateJobs,foo,mybuilder");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("CreateJobs,foo,mybuilder");
|
||||
|
||||
// Intentionally not using sleeps in this test. It means that the
|
||||
// captured duration will be likely 0 but its not worth it to slow down tests.
|
||||
// If the durations end up 0 its going to be extremely noticable in day-to-day use.
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("CreateJobs,foo,mybuilder");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("CreateJobs,foo,mybuilder");
|
||||
|
||||
// for the second stat, we'll double capture and double end, in order to test debounce
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("CreateJobs,foo2,mybuilder");
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("CreateJobs,foo2,mybuilder");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("CreateJobs,foo2,mybuilder2");
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("CreateJobs,foo2,mybuilder2");
|
||||
|
||||
m_gatheredMessages.clear();
|
||||
Dump();
|
||||
EXPECT_GT(m_gatheredMessages.size(), 0);
|
||||
|
||||
// We'll parse the machine readable stat lines here and make sure that the following is true
|
||||
// mybuilder appears
|
||||
// mybuilder appears only once but count is 2
|
||||
bool foundFoo = false;
|
||||
bool foundFoo2 = false;
|
||||
|
||||
for (const auto& stat : m_gatheredMessages)
|
||||
{
|
||||
if (stat.contains("MachineReadableStat:"))
|
||||
{
|
||||
AZStd::vector<AZStd::string> tokens;
|
||||
AZ::StringFunc::Tokenize(stat, tokens, ":", false, false);
|
||||
ASSERT_EQ(tokens.size(), 5); // should be "MachineReadableStat:time:count:average:name)
|
||||
const auto& countData = tokens[2];
|
||||
const auto& nameData = tokens[4];
|
||||
|
||||
if (AZ::StringFunc::Equal(nameData, "CreateJobs,foo,mybuilder"))
|
||||
{
|
||||
EXPECT_FALSE(foundFoo); // should only find one of these
|
||||
foundFoo = true;
|
||||
EXPECT_STREQ(countData.c_str(), "2");
|
||||
}
|
||||
|
||||
if (AZ::StringFunc::Equal(nameData, "CreateJobs,foo2,mybuilder2"))
|
||||
{
|
||||
EXPECT_FALSE(foundFoo2); // should only find one of these
|
||||
foundFoo2 = true;
|
||||
EXPECT_STREQ(countData.c_str(), "1");
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
EXPECT_TRUE(foundFoo) << "The expected token CreateJobs,foo,mybuilder did not appear in the output.";
|
||||
EXPECT_TRUE(foundFoo2) << "The expected CreateJobs.foo2.mybuilder2 did not appear in the output";
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
@@ -16,7 +16,8 @@
|
||||
#include <AzFramework/Logging/LoggingComponent.h>
|
||||
#include <AzFramework/Asset/AssetSystemComponent.h>
|
||||
|
||||
#include "native/resourcecompiler/RCBuilder.h"
|
||||
#include <native/resourcecompiler/RCBuilder.h>
|
||||
#include <native/utilities/StatsCapture.h>
|
||||
|
||||
#include <QLocale>
|
||||
#include <QTranslator>
|
||||
@@ -200,6 +201,10 @@ ApplicationManager::~ApplicationManager()
|
||||
delete m_appDependencies[idx];
|
||||
}
|
||||
|
||||
// end stats capture (dump and shutdown)
|
||||
AssetProcessor::StatsCapture::Dump();
|
||||
AssetProcessor::StatsCapture::Shutdown();
|
||||
|
||||
qInstallMessageHandler(nullptr);
|
||||
|
||||
//deleting QCoreApplication/QApplication
|
||||
@@ -571,6 +576,8 @@ bool ApplicationManager::StartAZFramework()
|
||||
|
||||
bool ApplicationManager::ActivateModules()
|
||||
{
|
||||
AssetProcessor::StatsCapture::BeginCaptureStat("LoadingModules");
|
||||
|
||||
// we load the editor xml for our modules since it contains the list of gems we need for tools to function (not just runtime)
|
||||
connect(&m_frameworkApp, &AssetProcessorAZApplication::AssetProcessorStatus, this,
|
||||
[this](AssetProcessor::AssetProcessorStatusEntry entry)
|
||||
@@ -587,6 +594,8 @@ bool ApplicationManager::ActivateModules()
|
||||
}
|
||||
|
||||
m_frameworkApp.LoadDynamicModules();
|
||||
|
||||
AssetProcessor::StatsCapture::EndCaptureStat("LoadingModules");
|
||||
return true;
|
||||
}
|
||||
|
||||
@@ -618,6 +627,9 @@ ApplicationManager::BeforeRunStatus ApplicationManager::BeforeRun()
|
||||
return ApplicationManager::BeforeRunStatus::Status_Failure;
|
||||
}
|
||||
|
||||
// enable stats capture from this point on
|
||||
AssetProcessor::StatsCapture::Initialize();
|
||||
|
||||
return ApplicationManager::BeforeRunStatus::Status_Success;
|
||||
}
|
||||
|
||||
|
||||
@@ -1173,6 +1173,7 @@ void ApplicationManagerBase::InitBuilderManager()
|
||||
{
|
||||
m_builderManager->ConnectionLost(connId);
|
||||
});
|
||||
|
||||
}
|
||||
|
||||
void ApplicationManagerBase::ShutdownBuilderManager()
|
||||
|
||||
@@ -0,0 +1,394 @@
|
||||
/*
|
||||
* Copyright (c) Contributors to the Open 3D Engine Project.
|
||||
* For complete copyright and license terms please see the LICENSE at the root of this distribution.
|
||||
*
|
||||
* SPDX-License-Identifier: Apache-2.0 OR MIT
|
||||
*
|
||||
*/
|
||||
|
||||
#include <native/utilities/StatsCapture.h>
|
||||
#include <native/assetprocessor.h>
|
||||
|
||||
#include <AzCore/Memory/SystemAllocator.h>
|
||||
#include <AzCore/Settings/SettingsRegistry.h>
|
||||
#include <AzCore/std/chrono/chrono.h>
|
||||
#include <AzCore/std/chrono/clocks.h>
|
||||
#include <AzCore/std/string/string.h>
|
||||
#include <AzCore/std/sort.h>
|
||||
#include <AzCore/std/containers/unordered_map.h>
|
||||
#include <AzCore/std/containers/unordered_set.h>
|
||||
#include <AzCore/std/containers/vector.h>
|
||||
#include <AzCore/StringFunc/StringFunc.h>
|
||||
|
||||
#include <inttypes.h>
|
||||
|
||||
namespace AssetProcessor
|
||||
{
|
||||
namespace StatsCapture
|
||||
{
|
||||
// This class captures stats by storing them in a map of type
|
||||
// [name of stat] -> Stat struct
|
||||
// It can then analyze these stats and produce more stats from the original
|
||||
// Captures, before dumping.
|
||||
class StatsCaptureImpl final
|
||||
{
|
||||
public:
|
||||
AZ_CLASS_ALLOCATOR(StatsCaptureImpl, AZ::SystemAllocator, 0);
|
||||
|
||||
void BeginCaptureStat(AZStd::string_view statName);
|
||||
void EndCaptureStat(AZStd::string_view statName);
|
||||
void Dump();
|
||||
private:
|
||||
using timepoint = AZStd::chrono::high_resolution_clock::time_point;
|
||||
using duration = AZStd::chrono::milliseconds;
|
||||
struct StatsEntry
|
||||
{
|
||||
duration m_cumulativeTime = {}; // The total amount of time spent on this.
|
||||
timepoint m_operationStartTime = {}; // Async tracking - the last time stamp an operation started.
|
||||
int64_t m_operationCount = 0; // In case there's more than one sample. Used to calc average.
|
||||
};
|
||||
|
||||
AZStd::unordered_map<AZStd::string, StatsEntry> m_stats;
|
||||
bool m_dumpMachineReadableStats = false;
|
||||
bool m_dumpHumanReadableStats = true;
|
||||
|
||||
// Make a friendly time string of the format nnHnnMhhS.xxxms
|
||||
AZStd::string FormatDuration(const duration& duration)
|
||||
{
|
||||
int64_t milliseconds = duration.count();
|
||||
constexpr int64_t millisecondsInASecond = 1000;
|
||||
constexpr int64_t millisecondsInAMinute = millisecondsInASecond * 60;
|
||||
constexpr int64_t millisecondsInAnHour = millisecondsInAMinute * 60;
|
||||
|
||||
int64_t hours = milliseconds / millisecondsInAnHour;
|
||||
milliseconds -= hours * millisecondsInAnHour;
|
||||
|
||||
int64_t minutes = milliseconds / millisecondsInAMinute;
|
||||
milliseconds -= minutes * millisecondsInAMinute;
|
||||
|
||||
int64_t seconds = milliseconds / millisecondsInASecond;
|
||||
milliseconds -= seconds * millisecondsInASecond;
|
||||
|
||||
// omit the sections which dont make sense for readability
|
||||
if (hours)
|
||||
{
|
||||
return AZStd::string::format("%02" PRId64 "h%02" PRId64 "m%02" PRId64 "s%03" PRId64 "ms" , hours, minutes, seconds, milliseconds);
|
||||
}
|
||||
else if (minutes)
|
||||
{
|
||||
return AZStd::string::format(" %02" PRId64 "m%02" PRId64 "s%03" PRId64 "ms", minutes, seconds, milliseconds);
|
||||
}
|
||||
else if (seconds)
|
||||
{
|
||||
return AZStd::string::format(" %02" PRId64 "s%03" PRId64 "ms", seconds, milliseconds);
|
||||
}
|
||||
|
||||
return AZStd::string::format(" %03" PRId64 "ms", milliseconds);
|
||||
}
|
||||
|
||||
// Prints out a single stat.
|
||||
void PrintStat([[maybe_unused]] const char* name, duration milliseconds, int64_t count)
|
||||
{
|
||||
// note that name may be unused as it only appears in Trace macros, which are
|
||||
// stripped out in release builds.
|
||||
if (count <= 1)
|
||||
{
|
||||
count = 1;
|
||||
}
|
||||
|
||||
duration average(static_cast<int64_t>(static_cast<double>(milliseconds.count()) / static_cast<double>(count)));
|
||||
|
||||
if (m_dumpHumanReadableStats)
|
||||
{
|
||||
if (count > 1)
|
||||
{
|
||||
AZ_TracePrintf(AssetProcessor::ConsoleChannel, " Time: %s, Count: %4" PRId64 ", Average: %s, EventName: %s\n",
|
||||
FormatDuration(milliseconds).c_str(),
|
||||
count,
|
||||
FormatDuration(average).c_str(),
|
||||
name);
|
||||
}
|
||||
else
|
||||
{
|
||||
AZ_TracePrintf(AssetProcessor::ConsoleChannel, " Time: %s, EventName: %s\n",
|
||||
FormatDuration(milliseconds).c_str(),
|
||||
name);
|
||||
}
|
||||
}
|
||||
if (m_dumpMachineReadableStats)
|
||||
{
|
||||
// machine Readable mode prints raw milliseconds and uses a CSV-like format
|
||||
// note that the stat itself may contain commas, so we dont acutally separate with comma
|
||||
// instead we separate with :
|
||||
// and each "interesting line" is 'MachineReadableStat:milliseconds:count:average:name'
|
||||
AZ_TracePrintf(AssetProcessor::ConsoleChannel, "MachineReadableStat:%" PRId64 ":%" PRId64 ":%" PRId64 ":%s\n",
|
||||
milliseconds.count(),
|
||||
count,
|
||||
count > 1 ? average.count() : milliseconds.count(),
|
||||
name);
|
||||
}
|
||||
}
|
||||
|
||||
// calls PrintStat on each element in the vector.
|
||||
void PrintStatsArray(AZStd::vector<AZStd::string>& keys, int maxToPrint, const char* header)
|
||||
{
|
||||
if ((m_dumpHumanReadableStats)&&(header))
|
||||
{
|
||||
AZ_TracePrintf(AssetProcessor::ConsoleChannel,"Top %i %s\n", maxToPrint, header);
|
||||
}
|
||||
|
||||
auto sortByTimeDescending = [&](const AZStd::string& s1, const AZStd::string& s2)
|
||||
{
|
||||
return this->m_stats[s1].m_cumulativeTime > this->m_stats[s2].m_cumulativeTime;
|
||||
};
|
||||
|
||||
AZStd::sort(keys.begin(), keys.end(), sortByTimeDescending);
|
||||
|
||||
for (int idx = 0; idx < maxToPrint; ++idx)
|
||||
{
|
||||
if (idx < keys.size())
|
||||
{
|
||||
PrintStat(keys[idx].c_str(), m_stats[keys[idx]].m_cumulativeTime, m_stats[keys[idx]].m_operationCount);
|
||||
}
|
||||
}
|
||||
}
|
||||
};
|
||||
|
||||
|
||||
void StatsCaptureImpl::BeginCaptureStat(AZStd::string_view statName)
|
||||
{
|
||||
StatsEntry& existingStat = m_stats[statName];
|
||||
if (existingStat.m_operationStartTime != timepoint())
|
||||
{
|
||||
// prevent double 'Begins'
|
||||
return;
|
||||
}
|
||||
existingStat.m_operationStartTime = AZStd::chrono::high_resolution_clock::now();
|
||||
}
|
||||
|
||||
void StatsCaptureImpl::EndCaptureStat(AZStd::string_view statName)
|
||||
{
|
||||
StatsEntry& existingStat = m_stats[statName];
|
||||
if (existingStat.m_operationStartTime != timepoint())
|
||||
{
|
||||
existingStat.m_cumulativeTime = AZStd::chrono::high_resolution_clock::now() - existingStat.m_operationStartTime;
|
||||
existingStat.m_operationCount = existingStat.m_operationCount + 1;
|
||||
existingStat.m_operationStartTime = timepoint(); // reset the start time so that double 'Ends' are ignored.
|
||||
}
|
||||
}
|
||||
|
||||
void StatsCaptureImpl::Dump()
|
||||
{
|
||||
timepoint startTimeStamp = AZStd::chrono::high_resolution_clock::now();
|
||||
|
||||
auto settingsRegistry = AZ::SettingsRegistry::Get();
|
||||
|
||||
int maxCumulativeStats = 5; // default max cumulative stats to show
|
||||
int maxIndividualStats = 5; // default max individual files to show
|
||||
|
||||
if (settingsRegistry)
|
||||
{
|
||||
AZ::u64 cumulativeStats = static_cast<AZ::u64>(maxCumulativeStats);
|
||||
AZ::u64 individualStats = static_cast<AZ::u64>(maxIndividualStats);
|
||||
settingsRegistry->Get(m_dumpHumanReadableStats, "/Amazon/AssetProcessor/Settings/Stats/HumanReadable");
|
||||
settingsRegistry->Get(m_dumpMachineReadableStats, "/Amazon/AssetProcessor/Settings/Stats/MachineReadable");
|
||||
settingsRegistry->Get(cumulativeStats, "/Amazon/AssetProcessor/Settings/Stats/MaxCumulativeStats");
|
||||
settingsRegistry->Get(individualStats, "/Amazon/AssetProcessor/Settings/Stats/MaxIndividualStats");
|
||||
maxCumulativeStats = static_cast<int>(cumulativeStats);
|
||||
maxIndividualStats = static_cast<int>(individualStats);
|
||||
}
|
||||
|
||||
if ((!m_dumpHumanReadableStats)&&(!m_dumpMachineReadableStats))
|
||||
{
|
||||
return;
|
||||
}
|
||||
|
||||
AZStd::vector<AZStd::string> allCreateJobs; // individual
|
||||
AZStd::vector<AZStd::string> allCreateJobsByBuilder; // bucketed by builder
|
||||
AZStd::vector<AZStd::string> allProcessJobs; // individual
|
||||
AZStd::vector<AZStd::string> allProcessJobsByPlatform; // bucketed by platform
|
||||
AZStd::vector<AZStd::string> allProcessJobsByJobKey; // bucketed by type of job (job key)
|
||||
AZStd::vector<AZStd::string> allHashFiles;
|
||||
|
||||
// capture only existing keys as we will be expanding the stats
|
||||
// this approach avoids mutating an iterator.
|
||||
AZStd::vector<AZStd::string> statKeys;
|
||||
for (const auto& element : m_stats)
|
||||
{
|
||||
statKeys.push_back(element.first);
|
||||
}
|
||||
|
||||
for (const AZStd::string& statKey : statKeys)
|
||||
{
|
||||
const StatsEntry& statistic = m_stats[statKey];
|
||||
// Createjobs stats encode like (CreateJobs,sourcefilepath,builderid)
|
||||
if (AZ::StringFunc::StartsWith(statKey, "CreateJobs,", true))
|
||||
{
|
||||
allCreateJobs.push_back(statKey);
|
||||
AZStd::vector<AZStd::string> tokens;
|
||||
AZ::StringFunc::Tokenize(statKey, tokens, ",", false, false);
|
||||
|
||||
// look up the builder so you can get its name:
|
||||
AZStd::string_view builderName = tokens[2];
|
||||
|
||||
// synthesize a stat to track per-builder createjobs times:
|
||||
{
|
||||
AZStd::string newStatKey = AZStd::string::format("CreateJobsByBuilder,%.*s", AZ_STRING_ARG(builderName));
|
||||
|
||||
auto insertion = m_stats.insert(newStatKey);
|
||||
StatsEntry& statToSynth = insertion.first->second;
|
||||
statToSynth.m_cumulativeTime += statistic.m_cumulativeTime;
|
||||
statToSynth.m_operationCount += statistic.m_operationCount;
|
||||
if (insertion.second)
|
||||
{
|
||||
allCreateJobsByBuilder.push_back(newStatKey);
|
||||
}
|
||||
}
|
||||
// synthesize a stat to track total createjobs times:
|
||||
{
|
||||
StatsEntry& statToSynth = m_stats["CreateJobsTotal"];
|
||||
statToSynth.m_cumulativeTime += statistic.m_cumulativeTime;
|
||||
statToSynth.m_operationCount += statistic.m_operationCount;
|
||||
}
|
||||
}
|
||||
else if (AZ::StringFunc::StartsWith(statKey, "ProcessJob,", true))
|
||||
{
|
||||
allProcessJobs.push_back(statKey);
|
||||
// processjob has the format ProcessJob,sourcename,jobkey,platformname
|
||||
AZStd::vector<AZStd::string> tokens;
|
||||
AZ::StringFunc::Tokenize(statKey, tokens, ",", false, false);
|
||||
AZStd::string_view jobKey = tokens[2];
|
||||
AZStd::string_view platformName = tokens[3];
|
||||
|
||||
// synthesize a stat to record process time accumulated by job key platform
|
||||
{
|
||||
AZStd::string newStatKey = AZStd::string::format("ProcessJobsByPlatform,%.*s", AZ_STRING_ARG(platformName));
|
||||
auto insertion = m_stats.insert(newStatKey);
|
||||
StatsEntry& statToSynth = insertion.first->second;
|
||||
statToSynth.m_cumulativeTime += statistic.m_cumulativeTime;
|
||||
statToSynth.m_operationCount += statistic.m_operationCount;
|
||||
if (insertion.second)
|
||||
{
|
||||
allProcessJobsByPlatform.push_back(newStatKey);
|
||||
}
|
||||
}
|
||||
|
||||
// synthesize a stat to record process time accumulated job key total across all platforms
|
||||
{
|
||||
AZStd::string newStatKey = AZStd::string::format("ProcessJobsByJobKey,%.*s", AZ_STRING_ARG(jobKey));
|
||||
auto insertion = m_stats.insert(newStatKey);
|
||||
StatsEntry& statToSynth = insertion.first->second;
|
||||
statToSynth.m_cumulativeTime += statistic.m_cumulativeTime;
|
||||
statToSynth.m_operationCount += statistic.m_operationCount;
|
||||
if (insertion.second)
|
||||
{
|
||||
allProcessJobsByJobKey.push_back(newStatKey);
|
||||
}
|
||||
}
|
||||
// synthesize a stat to track total processjob times:
|
||||
{
|
||||
StatsEntry& statToSynth = m_stats["ProcessJobsTotal"];
|
||||
statToSynth.m_cumulativeTime += statistic.m_cumulativeTime;
|
||||
statToSynth.m_operationCount += statistic.m_operationCount;
|
||||
}
|
||||
}
|
||||
else if (AZ::StringFunc::StartsWith(statKey, "HashFile,", true))
|
||||
{
|
||||
allHashFiles.push_back(statKey);
|
||||
// processjob has the format ProcessJob,sourcename,jobkey,platformname
|
||||
// synthesize a stat to track total hash times:
|
||||
StatsEntry& statToSynth = m_stats["HashFileTotal"];
|
||||
statToSynth.m_cumulativeTime += statistic.m_cumulativeTime;
|
||||
statToSynth.m_operationCount += statistic.m_operationCount;
|
||||
}
|
||||
}
|
||||
|
||||
StatsEntry& gemLoadStat = m_stats["LoadingModules"];
|
||||
PrintStat("LoadingGems", gemLoadStat.m_cumulativeTime, 1);
|
||||
// analysis-related stats
|
||||
|
||||
StatsEntry& totalScanTime = m_stats["AssetScanning"];
|
||||
PrintStat("AssetScanning", totalScanTime.m_cumulativeTime, totalScanTime.m_operationCount);
|
||||
StatsEntry& totalHashTime = m_stats["HashFileTotal"];
|
||||
PrintStat("HashFileTotal", totalHashTime.m_cumulativeTime, totalHashTime.m_operationCount);
|
||||
PrintStatsArray(allHashFiles, maxIndividualStats, "longest individual file hashes:");
|
||||
|
||||
// CreateJobs stats
|
||||
StatsEntry& totalCreateJobs = m_stats["CreateJobsTotal"];
|
||||
if (totalCreateJobs.m_operationCount)
|
||||
{
|
||||
PrintStat("CreateJobsTotal", totalCreateJobs.m_cumulativeTime, totalCreateJobs.m_operationCount);
|
||||
PrintStatsArray(allCreateJobs, maxIndividualStats, "longest individual CreateJobs");
|
||||
PrintStatsArray(allCreateJobsByBuilder, maxCumulativeStats, "longest CreateJobs By builder");
|
||||
}
|
||||
|
||||
// ProcessJobs stats
|
||||
StatsEntry& totalProcessJobs = m_stats["ProcessJobsTotal"];
|
||||
if (totalProcessJobs.m_operationCount)
|
||||
{
|
||||
PrintStat("ProcessJobsTotal", totalProcessJobs.m_cumulativeTime, totalProcessJobs.m_operationCount);
|
||||
PrintStatsArray(allProcessJobs, maxIndividualStats, "longest individual ProcessJob");
|
||||
PrintStatsArray(allProcessJobsByJobKey, maxCumulativeStats, "cumulative time spent in ProcessJob by JobKey");
|
||||
PrintStatsArray(allProcessJobsByPlatform, maxCumulativeStats, "cumulative time spent in ProcessJob by Platform");
|
||||
}
|
||||
duration costToGenerateStats = AZStd::chrono::high_resolution_clock::now() - startTimeStamp;
|
||||
PrintStat("ComputeStatsTime", costToGenerateStats, 1);
|
||||
}
|
||||
|
||||
// Public interface:
|
||||
static StatsCaptureImpl* g_instance = nullptr;
|
||||
|
||||
//! call this one time before capturing stats.
|
||||
void Initialize()
|
||||
{
|
||||
if (g_instance)
|
||||
{
|
||||
AZ_Assert(false, "An instance of StatsCaptureImpl already exists.");
|
||||
return;
|
||||
}
|
||||
g_instance = aznew StatsCaptureImpl();
|
||||
}
|
||||
|
||||
//! Call this one time as part of shutting down.
|
||||
//! note that while it is an error to double-initialize, it is intentionally
|
||||
//! not an error to call any other function when uninitialized, allowing this system
|
||||
//! to essentially be "turned off" just by not initializing it in the first place.
|
||||
void Shutdown()
|
||||
{
|
||||
if (g_instance)
|
||||
{
|
||||
delete g_instance;
|
||||
g_instance = nullptr;
|
||||
}
|
||||
}
|
||||
|
||||
//! Start the clock running for a particular stat name.
|
||||
void BeginCaptureStat(AZStd::string_view statName)
|
||||
{
|
||||
if (g_instance)
|
||||
{
|
||||
g_instance->BeginCaptureStat(statName);
|
||||
}
|
||||
}
|
||||
|
||||
//! Stop the clock running for a particular stat name.
|
||||
void EndCaptureStat(AZStd::string_view statName)
|
||||
{
|
||||
if (g_instance)
|
||||
{
|
||||
g_instance->EndCaptureStat(statName);
|
||||
}
|
||||
}
|
||||
|
||||
//! Do additional processing and then write the cumulative stats to log.
|
||||
//! Note that since this is an AP-specific system, the analysis done in the dump function
|
||||
//! is going to make a lot of assumptions about the way the data is encoded.
|
||||
void Dump()
|
||||
{
|
||||
if (g_instance)
|
||||
{
|
||||
g_instance->Dump();
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,40 @@
|
||||
/*
|
||||
* Copyright (c) Contributors to the Open 3D Engine Project.
|
||||
* For complete copyright and license terms please see the LICENSE at the root of this distribution.
|
||||
*
|
||||
* SPDX-License-Identifier: Apache-2.0 OR MIT
|
||||
*
|
||||
*/
|
||||
|
||||
// This is an AssetProcessor-only stats capture system. Its kept out-of-band
|
||||
// from the rest of the Asset Processor systems so that it can avoid interfering
|
||||
// with the rest of the processing decision making and other parts of AssetProcessor.
|
||||
// This is not meant to be used anywhere except in AssetProcessor.
|
||||
|
||||
#pragma once
|
||||
|
||||
#include <AzCore/std/string/string_view.h>
|
||||
|
||||
namespace AssetProcessor
|
||||
{
|
||||
namespace StatsCapture
|
||||
{
|
||||
//! call this one time before capturing stats.
|
||||
void Initialize();
|
||||
|
||||
//! Call this one time as part of shutting down.
|
||||
void Shutdown();
|
||||
|
||||
//! Start the clock running for a particular stat name.
|
||||
void BeginCaptureStat(AZStd::string_view statName);
|
||||
|
||||
//! Stop the clock running for a particular stat name.
|
||||
void EndCaptureStat(AZStd::string_view statName);
|
||||
|
||||
//! Do additional processing and then write the cumulative stats to log.
|
||||
//! Note that since this is an AP-specific system, the analysis done in the dump function
|
||||
//! is going to make a lot of assumptions about the way the data is encoded.
|
||||
void Dump();
|
||||
}
|
||||
|
||||
}
|
||||
@@ -10,9 +10,10 @@
|
||||
#include <AzCore/Component/ComponentApplication.h>
|
||||
#include <AzCore/Math/Sha1.h>
|
||||
|
||||
#include "native/utilities/PlatformConfiguration.h"
|
||||
#include "native/AssetManager/FileStateCache.h"
|
||||
#include "native/AssetDatabase/AssetDatabase.h"
|
||||
#include <native/utilities/PlatformConfiguration.h>
|
||||
#include <native/utilities/StatsCapture.h>
|
||||
#include <native/AssetManager/FileStateCache.h>
|
||||
#include <native/AssetDatabase/AssetDatabase.h>
|
||||
#include <utilities/ThreadHelper.h>
|
||||
#include <QCoreApplication>
|
||||
#include <QElapsedTimer>
|
||||
|
||||
Reference in New Issue
Block a user