From 69b7a10c1f20624c2b10fd485651bb1a319c3afd Mon Sep 17 00:00:00 2001 From: Wojtek Figat Date: Sun, 28 Jan 2024 20:31:03 +0100 Subject: [PATCH] Add `Stopwatch` for accurate duration measuring --- .../CustomEditors/CustomEditorsUtil.cpp | 7 +- Source/Engine/Content/Cache/AssetsCache.cpp | 8 ++- Source/Engine/Core/Types/Stopwatch.h | 64 +++++++++++++++++++ Source/Engine/Level/Level.cpp | 22 +++---- Source/Engine/Level/Scene/SceneCSGData.h | 3 +- .../Engine/Scripting/ManagedCLR/MAssembly.h | 2 +- Source/Engine/Scripting/ManagedCLR/MCore.cpp | 11 ++-- Source/Engine/Scripting/Runtime/DotNet.cpp | 16 +++-- Source/Engine/Scripting/Runtime/Mono.cpp | 5 +- Source/Engine/Scripting/Scripting.cpp | 16 ++--- 10 files changed, 113 insertions(+), 41 deletions(-) create mode 100644 Source/Engine/Core/Types/Stopwatch.h diff --git a/Source/Editor/CustomEditors/CustomEditorsUtil.cpp b/Source/Editor/CustomEditors/CustomEditorsUtil.cpp index d0c10c13d..cf0b6e4d7 100644 --- a/Source/Editor/CustomEditors/CustomEditorsUtil.cpp +++ b/Source/Editor/CustomEditors/CustomEditorsUtil.cpp @@ -4,6 +4,7 @@ #include "Engine/Core/Log.h" #include "Engine/Core/Types/DateTime.h" #include "Engine/Core/Types/TimeSpan.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Core/Collections/Dictionary.h" #include "Engine/Engine/EngineService.h" #include "Engine/Scripting/Scripting.h" @@ -81,7 +82,7 @@ bool CustomEditorsUtilService::Init() void OnAssemblyLoaded(MAssembly* assembly) { - const auto startTime = DateTime::NowUTC(); + Stopwatch stopwatch; // Prepare FlaxEngine auto engineAssembly = ((NativeBinaryModule*)GetBinaryModuleFlaxEngine())->Assembly; @@ -162,8 +163,8 @@ void OnAssemblyLoaded(MAssembly* assembly) } } - const auto endTime = DateTime::NowUTC(); - LOG(Info, "Assembly \'{0}\' scanned for custom editors in {1} ms", assembly->ToString(), (int32)(endTime - startTime).GetTotalMilliseconds()); + stopwatch.Stop(); + LOG(Info, "Assembly \'{0}\' scanned for custom editors in {1} ms", assembly->ToString(), stopwatch.GetMilliseconds()); } void OnAssemblyUnloading(MAssembly* assembly) diff --git a/Source/Engine/Content/Cache/AssetsCache.cpp b/Source/Engine/Content/Cache/AssetsCache.cpp index c9a10f721..e9ce23e1a 100644 --- a/Source/Engine/Content/Cache/AssetsCache.cpp +++ b/Source/Engine/Content/Cache/AssetsCache.cpp @@ -4,6 +4,8 @@ #include "Engine/Core/Log.h" #include "Engine/Core/DeleteMe.h" #include "Engine/Core/Types/TimeSpan.h" +#include "Engine/Core/Types/DateTime.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Platform/FileSystem.h" #include "Engine/Serialization/FileWriteStream.h" #include "Engine/Serialization/FileReadStream.h" @@ -19,7 +21,7 @@ void AssetsCache::Init() { Entry e; int32 count; - const DateTime loadStartTime = DateTime::Now(); + Stopwatch stopwatch; #if USE_EDITOR _path = Globals::ProjectCacheFolder / TEXT("AssetsCache.dat"); #else @@ -138,8 +140,8 @@ void AssetsCache::Init() } } - const int32 loadTimeInMs = static_cast((DateTime::Now() - loadStartTime).GetTotalMilliseconds()); - LOG(Info, "Asset Cache loaded {0} entries in {1} ms ({2} rejected)", _registry.Count(), loadTimeInMs, rejectedCount); + stopwatch.Stop(); + LOG(Info, "Asset Cache loaded {0} entries in {1} ms ({2} rejected)", _registry.Count(), stopwatch.GetMilliseconds(), rejectedCount); } bool AssetsCache::Save() diff --git a/Source/Engine/Core/Types/Stopwatch.h b/Source/Engine/Core/Types/Stopwatch.h new file mode 100644 index 000000000..675f826a4 --- /dev/null +++ b/Source/Engine/Core/Types/Stopwatch.h @@ -0,0 +1,64 @@ +// Copyright (c) 2012-2023 Wojciech Figat. All rights reserved. + +#pragma once + +#include "BaseTypes.h" +#include "Engine/Platform/Platform.h" + +/// +/// High-resolution performance counter based on Platform::GetTimeSeconds. +/// +API_STRUCT(InBuild, Namespace="System.Diagnostics") struct FLAXENGINE_API Stopwatch +{ +private: + double _start, _end; + +public: + Stopwatch() + { + _start = _end = Platform::GetTimeSeconds(); + } + +public: + // Starts the counter. + void Start() + { + _start = Platform::GetTimeSeconds(); + } + + // Stops the counter. + void Stop() + { + _end = Platform::GetTimeSeconds(); + } + + /// + /// Gets the milliseconds time. + /// + FORCE_INLINE int32 GetMilliseconds() const + { + return (int32)((_end - _start) * 1000.0); + } + + /// + /// Gets the total number of milliseconds. + /// + FORCE_INLINE double GetTotalMilliseconds() const + { + return (float)((_end - _start) * 1000.0); + } + + /// + /// Gets the total number of seconds. + /// + FORCE_INLINE float GetTotalSeconds() const + { + return (float)(_end - _start); + } +}; + +template<> +struct TIsPODType +{ + enum { Value = true }; +}; diff --git a/Source/Engine/Level/Level.cpp b/Source/Engine/Level/Level.cpp index 160243e24..e7f193ea8 100644 --- a/Source/Engine/Level/Level.cpp +++ b/Source/Engine/Level/Level.cpp @@ -12,6 +12,7 @@ #include "Engine/Core/ObjectsRemovalService.h" #include "Engine/Core/Config/LayersTagsSettings.h" #include "Engine/Core/Types/LayersMask.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Debug/Exceptions/ArgumentException.h" #include "Engine/Debug/Exceptions/ArgumentNullException.h" #include "Engine/Debug/Exceptions/InvalidOperationException.h" @@ -868,13 +869,11 @@ bool Level::loadScene(rapidjson_flax::Document& document, Scene** outScene) bool Level::loadScene(rapidjson_flax::Value& data, int32 engineBuild, Scene** outScene) { PROFILE_CPU_NAMED("Level.LoadScene"); - if (outScene) *outScene = nullptr; - LOG(Info, "Loading scene..."); - const DateTime startTime = DateTime::NowUTC(); - _lastSceneLoadTime = startTime; + Stopwatch stopwatch; + _lastSceneLoadTime = DateTime::Now(); // Here whole scripting backend should be loaded for current project // Later scripts will setup attached scripts and restore initial vars @@ -1083,7 +1082,8 @@ bool Level::loadScene(rapidjson_flax::Value& data, int32 engineBuild, Scene** ou // Fire event CallSceneEvent(SceneEventType::OnSceneLoaded, scene, sceneId); - LOG(Info, "Scene loaded in {0} ms", (int32)(DateTime::NowUTC() - startTime).GetTotalMilliseconds()); + stopwatch.Stop(); + LOG(Info, "Scene loaded in {0}ms", stopwatch.GetMilliseconds()); if (outScene) *outScene = scene; return false; @@ -1112,7 +1112,7 @@ bool LevelImpl::saveScene(Scene* scene, const String& path) auto sceneId = scene->GetID(); LOG(Info, "Saving scene {0} to \'{1}\'", scene->GetName(), path); - const DateTime startTime = DateTime::NowUTC(); + Stopwatch stopwatch; // Serialize to json rapidjson_flax::StringBuffer buffer; @@ -1130,7 +1130,8 @@ bool LevelImpl::saveScene(Scene* scene, const String& path) return true; } - LOG(Info, "Scene saved! Time {0} ms", Math::CeilToInt((float)(DateTime::NowUTC() - startTime).GetTotalMilliseconds())); + stopwatch.Stop(); + LOG(Info, "Scene saved! Time {0}ms", stopwatch.GetMilliseconds()); #if USE_EDITOR // Reload asset at the target location if is loaded @@ -1210,9 +1211,8 @@ bool Level::SaveSceneToBytes(Scene* scene, rapidjson_flax::StringBuffer& outData { ASSERT(scene); ScopeLock lock(_sceneActionsLocker); - + Stopwatch stopwatch; LOG(Info, "Saving scene {0} to bytes", scene->GetName()); - const DateTime startTime = DateTime::NowUTC(); // Serialize to json if (saveScene(scene, outData, prettyJson)) @@ -1221,8 +1221,8 @@ bool Level::SaveSceneToBytes(Scene* scene, rapidjson_flax::StringBuffer& outData return true; } - // Info - LOG(Info, "Scene saved! Time {0} ms", Math::CeilToInt(static_cast((DateTime::NowUTC() - startTime).GetTotalMilliseconds()))); + stopwatch.Stop(); + LOG(Info, "Scene saved! Time {0}ms", stopwatch.GetMilliseconds()); // Fire event CallSceneEvent(SceneEventType::OnSceneSaved, scene, scene->GetID()); diff --git a/Source/Engine/Level/Scene/SceneCSGData.h b/Source/Engine/Level/Scene/SceneCSGData.h index ca6ed0540..baf01cacf 100644 --- a/Source/Engine/Level/Scene/SceneCSGData.h +++ b/Source/Engine/Level/Scene/SceneCSGData.h @@ -2,10 +2,11 @@ #pragma once +#include "Engine/Core/ISerializable.h" +#include "Engine/Core/Types/DateTime.h" #include "Engine/Core/Math/Triangle.h" #include "Engine/Core/Collections/Dictionary.h" #include "Engine/Physics/CollisionData.h" -#include "Engine/Core/ISerializable.h" #include "Engine/Content/AssetReference.h" #include "Engine/Content/Assets/RawDataAsset.h" #include "Engine/Content/Assets/Model.h" diff --git a/Source/Engine/Scripting/ManagedCLR/MAssembly.h b/Source/Engine/Scripting/ManagedCLR/MAssembly.h index ff1645e5e..dff3284fb 100644 --- a/Source/Engine/Scripting/ManagedCLR/MAssembly.h +++ b/Source/Engine/Scripting/ManagedCLR/MAssembly.h @@ -219,7 +219,7 @@ private: bool LoadImage(const String& assemblyPath, const StringView& nativePath); bool UnloadImage(bool isReloading); void OnLoading(); - void OnLoaded(const struct DateTime& startTime); + void OnLoaded(struct Stopwatch& stopwatch); void OnLoadFailed(); bool ResolveMissingFile(String& assemblyPath) const; }; diff --git a/Source/Engine/Scripting/ManagedCLR/MCore.cpp b/Source/Engine/Scripting/ManagedCLR/MCore.cpp index 02a834a9f..35bec8b8e 100644 --- a/Source/Engine/Scripting/ManagedCLR/MCore.cpp +++ b/Source/Engine/Scripting/ManagedCLR/MCore.cpp @@ -10,6 +10,7 @@ #include "MProperty.h" #include "Engine/Core/Math/Math.h" #include "Engine/Core/Types/DateTime.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Core/Types/TimeSpan.h" #include "Engine/Platform/FileSystem.h" #include "Engine/Profiler/ProfilerCPU.h" @@ -80,6 +81,7 @@ bool MAssembly::Load(const String& assemblyPath, const StringView& nativePath) return false; PROFILE_CPU(); ZoneText(*assemblyPath, assemblyPath.Length()); + Stopwatch stopwatch; const String* pathPtr = &assemblyPath; String path; @@ -94,7 +96,6 @@ bool MAssembly::Load(const String& assemblyPath, const StringView& nativePath) } } - const auto startTime = DateTime::NowUTC(); OnLoading(); if (LoadImage(*pathPtr, nativePath)) @@ -103,7 +104,7 @@ bool MAssembly::Load(const String& assemblyPath, const StringView& nativePath) return true; } - OnLoaded(startTime); + OnLoaded(stopwatch); return false; } @@ -173,7 +174,7 @@ void MAssembly::OnLoading() _domain = MCore::GetActiveDomain(); } -void MAssembly::OnLoaded(const DateTime& startTime) +void MAssembly::OnLoaded(Stopwatch& stopwatch) { // Register in domain _domain->_assemblies[_name] = this; @@ -181,8 +182,8 @@ void MAssembly::OnLoaded(const DateTime& startTime) _isLoaded = true; _isLoading = false; - const auto endTime = DateTime::NowUTC(); - LOG(Info, "Assembly {0} loaded in {1}ms", String(_name), (int32)(endTime - startTime).GetTotalMilliseconds()); + stopwatch.Stop(); + LOG(Info, "Assembly {0} loaded in {1}ms", String(_name), stopwatch.GetMilliseconds()); // Pre-cache classes GetClasses(); diff --git a/Source/Engine/Scripting/Runtime/DotNet.cpp b/Source/Engine/Scripting/Runtime/DotNet.cpp index 2092ea30c..6845941b2 100644 --- a/Source/Engine/Scripting/Runtime/DotNet.cpp +++ b/Source/Engine/Scripting/Runtime/DotNet.cpp @@ -9,6 +9,7 @@ #include "Engine/Core/Log.h" #include "Engine/Core/Types/DateTime.h" #include "Engine/Core/Types/TimeSpan.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Core/Collections/Dictionary.h" #include "Engine/Platform/Platform.h" #include "Engine/Platform/File.h" @@ -663,7 +664,7 @@ const MAssembly::ClassesDictionary& MAssembly::GetClasses() const if (_hasCachedClasses || !IsLoaded()) return _classes; PROFILE_CPU(); - const auto startTime = DateTime::NowUTC(); + Stopwatch stopwatch; #if TRACY_ENABLE ZoneText(*_name, _name.Length()); @@ -698,8 +699,8 @@ const MAssembly::ClassesDictionary& MAssembly::GetClasses() const MCore::GC::FreeMemory(managedClasses); - const auto endTime = DateTime::NowUTC(); - LOG(Info, "Caching classes for assembly {0} took {1}ms", String(_name), (int32)(endTime - startTime).GetTotalMilliseconds()); + stopwatch.Stop(); + LOG(Info, "Caching classes for assembly {0} took {1}ms", String(_name), stopwatch.GetMilliseconds()); #if 0 for (auto i = _classes.Begin(); i.IsNotEnd(); ++i) @@ -768,7 +769,7 @@ bool MAssembly::LoadCorlib() Unload(); // Start - const auto startTime = DateTime::NowUTC(); + Stopwatch stopwatch; OnLoading(); // Load @@ -786,7 +787,7 @@ bool MAssembly::LoadCorlib() CachedAssemblyHandles.Add(_handle, this); // End - OnLoaded(startTime); + OnLoaded(stopwatch); return false; } @@ -2051,7 +2052,7 @@ bool InitHostfxr() #ifdef USE_MONO_AOT_MODULE // Load AOT module - const DateTime aotModuleLoadStartTime = DateTime::Now(); + Stopwatch aotModuleLoadStopwatch; LOG(Info, "Loading Mono AOT module..."); void* libAotModule = Platform::LoadLibrary(TEXT(USE_MONO_AOT_MODULE)); if (libAotModule == nullptr) @@ -2076,7 +2077,8 @@ bool InitHostfxr() mono_aot_register_module((void**)modules[i]); } Allocator::Free(modules); - LOG(Info, "Mono AOT module loaded in {0}ms", (int32)(DateTime::Now() - aotModuleLoadStartTime).GetTotalMilliseconds()); + aotModuleLoadStopwatch.Stop(); + LOG(Info, "Mono AOT module loaded in {0}ms", aotModuleLoadStopwatch.GetMilliseconds()); #endif // Setup debugger diff --git a/Source/Engine/Scripting/Runtime/Mono.cpp b/Source/Engine/Scripting/Runtime/Mono.cpp index 00f16fd44..f20e1f514 100644 --- a/Source/Engine/Scripting/Runtime/Mono.cpp +++ b/Source/Engine/Scripting/Runtime/Mono.cpp @@ -7,6 +7,7 @@ #include "Engine/Core/Log.h" #include "Engine/Core/Types/DateTime.h" #include "Engine/Core/Types/TimeSpan.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Platform/File.h" #include "Engine/Platform/FileSystem.h" #include "Engine/Engine/Globals.h" @@ -1089,7 +1090,7 @@ bool MAssembly::Load(MonoImage* monoImage) Unload(); // Start - const auto startTime = DateTime::NowUTC(); + Stopwatch stopwatch; OnLoading(); // Load @@ -1103,7 +1104,7 @@ bool MAssembly::Load(MonoImage* monoImage) _hasCachedClasses = false; // End - OnLoaded(startTime); + OnLoaded(stopwatch); return false; } diff --git a/Source/Engine/Scripting/Scripting.cpp b/Source/Engine/Scripting/Scripting.cpp index 6cabbc0dd..f375b7bf0 100644 --- a/Source/Engine/Scripting/Scripting.cpp +++ b/Source/Engine/Scripting/Scripting.cpp @@ -23,7 +23,7 @@ #include "Internal/StdTypesContainer.h" #include "Engine/Core/ObjectsRemovalService.h" #include "Engine/Core/Types/TimeSpan.h" -#include "Engine/Profiler/ProfilerCPU.h" +#include "Engine/Core/Types/Stopwatch.h" #include "Engine/Content/Asset.h" #include "Engine/Content/Content.h" #include "Engine/Engine/EngineService.h" @@ -31,6 +31,7 @@ #include "Engine/Engine/Time.h" #include "Engine/Graphics/RenderTask.h" #include "Engine/Serialization/JsonTools.h" +#include "Engine/Profiler/ProfilerCPU.h" extern void registerFlaxEngineInternalCalls(); @@ -126,7 +127,7 @@ void onEngineUnloading(MAssembly* assembly); bool ScriptingService::Init() { - const auto startTime = DateTime::NowUTC(); + Stopwatch stopwatch; // Initialize managed runtime if (MCore::LoadEngine()) @@ -158,9 +159,8 @@ bool ScriptingService::Init() return true; } - auto endTime = DateTime::NowUTC(); - LOG(Info, "Scripting Engine initializated! (time: {0}ms)", (int32)((endTime - startTime).GetTotalMilliseconds())); - + stopwatch.Stop(); + LOG(Info, "Scripting Engine initializated! (time: {0}ms)", stopwatch.GetMilliseconds()); return false; } @@ -357,7 +357,7 @@ bool Scripting::LoadBinaryModules(const String& path, const String& projectFolde if (!module) { // Load library - const auto startTime = DateTime::NowUTC(); + Stopwatch stopwatch; #if PLATFORM_ANDROID || PLATFORM_MAC // On some platforms all native binaries are side-by-side with the app in a different folder if (!FileSystem::FileExists(nativePath)) @@ -390,8 +390,8 @@ bool Scripting::LoadBinaryModules(const String& path, const String& projectFolde LOG(Error, "Failed to setup library '{0}' for binary module {1}.", nativePath, name); return true; } - const auto endTime = DateTime::NowUTC(); - LOG(Info, "Module {0} loaded in {1}ms", name, (int32)(endTime - startTime).GetTotalMilliseconds()); + stopwatch.Stop(); + LOG(Info, "Module {0} loaded in {1}ms", name, stopwatch.GetMilliseconds()); // Get the binary module module = getBinaryFunc();