feat: add Timings API

Dalamud/Dalamud.cs

@@ -27,6 +27,7 @@ using Dalamud.Plugin.Internal;
 using Dalamud.Plugin.Ipc.Internal;
 using Dalamud.Support;
 using Dalamud.Utility;
+using Dalamud.Utility.Timing;
 using Serilog;
 using Serilog.Core;
 using Serilog.Events;
@@ -97,10 +98,10 @@ namespace Dalamud
         /// </summary>
         public void LoadTier1()
         {
+            using var tier1Timing = Timings.Start("Tier 1 Init");
+
             try
             {
-                ThreadSafety.MarkMainThread();
-
                 SerilogEventSink.Instance.LogLine += SerilogOnLogLine;
 
                 Service<ServiceContainer>.Set();
@@ -112,7 +113,6 @@ namespace Dalamud
                 // Initialize game fixes
                 var gameFixes = Service<GameFixes>.Set();
                 gameFixes.Apply();
-
                 Log.Information("[T1] GameFixes OK!");
 
                 // Signal the main game thread to continue
@@ -120,8 +120,11 @@ namespace Dalamud
                 Log.Information("[T1] Game thread continued!");
 
                 // Initialize FFXIVClientStructs function resolver
-                FFXIVClientStructs.Resolver.Initialize();
+                using (Timings.Start("FFXIVClientStructs Resolver Init"))
-                Log.Information("[T1] FFXIVClientStructs initialized!");
+                {
+                    FFXIVClientStructs.Resolver.Initialize();
+                    Log.Information("[T1] FFXIVClientStructs initialized!");
+                }
 
                 // Initialize game subsystem
                 var framework = Service<Framework>.Set();
@@ -151,6 +154,11 @@ namespace Dalamud
         /// <returns>Whether or not the load succeeded.</returns>
         public bool LoadTier2()
         {
+            // This marks the first time we are actually on the game's main thread
+            ThreadSafety.MarkMainThread();
+
+            using var tier2Timing = Timings.Start("Tier 2 Init");
+
             try
             {
                 var configuration = Service<DalamudConfiguration>.Get();
@@ -252,33 +260,48 @@ namespace Dalamud
         /// <returns>Whether or not the load succeeded.</returns>
         public bool LoadTier3()
         {
+            using var tier3Timing = Timings.Start("Tier 3 Init");
+
+            ThreadSafety.AssertMainThread();
+
             try
             {
                 Log.Information("[T3] START!");
 
                 Service<TitleScreenMenu>.Set();
 
-                var pluginManager = Service<PluginManager>.Set();
+                PluginManager pluginManager;
-                Service<CallGate>.Set();
+                using (Timings.Start("PM Init"))
-
+                {
-                Log.Information("[T3] PM OK!");
+                    pluginManager = Service<PluginManager>.Set();
+                    Service<CallGate>.Set();
+                    Log.Information("[T3] PM OK!");
+                }
 
                 Service<DalamudInterface>.Set();
                 Log.Information("[T3] DUI OK!");
 
                 try
                 {
-                    _ = pluginManager.SetPluginReposFromConfigAsync(false);
+                    using (Timings.Start("PM Load Plugin Repos"))
+                    {
+                        _ = pluginManager.SetPluginReposFromConfigAsync(false);
+                        pluginManager.OnInstalledPluginsChanged += Troubleshooting.LogTroubleshooting;
 
-                    pluginManager.OnInstalledPluginsChanged += Troubleshooting.LogTroubleshooting;
+                        Log.Information("[T3] PM repos OK!");
+                    }
 
-                    Log.Information("[T3] Sync plugins OK!");
+                    using (Timings.Start("PM Cleanup Plugins"))
+                    {
+                        pluginManager.CleanupPlugins();
+                        Log.Information("[T3] PMC OK!");
+                    }
 
-                    pluginManager.CleanupPlugins();
+                    using (Timings.Start("PM Load Sync Plugins"))
-                    Log.Information("[T3] PMC OK!");
+                    {
-
+                        pluginManager.LoadAllPlugins();
-                    pluginManager.LoadAllPlugins();
+                        Log.Information("[T3] PML OK!");
-                    Log.Information("[T3] PML OK!");
+                    }
                 }
                 catch (Exception ex)
                 {

Dalamud/Interface/Internal/InterfaceManager.cs

@@ -21,6 +21,7 @@ using Dalamud.Interface.Internal.Notifications;
 using Dalamud.Interface.Style;
 using Dalamud.Interface.Windowing;
 using Dalamud.Utility;
+using Dalamud.Utility.Timing;
 using ImGuiNET;
 using ImGuiScene;
 using PInvoke;
@@ -633,6 +634,8 @@ namespace Dalamud.Interface.Internal
         /// <param name="disableBigFonts">If set, then glyphs will be loaded in smaller resolution to make all glyphs fit into given constraints.</param>
         private unsafe void SetupFonts(bool disableBigFonts = false)
         {
+            using var setupFontsTimings = Timings.Start("IM SetupFonts");
+
             var gameFontManager = Service<GameFontManager>.Get();
             var dalamud = Service<Dalamud>.Get();
             var io = ImGui.GetIO();

Dalamud/Utility/Timing/TimingHandle.cs

@@ -0,0 +1,121 @@
+using System;
+using System.Diagnostics;
+using System.Linq;
+
+namespace Dalamud.Utility.Timing;
+
+/// <summary>
+/// Class used for tracking a time interval taken.
+/// </summary>
+[DebuggerDisplay("{Name} - {Duration}")]
+public sealed class TimingHandle : IDisposable
+{
+    /// <summary>
+    /// Initializes a new instance of the <see cref="TimingHandle"/> class.
+    /// </summary>
+    /// <param name="name">The name of this timing.</param>
+    internal TimingHandle(string name)
+    {
+        this.Name = name;
+
+        this.Parent = Timings.Current.Value;
+        Timings.Current.Value = this;
+
+        lock (Timings.AllTimings)
+        {
+            if (this.Parent != null)
+            {
+                this.ChildCount++;
+            }
+
+            this.StartTime = Timings.Stopwatch.Elapsed.TotalMilliseconds;
+            this.EndTime = this.StartTime;
+            this.IsMainThread = ThreadSafety.IsMainThread;
+
+            if (Timings.ActiveTimings.Count > 0)
+            {
+                this.Depth = Timings.ActiveTimings.Max(x => x.Depth) + 1;
+            }
+
+            Timings.ActiveTimings.Add(this);
+        }
+    }
+
+    /// <summary>
+    /// Gets the time this timing started.
+    /// </summary>
+    public double StartTime { get; private set; }
+
+    /// <summary>
+    /// Gets the time this timing ended.
+    /// </summary>
+    public double EndTime { get; private set; }
+
+    /// <summary>
+    /// Gets the duration of this timing.
+    /// </summary>
+    public double Duration => Math.Floor(this.EndTime - this.StartTime);
+
+    /// <summary>
+    /// Gets the parent timing.
+    /// </summary>
+    public TimingHandle? Parent { get; private set; }
+
+    /// <summary>
+    /// Gets a value indicating whether or not this timing has already returned to its parent.
+    /// </summary>
+    public bool Returned { get; private set; }
+
+    /// <summary>
+    /// Gets a value indicating whether or not this timing was started on the main thread.
+    /// </summary>
+    public bool IsMainThread { get; private set; }
+
+    /// <summary>
+    /// Gets the number of child timings.
+    /// </summary>
+    public uint ChildCount { get; private set; }
+
+    /// <summary>
+    /// Gets the depth of this timing.
+    /// </summary>
+    public uint Depth { get; private set; }
+
+    /// <summary>
+    /// Gets the name of the timing.
+    /// </summary>
+    public string Name { get; init; }
+
+    /// <summary>
+    /// Gets the member that created this timing.
+    /// </summary>
+    public string? MemberName { get; init; }
+
+    /// <summary>
+    /// Gets the file name that created this timing.
+    /// </summary>
+    public string? FileName { get; init; }
+
+    /// <summary>
+    /// Gets the line number that created this timing.
+    /// </summary>
+    public int LineNumber { get; init; }
+
+    /// <inheritdoc/>
+    public void Dispose()
+    {
+        this.EndTime = Timings.Stopwatch.Elapsed.TotalMilliseconds;
+        Timings.Current.Value = this.Parent;
+
+        lock (Timings.AllTimings)
+        {
+            if (this.Duration > 1 || this.ChildCount > 0)
+            {
+                Timings.AllTimings.Add(this);
+                this.Returned = this.Parent != null && Timings.ActiveTimings.Contains(this.Parent);
+            }
+
+            Timings.ActiveTimings.Remove(this);
+        }
+    }
+}

Dalamud/Utility/Timing/Timings.cs

@@ -0,0 +1,51 @@
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Runtime.CompilerServices;
+using System.Threading;
+
+namespace Dalamud.Utility.Timing;
+
+/// <summary>
+/// Class for measuring time taken in various subsystems.
+/// </summary>
+public static class Timings
+{
+    /// <summary>
+    /// Stopwatch used for timing.
+    /// </summary>
+    internal static readonly Stopwatch Stopwatch = Stopwatch.StartNew();
+
+    /// <summary>
+    /// All concluded timings.
+    /// </summary>
+    internal static readonly List<TimingHandle> AllTimings = new();
+
+    /// <summary>
+    /// All active timings.
+    /// </summary>
+    internal static readonly List<TimingHandle> ActiveTimings = new();
+
+    /// <summary>
+    /// Current active timing entry.
+    /// </summary>
+    internal static readonly AsyncLocal<TimingHandle> Current = new();
+
+    /// <summary>
+    /// Start a new timing.
+    /// </summary>
+    /// <param name="name">The name of the timing.</param>
+    /// <param name="memberName">Name of the calling member.</param>
+    /// <param name="sourceFilePath">Name of the calling file.</param>
+    /// <param name="sourceLineNumber">Name of the calling line number.</param>
+    /// <returns>Disposable that stops the timing once disposed.</returns>
+    public static IDisposable Start(string name, [CallerMemberName] string memberName = "", [CallerFilePath] string sourceFilePath = "", [CallerLineNumber] int sourceLineNumber = 0)
+    {
+        return new TimingHandle(name)
+        {
+            MemberName = memberName,
+            FileName = sourceFilePath,
+            LineNumber = sourceLineNumber,
+        };
+    }
+}