From 71aeee605d42ff9f4b0d137fe41be2ed9e362155 Mon Sep 17 00:00:00 2001 From: goaaats Date: Fri, 27 May 2022 16:29:12 +0200 Subject: [PATCH] feat: add Timings API --- Dalamud/Dalamud.cs | 57 ++++++--- .../Interface/Internal/InterfaceManager.cs | 3 + Dalamud/Utility/Timing/TimingHandle.cs | 121 ++++++++++++++++++ Dalamud/Utility/Timing/Timings.cs | 51 ++++++++ 4 files changed, 215 insertions(+), 17 deletions(-) create mode 100644 Dalamud/Utility/Timing/TimingHandle.cs create mode 100644 Dalamud/Utility/Timing/Timings.cs diff --git a/Dalamud/Dalamud.cs b/Dalamud/Dalamud.cs index 4389f270e..6f8498b17 100644 --- a/Dalamud/Dalamud.cs +++ b/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 /// public void LoadTier1() { + using var tier1Timing = Timings.Start("Tier 1 Init"); + try { - ThreadSafety.MarkMainThread(); - SerilogEventSink.Instance.LogLine += SerilogOnLogLine; Service.Set(); @@ -112,7 +113,6 @@ namespace Dalamud // Initialize game fixes var gameFixes = Service.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(); - Log.Information("[T1] FFXIVClientStructs initialized!"); + using (Timings.Start("FFXIVClientStructs Resolver Init")) + { + FFXIVClientStructs.Resolver.Initialize(); + Log.Information("[T1] FFXIVClientStructs initialized!"); + } // Initialize game subsystem var framework = Service.Set(); @@ -151,6 +154,11 @@ namespace Dalamud /// Whether or not the load succeeded. 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.Get(); @@ -252,33 +260,48 @@ namespace Dalamud /// Whether or not the load succeeded. public bool LoadTier3() { + using var tier3Timing = Timings.Start("Tier 3 Init"); + + ThreadSafety.AssertMainThread(); + try { Log.Information("[T3] START!"); Service.Set(); - var pluginManager = Service.Set(); - Service.Set(); - - Log.Information("[T3] PM OK!"); + PluginManager pluginManager; + using (Timings.Start("PM Init")) + { + pluginManager = Service.Set(); + Service.Set(); + Log.Information("[T3] PM OK!"); + } Service.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(); - Log.Information("[T3] PMC OK!"); - - pluginManager.LoadAllPlugins(); - Log.Information("[T3] PML OK!"); + using (Timings.Start("PM Load Sync Plugins")) + { + pluginManager.LoadAllPlugins(); + Log.Information("[T3] PML OK!"); + } } catch (Exception ex) { diff --git a/Dalamud/Interface/Internal/InterfaceManager.cs b/Dalamud/Interface/Internal/InterfaceManager.cs index a768dd2df..d105e5c27 100644 --- a/Dalamud/Interface/Internal/InterfaceManager.cs +++ b/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 /// If set, then glyphs will be loaded in smaller resolution to make all glyphs fit into given constraints. private unsafe void SetupFonts(bool disableBigFonts = false) { + using var setupFontsTimings = Timings.Start("IM SetupFonts"); + var gameFontManager = Service.Get(); var dalamud = Service.Get(); var io = ImGui.GetIO(); diff --git a/Dalamud/Utility/Timing/TimingHandle.cs b/Dalamud/Utility/Timing/TimingHandle.cs new file mode 100644 index 000000000..7bdebc420 --- /dev/null +++ b/Dalamud/Utility/Timing/TimingHandle.cs @@ -0,0 +1,121 @@ +using System; +using System.Diagnostics; +using System.Linq; + +namespace Dalamud.Utility.Timing; + +/// +/// Class used for tracking a time interval taken. +/// +[DebuggerDisplay("{Name} - {Duration}")] +public sealed class TimingHandle : IDisposable +{ + /// + /// Initializes a new instance of the class. + /// + /// The name of this timing. + 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); + } + } + + /// + /// Gets the time this timing started. + /// + public double StartTime { get; private set; } + + /// + /// Gets the time this timing ended. + /// + public double EndTime { get; private set; } + + /// + /// Gets the duration of this timing. + /// + public double Duration => Math.Floor(this.EndTime - this.StartTime); + + /// + /// Gets the parent timing. + /// + public TimingHandle? Parent { get; private set; } + + /// + /// Gets a value indicating whether or not this timing has already returned to its parent. + /// + public bool Returned { get; private set; } + + /// + /// Gets a value indicating whether or not this timing was started on the main thread. + /// + public bool IsMainThread { get; private set; } + + /// + /// Gets the number of child timings. + /// + public uint ChildCount { get; private set; } + + /// + /// Gets the depth of this timing. + /// + public uint Depth { get; private set; } + + /// + /// Gets the name of the timing. + /// + public string Name { get; init; } + + /// + /// Gets the member that created this timing. + /// + public string? MemberName { get; init; } + + /// + /// Gets the file name that created this timing. + /// + public string? FileName { get; init; } + + /// + /// Gets the line number that created this timing. + /// + public int LineNumber { get; init; } + + /// + 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); + } + } +} diff --git a/Dalamud/Utility/Timing/Timings.cs b/Dalamud/Utility/Timing/Timings.cs new file mode 100644 index 000000000..48d8d5c17 --- /dev/null +++ b/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; + +/// +/// Class for measuring time taken in various subsystems. +/// +public static class Timings +{ + /// + /// Stopwatch used for timing. + /// + internal static readonly Stopwatch Stopwatch = Stopwatch.StartNew(); + + /// + /// All concluded timings. + /// + internal static readonly List AllTimings = new(); + + /// + /// All active timings. + /// + internal static readonly List ActiveTimings = new(); + + /// + /// Current active timing entry. + /// + internal static readonly AsyncLocal Current = new(); + + /// + /// Start a new timing. + /// + /// The name of the timing. + /// Name of the calling member. + /// Name of the calling file. + /// Name of the calling line number. + /// Disposable that stops the timing once disposed. + 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, + }; + } +}