Timing test.

Penumbra/Interop/CharacterUtility.List.cs

@@ -77,11 +77,13 @@ public unsafe partial class CharacterUtility
         // Set the currently stored data of this resource to new values.
         private void SetResourceInternal( IntPtr data, int length )
         {
+            TimingManager.StartTimer( TimingType.SetResource );
             if( Ready )
             {
                 var resource = Penumbra.CharacterUtility.Address->Resource( GlobalIndex );
                 resource->SetData( data, length );
             }
+            TimingManager.StopTimer( TimingType.SetResource );
         }
 
         // Reset the currently stored data of this resource to its default values.
@@ -133,6 +135,7 @@ public unsafe partial class CharacterUtility
             {
                 if( !Disposed )
                 {
+                    TimingManager.StartTimer( TimingType.SetResource );
                     var list       = List._entries;
                     var wasCurrent = ReferenceEquals( this, list.First?.Value );
                     list.Remove( this );
@@ -159,6 +162,7 @@ public unsafe partial class CharacterUtility
                     }
 
                     Disposed = true;
+                    TimingManager.StopTimer( TimingType.SetResource );
                 }
             }
         }

Penumbra/Interop/Loader/ResourceLoader.Debug.cs

@@ -76,6 +76,7 @@ public unsafe partial class ResourceLoader
             return;
         }
 
+        TimingManager.StartTimer( TimingType.DebugTimes );
         // Got some incomprehensible null-dereference exceptions here when hot-reloading penumbra.
         try
         {
@@ -96,6 +97,7 @@ public unsafe partial class ResourceLoader
         {
             Penumbra.Log.Error( e.ToString() );
         }
+        TimingManager.StopTimer( TimingType.DebugTimes );
     }
 
     // Find a key in a StdMap.
@@ -202,6 +204,7 @@ public unsafe partial class ResourceLoader
     // Only used when the Replaced Resources Tab in the Debug tab is open.
     public void UpdateDebugInfo()
     {
+        TimingManager.StartTimer( TimingType.DebugTimes );
         for( var i = 0; i < _debugList.Count; ++i )
         {
             var data             = _debugList.Values[ i ];
@@ -220,6 +223,7 @@ public unsafe partial class ResourceLoader
                 };
             }
         }
+        TimingManager.StopTimer( TimingType.DebugTimes );
     }
 
     // Prevent resource management weirdness.

Penumbra/Interop/Loader/ResourceLoader.Replacement.cs

@@ -81,11 +81,15 @@ public unsafe partial class ResourceLoader
     internal ResourceHandle* GetResourceHandler( bool isSync, ResourceManager* resourceManager, ResourceCategory* categoryId,
         ResourceType* resourceType, int* resourceHash, byte* path, GetResourceParameters* pGetResParams, bool isUnk )
     {
+        TimingManager.StartTimer( TimingType.GetResourceHandler );
+        ResourceHandle* ret = null;
         if( !Utf8GamePath.FromPointer( path, out var gamePath ) )
         {
             Penumbra.Log.Error( "Could not create GamePath from resource path." );
-            return CallOriginalHandler( isSync, resourceManager, categoryId, resourceType, resourceHash, path, pGetResParams, isUnk );
+            ret = CallOriginalHandler( isSync, resourceManager, categoryId, resourceType, resourceHash, path, pGetResParams, isUnk );
         }
+        else
+        {
 
             CompareHash( ComputeHash( gamePath.Path, pGetResParams ), *resourceHash, gamePath );
 
@@ -99,16 +103,22 @@ public unsafe partial class ResourceLoader
                 var retUnmodified =
                     CallOriginalHandler( isSync, resourceManager, categoryId, resourceType, resourceHash, path, pGetResParams, isUnk );
                 ResourceLoaded?.Invoke( ( Structs.ResourceHandle* )retUnmodified, gamePath, null, data );
-            return retUnmodified;
+                ret = retUnmodified;
             }
+            else
+            {
 
                 // Replace the hash and path with the correct one for the replacement.
                 *resourceHash = ComputeHash( resolvedPath.Value.InternalName, pGetResParams );
 
                 path = resolvedPath.Value.InternalName.Path;
-        var retModified = CallOriginalHandler( isSync, resourceManager, categoryId, resourceType, resourceHash, path, pGetResParams, isUnk );
+                ret = CallOriginalHandler( isSync, resourceManager, categoryId, resourceType, resourceHash, path, pGetResParams, isUnk );
-        ResourceLoaded?.Invoke( ( Structs.ResourceHandle* )retModified, gamePath, resolvedPath.Value, data );
+                ResourceLoaded?.Invoke( ( Structs.ResourceHandle* )ret, gamePath, resolvedPath.Value, data );
-        return retModified;
+                
+            }
+        }
+        TimingManager.StopTimer( TimingType.GetResourceHandler );
+        return ret;
     }
 
 
@@ -164,48 +174,50 @@ public unsafe partial class ResourceLoader
 
     private byte ReadSqPackDetour( ResourceManager* resourceManager, SeFileDescriptor* fileDescriptor, int priority, bool isSync )
     {
+        TimingManager.StartTimer( TimingType.ReadSqPack );
+        byte ret = 0;
         if( !DoReplacements )
         {
-            return ReadSqPackHook.Original( resourceManager, fileDescriptor, priority, isSync );
+            ret = ReadSqPackHook.Original( resourceManager, fileDescriptor, priority, isSync );
         }
-
+        else if( fileDescriptor == null || fileDescriptor->ResourceHandle == null )
-        if( fileDescriptor == null || fileDescriptor->ResourceHandle == null )
         {
             Penumbra.Log.Error( "Failure to load file from SqPack: invalid File Descriptor." );
-            return ReadSqPackHook.Original( resourceManager, fileDescriptor, priority, isSync );
+            ret = ReadSqPackHook.Original( resourceManager, fileDescriptor, priority, isSync );
         }
-
+        else if( !Utf8GamePath.FromSpan( fileDescriptor->ResourceHandle->FileNameSpan(), out var gamePath, false ) || gamePath.Length == 0 )
-        if( !Utf8GamePath.FromSpan( fileDescriptor->ResourceHandle->FileNameSpan(), out var gamePath, false ) || gamePath.Length == 0 )
         {
-            return ReadSqPackHook.Original( resourceManager, fileDescriptor, priority, isSync );
+            ret = ReadSqPackHook.Original(resourceManager, fileDescriptor, priority, isSync);
         }
-
         // Paths starting with a '|' are handled separately to allow for special treatment.
         // They are expected to also have a closing '|'.
-        if( ResourceLoadCustomization == null || gamePath.Path[ 0 ] != ( byte )'|' )
+        else if( ResourceLoadCustomization == null || gamePath.Path[ 0 ] != ( byte )'|' )
         {
-            return DefaultLoadResource( gamePath.Path, resourceManager, fileDescriptor, priority, isSync );
+            ret = DefaultLoadResource( gamePath.Path, resourceManager, fileDescriptor, priority, isSync );
         }
-
+        else
+        {
             // Split the path into the special-treatment part (between the first and second '|')
             // and the actual path.
-        byte ret   = 0;
             var  split = gamePath.Path.Split( ( byte )'|', 3, false );
-        fileDescriptor->ResourceHandle->FileNameData   = split[ 2 ].Path;
+            fileDescriptor->ResourceHandle->FileNameData   = split[2].Path;
-        fileDescriptor->ResourceHandle->FileNameLength = split[ 2 ].Length;
+            fileDescriptor->ResourceHandle->FileNameLength = split[2].Length;
             var funcFound = fileDescriptor->ResourceHandle->Category != ResourceCategory.Ui
              && ResourceLoadCustomization.GetInvocationList()
                    .Any( f => ( ( ResourceLoadCustomizationDelegate )f )
-                   .Invoke( split[ 1 ], split[ 2 ], resourceManager, fileDescriptor, priority, isSync, out ret ) );
+                       .Invoke( split[1], split[2], resourceManager, fileDescriptor, priority, isSync, out ret ) );
 
             if( !funcFound )
             {
-            ret = DefaultLoadResource( split[ 2 ], resourceManager, fileDescriptor, priority, isSync );
+                ret = DefaultLoadResource( split[2], resourceManager, fileDescriptor, priority, isSync );
             }
 
             // Return original resource handle path so that they can be loaded separately.
             fileDescriptor->ResourceHandle->FileNameData   = gamePath.Path.Path;
             fileDescriptor->ResourceHandle->FileNameLength = gamePath.Path.Length;
+        }
+
+        TimingManager.StopTimer( TimingType.ReadSqPack );
         return ret;
     }
 

Penumbra/Interop/Resolver/PathResolver.AnimationState.cs

@@ -126,6 +126,7 @@ public unsafe partial class PathResolver
 
         private ulong LoadTimelineResourcesDetour( IntPtr timeline )
         {
+            TimingManager.StartTimer( TimingType.TimelineResources );
             ulong ret;
             var   old = _animationLoadData;
             try
@@ -152,6 +153,7 @@ public unsafe partial class PathResolver
 
             _animationLoadData = old;
 
+            TimingManager.StopTimer( TimingType.TimelineResources );
             return ret;
         }
 
@@ -246,6 +248,7 @@ public unsafe partial class PathResolver
 
         private IntPtr LoadCharacterVfxDetour( byte* vfxPath, VfxParams* vfxParams, byte unk1, byte unk2, float unk3, int unk4 )
         {
+            TimingManager.StartTimer( TimingType.LoadCharacterVfx );
             var last = _animationLoadData;
             if( vfxParams != null && vfxParams->GameObjectId != unchecked( ( uint )-1 ) )
             {
@@ -264,7 +267,6 @@ public unsafe partial class PathResolver
             {
                 _animationLoadData = ResolveData.Invalid;
             }
-
             var ret = _loadCharacterVfxHook.Original( vfxPath, vfxParams, unk1, unk2, unk3, unk4 );
 #if DEBUG
             var path = new ByteString( vfxPath );
@@ -272,6 +274,7 @@ public unsafe partial class PathResolver
                 $"Load Character VFX: {path}  {vfxParams->GameObjectId:X} {vfxParams->TargetCount} {unk1} {unk2} {unk3} {unk4} -> {ret:X} {_animationLoadData.ModCollection.Name} {_animationLoadData.AssociatedGameObject} {last.ModCollection.Name} {last.AssociatedGameObject}" );
 #endif
             _animationLoadData = last;
+            TimingManager.StopTimer( TimingType.LoadCharacterVfx );
             return ret;
         }
 
@@ -282,6 +285,7 @@ public unsafe partial class PathResolver
 
         private IntPtr LoadAreaVfxDetour( uint vfxId, float* pos, GameObject* caster, float unk1, float unk2, byte unk3 )
         {
+            TimingManager.StartTimer( TimingType.LoadAreaVfx );
             var last = _animationLoadData;
             if( caster != null )
             {
@@ -298,6 +302,7 @@ public unsafe partial class PathResolver
                 $"Load Area VFX: {vfxId}, {pos[ 0 ]} {pos[ 1 ]} {pos[ 2 ]} {( caster != null ? new ByteString( caster->GetName() ).ToString() : "Unknown" )} {unk1} {unk2} {unk3} -> {ret:X} {_animationLoadData.ModCollection.Name} {_animationLoadData.AssociatedGameObject} {last.ModCollection.Name} {last.AssociatedGameObject}" );
 #endif
             _animationLoadData = last;
+            TimingManager.StopTimer( TimingType.LoadAreaVfx );
             return ret;
         }
 

Penumbra/Interop/Resolver/PathResolver.DrawObjectState.cs

@@ -138,6 +138,7 @@ public unsafe partial class PathResolver
 
         private IntPtr CharacterBaseCreateDetour( uint a, IntPtr b, IntPtr c, byte d )
         {
+            TimingManager.StartTimer( TimingType.CharacterBaseCreate );
             var meta = DisposableContainer.Empty;
             if( LastGameObject != null )
             {
@@ -170,6 +171,7 @@ public unsafe partial class PathResolver
             {
                 meta.Dispose();
             }
+            TimingManager.StopTimer( TimingType.CharacterBaseCreate );
             return ret;
         }
 

Penumbra/Interop/Resolver/PathResolver.Identification.cs

@@ -24,6 +24,7 @@ public unsafe partial class PathResolver
             return new ResolveData( Penumbra.CollectionManager.Default );
         }
 
+        TimingManager.StartTimer( TimingType.IdentifyCollection );
         try
         {
             if( useCache && IdentifiedCache.TryGetValue( gameObject, out var data ) )
@@ -60,6 +61,7 @@ public unsafe partial class PathResolver
              ?? CollectionByAttributes( gameObject )
              ?? CheckOwnedCollection( identifier, owner )
              ?? Penumbra.CollectionManager.Default;
+
             return IdentifiedCache.Set( collection, identifier, gameObject );
         }
         catch( Exception e )
@@ -67,25 +69,36 @@ public unsafe partial class PathResolver
             Penumbra.Log.Error( $"Error identifying collection:\n{e}" );
             return Penumbra.CollectionManager.Default.ToResolveData( gameObject );
         }
+        finally
+        {
+            TimingManager.StopTimer( TimingType.IdentifyCollection );
+        }
     }
 
     // Get the collection applying to the current player character
     // or the default collection if no player exists.
     public static ModCollection PlayerCollection()
     {
+        TimingManager.StartTimer( TimingType.IdentifyCollection );
         var           gameObject = ( GameObject* )Dalamud.Objects.GetObjectAddress( 0 );
+        ModCollection ret;
         if( gameObject == null )
         {
-            return Penumbra.CollectionManager.ByType( CollectionType.Yourself )
+            ret = Penumbra.CollectionManager.ByType( CollectionType.Yourself )
              ?? Penumbra.CollectionManager.Default;
         }
+        else
+        {
 
             var player = Penumbra.Actors.GetCurrentPlayer();
-        return CollectionByIdentifier( player )
+            ret = CollectionByIdentifier( player )
              ?? CheckYourself( player, gameObject )
              ?? CollectionByAttributes( gameObject )
              ?? Penumbra.CollectionManager.Default;
         }
+        TimingManager.StopTimer( TimingType.IdentifyCollection );
+        return ret;
+    }
 
     // Check both temporary and permanent character collections. Temporary first.
     private static ModCollection? CollectionByIdentifier( ActorIdentifier identifier )

Penumbra/Interop/Resolver/PathResolver.PathState.cs

@@ -95,6 +95,7 @@ public unsafe partial class PathResolver
         // Special handling for paths so that we do not store non-owned temporary strings in the dictionary.
         public void SetCollection( IntPtr gameObject, ByteString path, ModCollection collection )
         {
+            TimingManager.StartTimer( TimingType.SetPathCollection );
             if( _pathCollections.ContainsKey( path ) || path.IsOwned )
             {
                 _pathCollections[ path ] = collection.ToResolveData( gameObject );
@@ -103,6 +104,7 @@ public unsafe partial class PathResolver
             {
                 _pathCollections[ path.Clone() ] = collection.ToResolveData( gameObject );
             }
+            TimingManager.StopTimer( TimingType.SetPathCollection );
         }
     }
 }

Penumbra/Interop/Resolver/PathResolver.Subfiles.cs

@@ -113,7 +113,9 @@ public unsafe partial class PathResolver
                 case ResourceType.Avfx:
                     if( handle->FileSize == 0 )
                     {
+                        TimingManager.StartTimer( TimingType.AddSubfile );
                         _subFileCollection[ ( IntPtr )handle ] = resolveData;
+                        TimingManager.StopTimer( TimingType.AddSubfile );
                     }
 
                     break;
@@ -126,7 +128,9 @@ public unsafe partial class PathResolver
             {
                 case ResourceType.Mtrl:
                 case ResourceType.Avfx:
+                    TimingManager.StartTimer( TimingType.AddSubfile );
                     _subFileCollection.TryRemove( ( IntPtr )handle, out _ );
+                    TimingManager.StopTimer( TimingType.AddSubfile );
                     break;
             }
         }

Penumbra/Interop/Resolver/PathResolver.cs

@@ -48,6 +48,7 @@ public partial class PathResolver : IDisposable
     // The modified resolver that handles game path resolving.
     private bool CharacterResolver( Utf8GamePath gamePath, ResourceCategory _1, ResourceType type, int _2, out (FullPath?, ResolveData) data )
     {
+        TimingManager.StartTimer( TimingType.CharacterResolver );
         // Check if the path was marked for a specific collection,
         // or if it is a file loaded by a material, and if we are currently in a material load,
         // or if it is a face decal path and the current mod collection is set.
@@ -71,6 +72,7 @@ public partial class PathResolver : IDisposable
         // We also need to handle defaulted materials against a non-default collection.
         var path = resolved == null ? gamePath.Path : resolved.Value.InternalName;
         SubfileHelper.HandleCollection( resolveData, path, nonDefault, type, resolved, out data );
+        TimingManager.StopTimer( TimingType.CharacterResolver );
         return true;
     }
 

Penumbra/Penumbra.cs

@@ -86,6 +86,9 @@ public class Penumbra : IDalamudPlugin
     {
         try
         {
+            TimingManager.StartTimer( TimingType.TotalTime );
+            TimingManager.StartTimer( TimingType.LaunchTime );
+
             Dalamud.Initialize( pluginInterface );
             Log                    = new Logger();
             DevPenumbraExists      = CheckDevPluginPenumbra();
@@ -162,6 +165,7 @@ public class Penumbra : IDalamudPlugin
             {
                 ResidentResources.Reload();
             }
+            TimingManager.StopTimer( TimingType.LaunchTime );
         }
         catch
         {
@@ -304,6 +308,7 @@ public class Penumbra : IDalamudPlugin
         ResourceLogger?.Dispose();
         ResourceLoader?.Dispose();
         CharacterUtility?.Dispose();
+        TimingManager.StopAllTimers();
     }
 
     // Collect all relevant files for penumbra configuration.

Penumbra/TimingManager.cs

@@ -0,0 +1,90 @@
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+using System.Text;
+using System.Threading;
+using ImGuiNET;
+
+namespace Penumbra;
+
+public enum TimingType
+{
+    TotalTime,
+    LaunchTime,
+    DebugTimes,
+    UiMainWindow,
+    UiAdvancedWindow,
+    GetResourceHandler,
+    ReadSqPack,
+    CharacterResolver,
+    IdentifyCollection,
+    CharacterBaseCreate,
+    TimelineResources,
+    LoadCharacterVfx,
+    LoadAreaVfx,
+    AddSubfile,
+    SetResource,
+    SetPathCollection,
+}
+
+public static class TimingManager
+{
+    public static readonly IReadOnlyList< ThreadLocal< Stopwatch > > StopWatches =
+#if DEBUG
+        Enum.GetValues< TimingType >().Select( e => new ThreadLocal< Stopwatch >( () => new Stopwatch(), true ) ).ToArray();
+#else
+        Array.Empty<ThreadLocal<Stopwatch>>();
+#endif
+
+    [Conditional( "DEBUG" )]
+    public static void StartTimer( TimingType timingType )
+    {
+        var stopWatch = StopWatches[ ( int )timingType ].Value;
+        stopWatch!.Start();
+    }
+
+    [Conditional( "DEBUG" )]
+    public static void StopTimer( TimingType timingType )
+    {
+        var stopWatch = StopWatches[ ( int )timingType ].Value;
+        stopWatch!.Stop();
+    }
+
+    [Conditional( "DEBUG" )]
+    public static void StopAllTimers()
+    {
+        foreach( var threadWatch in StopWatches )
+        {
+            foreach( var stopWatch in threadWatch.Values )
+            {
+                stopWatch.Stop();
+            }
+        }
+    }
+
+    [Conditional( "DEBUG" )]
+    public static void CreateTimingReport()
+    {
+        try
+        {
+            var sb = new StringBuilder( 1024 );
+            sb.AppendLine( "```" );
+            foreach( var type in Enum.GetValues< TimingType >() )
+            {
+                var watches = StopWatches[ ( int )type ];
+                var timeSum = watches.Values.Sum( w => w.ElapsedMilliseconds );
+
+                sb.AppendLine( $"{type,-20} - {timeSum,8} ms over {watches.Values.Count,2} Thread(s)" );
+            }
+
+            sb.AppendLine( "```" );
+
+            ImGui.SetClipboardText( sb.ToString() );
+        }
+        catch( Exception ex )
+        {
+            Penumbra.Log.Error( $"Could not create timing report:\n{ex}" );
+        }
+    }
+}

Penumbra/UI/Classes/ModEditWindow.cs

@@ -61,6 +61,7 @@ public partial class ModEditWindow : Window, IDisposable
 
     public override void PreDraw()
     {
+        TimingManager.StartTimer( TimingType.UiAdvancedWindow );
         var sb = new StringBuilder( 256 );
 
         var redirections = 0;
@@ -125,6 +126,7 @@ public partial class ModEditWindow : Window, IDisposable
         _allowReduplicate = redirections != _editor.AvailableFiles.Count || _editor.MissingFiles.Count > 0;
         sb.Append( WindowBaseLabel );
         WindowName = sb.ToString();
+        TimingManager.StopTimer( TimingType.UiAdvancedWindow );
     }
 
     public override void OnClose()
@@ -135,6 +137,7 @@ public partial class ModEditWindow : Window, IDisposable
 
     public override void Draw()
     {
+        TimingManager.StartTimer( TimingType.UiAdvancedWindow );
         using var tabBar = ImRaii.TabBar( "##tabs" );
         if( !tabBar )
         {
@@ -152,6 +155,7 @@ public partial class ModEditWindow : Window, IDisposable
         _materialTab.Draw();
         DrawTextureTab();
         _swapWindow.DrawItemSwapPanel();
+        TimingManager.StopTimer( TimingType.UiAdvancedWindow );
     }
 
     // A row of three buttonSizes and a help marker that can be used for material suffix changing.

Penumbra/UI/ConfigWindow.SettingsTab.General.cs

@@ -29,6 +29,9 @@ public partial class ConfigWindow
 
         private void DrawModSelectorSettings()
         {
+#if DEBUG
+            ImGui.NewLine(); // Due to the timing button.
+#endif
             if( !ImGui.CollapsingHeader( "General" ) )
             {
                 OpenTutorial( BasicTutorialSteps.GeneralSettings );

Penumbra/UI/ConfigWindow.SettingsTab.cs

@@ -370,6 +370,14 @@ public partial class ConfigWindow
             {
                 _window._penumbra.ForceChangelogOpen();
             }
+
+#if DEBUG
+            ImGui.SetCursorPos( new Vector2( xPos, 5 * ImGui.GetFrameHeightWithSpacing() ) );
+            if( ImGui.Button( "Copy Timings", new Vector2( width, 0 ) ) )
+            {
+                TimingManager.CreateTimingReport();
+            }
+#endif
         }
     }
 }

Penumbra/UI/ConfigWindow.cs

@@ -54,6 +54,8 @@ public sealed partial class ConfigWindow : Window, IDisposable
     {
         try
         {
+            TimingManager.StartTimer( TimingType.UiMainWindow );
+
             if( Penumbra.ImcExceptions.Count > 0 )
             {
                 DrawProblemWindow( $"There were {Penumbra.ImcExceptions.Count} errors while trying to load IMC files from the game data.\n"
@@ -101,6 +103,7 @@ public sealed partial class ConfigWindow : Window, IDisposable
         {
             Penumbra.Log.Error( $"Exception thrown during UI Render:\n{e}" );
         }
+        TimingManager.StopTimer( TimingType.UiMainWindow );
     }
 
     private static void DrawProblemWindow( string text, bool withExceptions )