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" },