DeferredStackTracingImpl refactor (#698)

* Make helper methods private in DeferredStackTracingImpl

* Extract GetAddrInfo method from loop in DeferredStackTracingImpl

* Make GetAddrInfo responsible for resizing the hashtable

...and update it's name to make it's new behavior clearer

* Inline variables

* Add show stack traces debug action

* Introduce skipping frames in stack tracing

This gets rid of the first line in every stack trace: DeferredStackTracing.Postfix

* Extract DeferredStackTracingImpl hashtable into a dedicated class

* Make AddrTable.size a property

* AddrTable: change fields to properties

* AddrTable: change it to a struct

Now it no longer introduces extra pointer chasing compared to the previous inline implementation in DeferredStackTracingImpl

* AddrInfo: remove unused field

Should improve cache locality and reduce memory usage

* AddrTable: StartingN = 10

The table easily grows to this size. It can just start out at this size

* Move MaxDepth to StackTraceLogItemRaw

* Clarify tracing behavior

Author: mibac138

Source/Client/Debug/DebugActions.cs

@@ -22,7 +22,9 @@ namespace Multiplayer.Client
 {
     static class MpDebugActions
     {
-        const string MultiplayerCategory = "Multiplayer";
+        public const string MultiplayerCategory = "Multiplayer";
+        // Actions in this category are not synced and only happen on the client.
+        public const string MultiplayerLocalCategory = "Multiplayer local";
 
         [DebugAction(MultiplayerCategory, actionType = DebugActionType.ToolWorld, allowedGameStates = AllowedGameStates.PlayingOnWorld)]
         public static void SpawnCaravans()
@@ -135,9 +137,7 @@ public static void SaveGame()
             File.WriteAllBytes($"game_{Multiplayer.username}.xml", data);
         }
 
-        public const string TriggerDesyncActionName = "Trigger desync";
-
-        [DebugAction(MultiplayerCategory, name = TriggerDesyncActionName, allowedGameStates = AllowedGameStates.Playing)]
+        [DebugAction(MultiplayerLocalCategory, name = "Trigger desync", allowedGameStates = AllowedGameStates.Playing)]
         public static void TriggerDesync()
         {
             var logItem = StackTraceLogItemRaw.GetFromPool();
@@ -149,6 +149,20 @@ public static void TriggerDesync()
             Multiplayer.game.sync.TryAddStackTraceForDesyncLogRaw(logItem, depth, hash);
         }
 
+        [DebugAction(MultiplayerLocalCategory, name = "Show stack traces", allowedGameStates = AllowedGameStates.Playing)]
+        public static void ShowStackTraces()
+        {
+            var syncCoordinator = Multiplayer.game.sync;
+            var opinions = syncCoordinator.knownClientOpinions;
+            if (opinions.Count == 0)
+            {
+                Log.Message("No opinions available");
+                return;
+            }
+            var stackTrace = opinions[0].GetFormattedStackTracesForRange(-1);
+            Log.Message($"Current opinion stack trace: \n{stackTrace}");
+        }
+
         [DebugAction(MultiplayerCategory, name = "Show pending player", allowedGameStates = AllowedGameStates.Playing)]
         public static void ShowPendingPlayer()
         {

Source/Client/Debug/DebugSync.cs

@@ -272,7 +272,7 @@ static class DebugActionNodeEnter
         static void Prefix(DebugActionNode __instance)
         {
             if (Multiplayer.Client != null && __instance.action is { Target: not MpDebugAction } &&
-                __instance.label != MpDebugActions.TriggerDesyncActionName)
+                __instance.category != MpDebugActions.MultiplayerLocalCategory)
                 __instance.action = new MpDebugAction { node = __instance, original = __instance.action }.Action;
         }
 

Source/Client/Desyncs/DeferredStackTracing.cs

@@ -33,7 +33,8 @@ public static void Postfix()
             var logItem = StackTraceLogItemRaw.GetFromPool();
             var trace = logItem.raw;
             int hash = 0;
-            int depth = DeferredStackTracingImpl.TraceImpl(trace, ref hash);
+            // Skip this (DeferredStackTracing.Postfix) frame. Keeping it in the trace doesn't provide any value.
+            int depth = DeferredStackTracingImpl.TraceImpl(trace, ref hash, skipFrames: 1);
 
             Multiplayer.game.sync.TryAddStackTraceForDesyncLogRaw(logItem, depth, hash);
 

Source/Client/Desyncs/StackTraceLogItem.cs

@@ -37,7 +37,8 @@ public class StackTraceLogItemObj : StackTraceLogItem
 
     public class StackTraceLogItemRaw : StackTraceLogItem
     {
-        public long[] raw = new long[DeferredStackTracingImpl.MaxDepth];
+        public const int MaxDepth = 32;
+        public long[] raw = new long[MaxDepth];
         public int depth;
 
         public int ticksGame;

Source/Client/UI/DebugPanel/SyncDebugPanel.cs

@@ -530,8 +530,8 @@ private static float DrawRngDebugSection(float x, float y, float width)
             DebugLine[] rngLines = [
                 new("Rand Calls:", $"{DeferredStackTracing.acc}", Color.white),
                 new("Max Trace Depth:", $"{DeferredStackTracing.maxTraceDepth}", Color.white),
-                new("Hash Entries:", $"{DeferredStackTracingImpl.hashtableEntries}/{DeferredStackTracingImpl.hashtableSize}", Color.white),
-                new("Hash Collisions:", $"{DeferredStackTracingImpl.collisions}", Color.white)
+                new("Hash Entries:", $"{DeferredStackTracingImpl.hashTable.Entries}/{DeferredStackTracingImpl.hashTable.Size}", Color.white),
+                new("Hash Collisions:", $"{DeferredStackTracingImpl.hashTable.Collisions}", Color.white)
             ];
 
             return DrawSection(x, y, width, new("RNG & DEBUG", rngLines));

Source/Client/UI/IngameDebug.cs

@@ -60,7 +60,7 @@ internal static void DoDebugPrintout()
                 text.AppendLine($"\nBuffered Changes: {SyncFieldUtil.bufferedChanges.Sum(kv => kv.Value.Count)}");
                 text.AppendLine($"Map Cmds: {async.cmds.Count}{separator} World Cmds: {Multiplayer.AsyncWorldTime.cmds.Count}");
                 text.AppendLine($"Stack Trace: {DeferredStackTracing.acc}{separator} Max Depth: {DeferredStackTracing.maxTraceDepth}");
-                text.AppendLine($"Hash: {DeferredStackTracingImpl.hashtableEntries}/{DeferredStackTracingImpl.hashtableSize} ({DeferredStackTracingImpl.collisions} collisions)");
+                text.AppendLine($"Hash: {DeferredStackTracingImpl.hashTable.Entries}/{DeferredStackTracingImpl.hashTable.Size} ({DeferredStackTracingImpl.hashTable.Collisions} collisions)");
 
                 text.AppendLine($"\nIdeology: {Find.IdeoManager.classicMode}{separator} Ideo ID: {Find.IdeoManager.IdeosInViewOrder.FirstOrDefault()?.id ?? 0}");
                 text.AppendLine($"Haul Dest: {Find.CurrentMap.haulDestinationManager.AllHaulDestinationsListForReading.Count}{separator} Designations: {Find.CurrentMap.designationManager.designationsByDef.Count}");

Source/Common/DeferredStackTracingImpl.cs

@@ -3,82 +3,115 @@
 
 namespace Multiplayer.Client.Desyncs;
 
-public static class DeferredStackTracingImpl
+public struct AddrTable()
 {
-    struct AddrInfo
+    private const int StartingN = 10; // 1024
+    private const int StartingShift = 64 - StartingN;
+    private const int StartingSize = 1 << StartingN;
+    private const float LoadFactor = 0.5f;
+
+    private AddrInfo[] hashtable = new AddrInfo[StartingSize];
+
+    public int Size => hashtable.Length;
+    public int Entries { get; private set; } = 0;
+    public int Collisions { get; private set; } = 0;
+
+    private int shift = StartingShift;
+
+    public ref AddrInfo GetOrCreateAddrInfo(long ret)
     {
-        public long addr;
-        public long stackUsage;
-        public long nameHash;
-        public long unused;
+        int indexmask = Size - 1;
+        int index = (int)(HashAddr((ulong)ret) >> shift);
+        ref var info = ref hashtable[index];
+        int colls = 0;
+
+        // Open addressing
+        while (info.addr != 0 && info.addr != ret)
+        {
+            index = (index + 1) & indexmask;
+            info = ref hashtable[index];
+            colls++;
+        }
+        if (colls > Collisions) Collisions = colls;
+
+        // When returning an unpopulated AddrInfo, assume it's going to get populated shortly and consider it used
+        // immediately.
+        if (info.addr == 0 && Entries++ > Size * LoadFactor) ResizeHashtable();
+        return ref info;
     }
 
-    const int StartingN = 7;
-    const int StartingShift = 64 - StartingN;
-    const int StartingSize = 1 << StartingN;
-    const float LoadFactor = 0.5f;
+    private static ulong HashAddr(ulong addr) => ((addr >> 4) | addr << 60) * 11400714819323198485;
 
-    static AddrInfo[] hashtable = new AddrInfo[StartingSize];
-    public static int hashtableSize = StartingSize;
-    public static int hashtableEntries;
-    public static int hashtableShift = StartingShift;
-    public static int collisions;
+    private void ResizeHashtable()
+    {
+        var oldTable = hashtable;
 
+        hashtable = new AddrInfo[Size * 2];
+        shift--;
+        Collisions = 0;
+
+        int indexmask = Size - 1;
+
+        for (int i = 0; i < oldTable.Length; i++)
+        {
+            ref var oldInfo = ref oldTable[i];
+            if (oldInfo.addr != 0)
+            {
+                int index = (int)(HashAddr((ulong)oldInfo.addr) >> shift);
+
+                while (hashtable[index].addr != 0)
+                    index = (index + 1) & indexmask;
+
+                ref var newInfo = ref hashtable[index];
+                newInfo.addr = oldInfo.addr;
+                newInfo.stackUsage = oldInfo.stackUsage;
+                newInfo.nameHash = oldInfo.nameHash;
+            }
+        }
+    }
+}
+
+public struct AddrInfo
+{
+    public long addr;
+    public long stackUsage;
+    public long nameHash;
+}
+
+public static class DeferredStackTracingImpl
+{
     const long NotJit = long.MaxValue;
     const long RbpBased = long.MaxValue - 1;
 
     const long UsesRbpAsGpr = 1L << 50;
     const long UsesRbx = 1L << 51;
     const long RbpInfoClearMask = ~(UsesRbpAsGpr | UsesRbx);
 
-    public const int MaxDepth = 32;
     public const int HashInfluence = 6;
 
-    public static unsafe int TraceImpl(long[] traceIn, ref int hash)
+    public static AddrTable hashTable = new();
+
+    public static unsafe int TraceImpl(long[] traceIn, ref int hash, int skipFrames = 0)
     {
         if (Native.LmfPtr == 0)
             return 0;
 
-        long[] trace = traceIn;
         long rbp = GetRbp();
 
         long stck = rbp;
         rbp = *(long*)rbp;
 
-        int indexmask = hashtableSize - 1;
-        int shift = hashtableShift;
-
-        long ret;
         long lmfPtr = *(long*)Native.LmfPtr;
 
-        int depth = 0;
-
+        int depth = 0; // frames seen
+        int index = 0; // frames returned through long[] traceIn
         while (true)
         {
-            ret = *(long*)(stck + 8);
-
-            int index = (int)(HashAddr((ulong)ret) >> shift);
-            ref var info = ref hashtable[index];
-            int colls = 0;
-
-            // Open addressing
-            while (info.addr != 0 && info.addr != ret)
-            {
-                index = (index + 1) & indexmask;
-                info = ref hashtable[index];
-                colls++;
-            }
-
-            if (colls > collisions)
-                collisions = colls;
-
-            long stackUsage = 0;
-
-            if (info.addr != 0)
-                stackUsage = info.stackUsage;
-            else
-                stackUsage = UpdateNewElement(ref info, ret);
+            var ret = *(long*)(stck + 8);
+            ref var info = ref hashTable.GetOrCreateAddrInfo(ret);
+            if (info.addr == 0) UpdateNewElement(ref info, ret);
 
+            long stackUsage = info.stackUsage;
             if (stackUsage == NotJit)
             {
                 // LMF (Last Managed Frame) layout on x64:
@@ -98,13 +131,18 @@ public static unsafe int TraceImpl(long[] traceIn, ref int hash)
                 continue;
             }
 
-            trace[depth] = ret;
+            if (depth >= skipFrames)
+            {
+                traceIn[index] = ret;
+
+                // info.nameHash == 0 marks methods to skip
+                if (index < HashInfluence && info.nameHash != 0) hash = HashCombineInt(hash, (int)info.nameHash);
 
-            // info.nameHash == 0 marks methods to skip
-            if (depth < HashInfluence && info.nameHash != 0)
-                hash = HashCombineInt(hash, (int)info.nameHash);
+                index++;
+            }
 
-            if (info.nameHash != 0 && ++depth == MaxDepth)
+            // traceIn length limits above all how many frames are visited, not how many are populated.
+            if (info.nameHash != 0 && ++depth == traceIn.Length)
                 break;
 
             if (stackUsage == RbpBased)
@@ -129,63 +167,21 @@ public static unsafe int TraceImpl(long[] traceIn, ref int hash)
             stck += stackUsage;
         }
 
-        return depth;
+        return index;
     }
 
-    static long UpdateNewElement(ref AddrInfo info, long ret)
-    {
-        long stackUsage = GetStackUsage(ret);
 
+    private static void UpdateNewElement(ref AddrInfo info, long ret)
+    {
         info.addr = ret;
-        info.stackUsage = stackUsage;
+        info.stackUsage = GetStackUsage(ret);
 
         var normalizedMethodNameBetweenOS = Native.MethodNameNormalizedFromAddr(ret, true);
 
         info.nameHash =
             normalizedMethodNameBetweenOS == null ? 1 :
             Native.GetMethodAggressiveInlining(ret) ? 0 :
             StableStringHash(normalizedMethodNameBetweenOS);
-
-        hashtableEntries++;
-        if (hashtableEntries > hashtableSize * LoadFactor)
-            ResizeHashtable();
-
-        return stackUsage;
-    }
-
-    static ulong HashAddr(ulong addr) => ((addr >> 4) | addr << 60) * 11400714819323198485;
-
-    static int ResizeHashtable()
-    {
-        var oldTable = hashtable;
-
-        hashtableSize *= 2;
-        hashtableShift--;
-
-        hashtable = new AddrInfo[hashtableSize];
-        collisions = 0;
-
-        int indexmask = hashtableSize - 1;
-        int shift = hashtableShift;
-
-        for (int i = 0; i < oldTable.Length; i++)
-        {
-            ref var oldInfo = ref oldTable[i];
-            if (oldInfo.addr != 0)
-            {
-                int index = (int)(HashAddr((ulong)oldInfo.addr) >> shift);
-
-                while (hashtable[index].addr != 0)
-                    index = (index + 1) & indexmask;
-
-                ref var newInfo = ref hashtable[index];
-                newInfo.addr = oldInfo.addr;
-                newInfo.stackUsage = oldInfo.stackUsage;
-                newInfo.nameHash = oldInfo.nameHash;
-            }
-        }
-
-        return indexmask;
     }
 
     static unsafe long GetStackUsage(long addr)
@@ -243,19 +239,17 @@ private static unsafe void CheckRbpUsage(uint* at, ref long stackUsage)
     }
 
     [MethodImpl(MethodImplOptions.NoInlining)]
-    static unsafe long GetRbp()
+    private static unsafe long GetRbp()
     {
         long rbp = 0;
 
         return *(&rbp + 1);
     }
 
-    public static int HashCombineInt(int seed, int value)
-    {
-        return (int)(seed ^ (value + 2654435769u + (seed << 6) + (seed >> 2)));
-    }
+    private static int HashCombineInt(int seed, int value) =>
+        (int)(seed ^ (value + 2654435769u + (seed << 6) + (seed >> 2)));
 
-    public static int StableStringHash(string? str)
+    private static int StableStringHash(string? str)
     {
         if (str == null)
         {