Add Stopwatch for accurate duration measuring

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();
+    stopwatch.Stop();
-    LOG(Info, "Assembly \'{0}\' scanned for custom editors in {1} ms", assembly->ToString(), (int32)(endTime - startTime).GetTotalMilliseconds());
+    LOG(Info, "Assembly \'{0}\' scanned for custom editors in {1} ms", assembly->ToString(), stopwatch.GetMilliseconds());
 }
 
 void OnAssemblyUnloading(MAssembly* assembly)

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<int32>((DateTime::Now() - loadStartTime).GetTotalMilliseconds());
+    stopwatch.Stop();
-    LOG(Info, "Asset Cache loaded {0} entries in {1} ms ({2} rejected)", _registry.Count(), loadTimeInMs, rejectedCount);
+    LOG(Info, "Asset Cache loaded {0} entries in {1} ms ({2} rejected)", _registry.Count(), stopwatch.GetMilliseconds(), rejectedCount);
 }
 
 bool AssetsCache::Save()

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"
+
+/// <summary>
+/// High-resolution performance counter based on Platform::GetTimeSeconds.
+/// </summary>
+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();
+    }
+
+    /// <summary>
+    /// Gets the milliseconds time.
+    /// </summary>
+    FORCE_INLINE int32 GetMilliseconds() const
+    {
+        return (int32)((_end - _start) * 1000.0);
+    }
+
+    /// <summary>
+    /// Gets the total number of milliseconds.
+    /// </summary>
+    FORCE_INLINE double GetTotalMilliseconds() const
+    {
+        return (float)((_end - _start) * 1000.0);
+    }
+
+    /// <summary>
+    /// Gets the total number of seconds.
+    /// </summary>
+    FORCE_INLINE float GetTotalSeconds() const
+    {
+        return (float)(_end - _start);
+    }
+};
+
+template<>
+struct TIsPODType<Stopwatch>
+{
+    enum { Value = true };
+};

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();
+    Stopwatch stopwatch;
-    _lastSceneLoadTime = startTime;
+    _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
+    stopwatch.Stop();
-    LOG(Info, "Scene saved! Time {0} ms", Math::CeilToInt(static_cast<float>((DateTime::NowUTC() - startTime).GetTotalMilliseconds())));
+    LOG(Info, "Scene saved! Time {0}ms", stopwatch.GetMilliseconds());
 
     // Fire event
     CallSceneEvent(SceneEventType::OnSceneSaved, scene, scene->GetID());

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"

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;
 };

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();
+    stopwatch.Stop();
-    LOG(Info, "Assembly {0} loaded in {1}ms", String(_name), (int32)(endTime - startTime).GetTotalMilliseconds());
+    LOG(Info, "Assembly {0} loaded in {1}ms", String(_name), stopwatch.GetMilliseconds());
 
     // Pre-cache classes
     GetClasses();

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();
+    stopwatch.Stop();
-    LOG(Info, "Caching classes for assembly {0} took {1}ms", String(_name), (int32)(endTime - startTime).GetTotalMilliseconds());
+    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

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;
 }
 

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();
+    stopwatch.Stop();
-    LOG(Info, "Scripting Engine initializated! (time: {0}ms)", (int32)((endTime - startTime).GetTotalMilliseconds()));
+    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();
+                        stopwatch.Stop();
-                        LOG(Info, "Module {0} loaded in {1}ms", name, (int32)(endTime - startTime).GetTotalMilliseconds());
+                        LOG(Info, "Module {0} loaded in {1}ms", name, stopwatch.GetMilliseconds());
 
                         // Get the binary module
                         module = getBinaryFunc();