From 1a0d466443cd10b11851d4f78702bf6d79539df6 Mon Sep 17 00:00:00 2001 From: Nicholas Lawson <70027408+lawsonamzn@users.noreply.github.com> Date: Mon, 22 Nov 2021 11:18:19 -0800 Subject: [PATCH] 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> --- .../assetprocessor_static_files.cmake | 2 + .../assetprocessor_test_files.cmake | 1 + .../AssetManager/assetProcessorManager.cpp | 24 ++ .../tests/utilities/StatsCaptureTest.cpp | 200 +++++++++ .../native/utilities/ApplicationManager.cpp | 14 +- .../utilities/ApplicationManagerBase.cpp | 1 + .../native/utilities/StatsCapture.cpp | 394 ++++++++++++++++++ .../native/utilities/StatsCapture.h | 40 ++ .../native/utilities/assetUtils.cpp | 7 +- Registry/AssetProcessorPlatformConfig.setreg | 13 + 10 files changed, 692 insertions(+), 4 deletions(-) create mode 100644 Code/Tools/AssetProcessor/native/tests/utilities/StatsCaptureTest.cpp create mode 100644 Code/Tools/AssetProcessor/native/utilities/StatsCapture.cpp create mode 100644 Code/Tools/AssetProcessor/native/utilities/StatsCapture.h diff --git a/Code/Tools/AssetProcessor/assetprocessor_static_files.cmake b/Code/Tools/AssetProcessor/assetprocessor_static_files.cmake index bce2458477..aa1d85d433 100644 --- a/Code/Tools/AssetProcessor/assetprocessor_static_files.cmake +++ b/Code/Tools/AssetProcessor/assetprocessor_static_files.cmake @@ -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 diff --git a/Code/Tools/AssetProcessor/assetprocessor_test_files.cmake b/Code/Tools/AssetProcessor/assetprocessor_test_files.cmake index 6aebc8bc25..3a336ce97b 100644 --- a/Code/Tools/AssetProcessor/assetprocessor_test_files.cmake +++ b/Code/Tools/AssetProcessor/assetprocessor_test_files.cmake @@ -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 diff --git a/Code/Tools/AssetProcessor/native/AssetManager/assetProcessorManager.cpp b/Code/Tools/AssetProcessor/native/AssetManager/assetProcessorManager.cpp index 05fe760bcb..de0f919a14 100644 --- a/Code/Tools/AssetProcessor/native/AssetManager/assetProcessorManager.cpp +++ b/Code/Tools/AssetProcessor/native/AssetManager/assetProcessorManager.cpp @@ -25,6 +25,7 @@ #include #include +#include #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 diff --git a/Code/Tools/AssetProcessor/native/tests/utilities/StatsCaptureTest.cpp b/Code/Tools/AssetProcessor/native/tests/utilities/StatsCaptureTest.cpp new file mode 100644 index 0000000000..ed7177e841 --- /dev/null +++ b/Code/Tools/AssetProcessor/native/tests/utilities/StatsCaptureTest.cpp @@ -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 +#include +#include +#include +#include +#include +#include + +// 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 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 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"; +} + +} + diff --git a/Code/Tools/AssetProcessor/native/utilities/ApplicationManager.cpp b/Code/Tools/AssetProcessor/native/utilities/ApplicationManager.cpp index a024ce6c7a..7a14f158d6 100644 --- a/Code/Tools/AssetProcessor/native/utilities/ApplicationManager.cpp +++ b/Code/Tools/AssetProcessor/native/utilities/ApplicationManager.cpp @@ -16,7 +16,8 @@ #include #include -#include "native/resourcecompiler/RCBuilder.h" +#include +#include #include #include @@ -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; } diff --git a/Code/Tools/AssetProcessor/native/utilities/ApplicationManagerBase.cpp b/Code/Tools/AssetProcessor/native/utilities/ApplicationManagerBase.cpp index 966b0f6723..eb230ce336 100644 --- a/Code/Tools/AssetProcessor/native/utilities/ApplicationManagerBase.cpp +++ b/Code/Tools/AssetProcessor/native/utilities/ApplicationManagerBase.cpp @@ -1173,6 +1173,7 @@ void ApplicationManagerBase::InitBuilderManager() { m_builderManager->ConnectionLost(connId); }); + } void ApplicationManagerBase::ShutdownBuilderManager() diff --git a/Code/Tools/AssetProcessor/native/utilities/StatsCapture.cpp b/Code/Tools/AssetProcessor/native/utilities/StatsCapture.cpp new file mode 100644 index 0000000000..1174e2500c --- /dev/null +++ b/Code/Tools/AssetProcessor/native/utilities/StatsCapture.cpp @@ -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 +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +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 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(static_cast(milliseconds.count()) / static_cast(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& 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(maxCumulativeStats); + AZ::u64 individualStats = static_cast(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(cumulativeStats); + maxIndividualStats = static_cast(individualStats); + } + + if ((!m_dumpHumanReadableStats)&&(!m_dumpMachineReadableStats)) + { + return; + } + + AZStd::vector allCreateJobs; // individual + AZStd::vector allCreateJobsByBuilder; // bucketed by builder + AZStd::vector allProcessJobs; // individual + AZStd::vector allProcessJobsByPlatform; // bucketed by platform + AZStd::vector allProcessJobsByJobKey; // bucketed by type of job (job key) + AZStd::vector allHashFiles; + + // capture only existing keys as we will be expanding the stats + // this approach avoids mutating an iterator. + AZStd::vector 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 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 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(); + } + } + } +} diff --git a/Code/Tools/AssetProcessor/native/utilities/StatsCapture.h b/Code/Tools/AssetProcessor/native/utilities/StatsCapture.h new file mode 100644 index 0000000000..dd3c9abccf --- /dev/null +++ b/Code/Tools/AssetProcessor/native/utilities/StatsCapture.h @@ -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 + +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(); + } + +} diff --git a/Code/Tools/AssetProcessor/native/utilities/assetUtils.cpp b/Code/Tools/AssetProcessor/native/utilities/assetUtils.cpp index 340f5343bd..ae70ee7fe5 100644 --- a/Code/Tools/AssetProcessor/native/utilities/assetUtils.cpp +++ b/Code/Tools/AssetProcessor/native/utilities/assetUtils.cpp @@ -10,9 +10,10 @@ #include #include -#include "native/utilities/PlatformConfiguration.h" -#include "native/AssetManager/FileStateCache.h" -#include "native/AssetDatabase/AssetDatabase.h" +#include +#include +#include +#include #include #include #include diff --git a/Registry/AssetProcessorPlatformConfig.setreg b/Registry/AssetProcessorPlatformConfig.setreg index c8d8dd9a80..cf793a9802 100644 --- a/Registry/AssetProcessorPlatformConfig.setreg +++ b/Registry/AssetProcessorPlatformConfig.setreg @@ -21,6 +21,19 @@ "Amazon": { "AssetProcessor": { "Settings": { + "Stats": { + // Setting MachineReadable to true will output stats in more of a CSV-like format that is ideal for script ingestion + "MachineReadable" : false, + // Setting HumanReadable to true will output stats in a friendly human format that is ideal for human reading + "HumanReadable" : true, + // To turn off stats output entirely, set both HumanReadable and MachineReadable to false. + // the maximum number of stats to show for cumulative stats like the time taken + // across all jobs of a certain type, or all jobs cumulative across a whole platform + "MaxCumulativeStats" : 4, + // the maximum number of stats to show for individual stats like how long a specific + // individual job took. + "MaxIndividualStats" : 4 + }, "Platform pc": { "tags": "tools,renderer,dx12,vulkan,null" },