perf logging, cap catchup loops

.timetracker

@@ -1,5 +1,5 @@
 {
- "total": 606745,
+ "total": 625681,
  "sessions": [
   {
    "begin": "2026-01-09T17:26:02+01:00",
@@ -1375,6 +1375,46 @@
    "begin": "2026-03-27T22:58:21+01:00",
    "end": "2026-03-27T23:01:28+01:00",
    "duration": 187
+  },
+  {
+   "begin": "2026-03-27T23:01:40+01:00",
+   "end": "2026-03-28T00:18:11+01:00",
+   "duration": 4591
+  },
+  {
+   "begin": "2026-03-28T17:18:28+01:00",
+   "end": "2026-03-28T17:38:48+01:00",
+   "duration": 1220
+  },
+  {
+   "begin": "2026-03-29T04:02:58+02:00",
+   "end": "2026-03-29T04:23:13+02:00",
+   "duration": 1215
+  },
+  {
+   "begin": "2026-03-29T05:13:12+02:00",
+   "end": "2026-03-29T05:40:09+02:00",
+   "duration": 1617
+  },
+  {
+   "begin": "2026-03-29T05:40:49+02:00",
+   "end": "2026-03-29T05:42:26+02:00",
+   "duration": 96
+  },
+  {
+   "begin": "2026-03-29T05:42:29+02:00",
+   "end": "2026-03-29T06:02:30+02:00",
+   "duration": 1201
+  },
+  {
+   "begin": "2026-03-29T06:51:48+02:00",
+   "end": "2026-03-29T08:02:50+02:00",
+   "duration": 4262
+  },
+  {
+   "begin": "2026-03-29T08:19:40+02:00",
+   "end": "2026-03-29T09:38:35+02:00",
+   "duration": 4734
   }
  ]
 }

OrekiWoofsBeehives/BlockEntities/BlockEntityReusableBeehive.cs

@@ -12,7 +12,7 @@ using Vintagestory.GameContent;
 
 namespace OrekiWoofsBeehives.BlockEntities;
 
-public class BlockEntityReusableBeehive : BlockEntityContainer
+public class BlockEntityReusableBeehive : BlockEntityContainer, IModEntity
 {
     private const string feed_remaining_attribute = "feedRemaining";
     private const double feed_full_amount = 1.0;
@@ -20,6 +20,7 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
     private const double swarm_building_hours = 3.0;
     private const double swarm_hanging_hours = 5.0;
 
+    private readonly Stopwatch stopwatch = new();
     private readonly StringBuilder infoStringBuilder = new();
     private readonly InventoryGeneric inventory;
     private double lastUpdateTotalHours = 0;
@@ -50,6 +51,8 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
     public bool WasFullyScanned => wasFullyScanned;
     public bool OpenForIncomingSwarms => BeePopulation < Config.Instance.BeehiveConsideredEmptyBelowPopulation && !IsReceivingIncomingSwarm;
 
+    public Mod? Mod { get; private set; }
+
     public BlockEntityReusableBeehive()
     {
         inventory = new InventoryGeneric(8, null, null);
@@ -60,6 +63,7 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
     public override void Initialize(ICoreAPI api)
     {
         base.Initialize(api);
+        Mod = api.GetOrekiWoofsBeehives()?.Mod;
 
         roomRegistry = Api.ModLoader.GetModSystem<RoomRegistry>();
         positionsToCheckGreenhouse.Clear();
@@ -109,7 +113,7 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
         if (Overlaps.IsWithinSphericalRadius(Pos, StructVec3i.FromBlockPos(pos), radius))
         {
             CropsAround += delta;
-            base.MarkDirty(true);
+            base.MarkDirty(false);
         }
     }
 
@@ -119,7 +123,7 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
         if (Overlaps.IsWithinSphericalRadius(Pos, StructVec3i.FromBlockPos(pos), radius))
         {
             FlowersAround += delta;
-            base.MarkDirty(true);
+            base.MarkDirty(false);
         }
     }
 
@@ -135,22 +139,21 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
 
     private void OnGameTick(float dt)
     {
-        var stopwatch = Stopwatch.StartNew();
+        stopwatch.Restart();
 
         UpdateGreenhouseStatus();
+        stopwatch.LogTime(this, 0.02, "after greenhouse");
         UpdateStatsText();
+        stopwatch.LogTime(this, 0.02, "after stats");
 
         if (Api.Side == EnumAppSide.Client)
             return;
         UpdateFlowersAndCrops();
+        stopwatch.LogTime(this, 0.05, "after flowers and crops");
         UpdateBeePopulationAndHoney();
+        stopwatch.LogTime(this, 0.05, "after population and honey");
 
-        stopwatch.Stop();
+        stopwatch.StopAndLogTime(this, 0.05);
-        if (stopwatch.Elapsed.TotalSeconds > 0.2)
-        {
-            var modSystem = Api.GetOrekiWoofsBeehives();
-            modSystem?.Mod?.Logger.Warning($"{nameof(BlockEntityReusableBeehive)} {nameof(OnGameTick)} took {stopwatch.Elapsed.TotalSeconds:F2}s");
-        }
     }
 
     private void ClearStaleIncomingSwarmReservation()
@@ -219,11 +222,23 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
         var startingHoneyProgress = HoneyProgress;
 
         if (isCatchUp)
+        {
+            Mod?.Logger.Notification($"{nameof(BlockEntityReusableBeehive)}.{nameof(UpdateBeePopulationAndHoney)} catchup detected.");
             BroadcastUnloadDebug($"hive {Pos}: catch-up start elapsed={hoursElapsed:F2}h population={startingPopulation:F0} honeyProgress={startingHoneyProgress:F3}");
+        }
 
         var framesChangedVisually = false;
+        var maxSteps = 10;
+        var steps = 0;
         while (lastUpdateTotalHours < currentTotalHours)
         {
+            steps++;
+            if (steps > maxSteps)
+            {
+                Mod?.Logger.Notification($"{nameof(BlockEntityReusableBeehive)}.{nameof(UpdateBeePopulationAndHoney)} catchup paused. {nameof(lastUpdateTotalHours)}={lastUpdateTotalHours}, {nameof(currentTotalHours)}={currentTotalHours}");
+                break;
+            }
+
             var populationBeforeStep = BeePopulation;
 
             if (lastUpdateTotalHours + maxHoursSkip < currentTotalHours)
@@ -263,6 +278,9 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
 
     private void UpdateSwarming(double simulationTotalHours, double hoursElapsed, double? catchUpTargetTotalHours)
     {
+        if (!Config.Instance.EnableSwarms)
+            return;
+
         if (activeSwarmPos != null)
         {
             if (Api.World.BlockAccessor.GetBlockEntity(activeSwarmPos) is BlockEntityBeeSwarm)
@@ -525,6 +543,7 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
 
     private bool TryFindSwarmSpawnPosition(out BlockPos swarmPos, out string attachmentSide)
     {
+        stopwatch.Restart();
         swarmPos = Pos.Copy();
         attachmentSide = "down";
 
@@ -593,6 +612,9 @@ public class BlockEntityReusableBeehive : BlockEntityContainer
             ?? SelectBiasedCandidate(sideCandidatesNonWood))
             ?? SelectBiasedCandidate(floorCandidates))
             ?? SelectBiasedCandidate(ceilingCandidates);
+        
+        stopwatch.StopAndLogTime(this, 0.01);
+
         if (selected == null)
             return false;
 

OrekiWoofsBees.Common/DiagnosticsUtil.cs

@@ -0,0 +1,30 @@
+using System.Diagnostics;
+using System.Runtime.CompilerServices;
+
+namespace OrekiWoofsBees.Common;
+
+public static class DiagnosticsUtil
+{
+    public static void StopAndLogTime<T>(
+        this Stopwatch stopwatch,
+        T instance,
+        double totalSecondsThreshold,
+        string? note = null,
+        [CallerMemberName] string? callerName = null) where T : IModEntity
+    {
+        stopwatch.Stop();
+        if (stopwatch.Elapsed.TotalSeconds >= totalSecondsThreshold)
+            instance.Mod?.Logger.Warning($"{typeof(T).Name}.{callerName} ({note}) took {stopwatch.Elapsed.TotalSeconds:F2}s");
+    }
+
+    public static void LogTime<T>(
+        this Stopwatch stopwatch,
+        T instance,
+        double totalSecondsThreshold,
+        string? note = null,
+        [CallerMemberName] string? callerName = null) where T : IModEntity
+    {
+        if (stopwatch.Elapsed.TotalSeconds >= totalSecondsThreshold)
+            instance.Mod?.Logger.Warning($"{typeof(T).Name}.{callerName} ({note}) took {stopwatch.Elapsed.TotalSeconds:F2}s");
+    }
+}

OrekiWoofsBees.Common/IModEntity.cs

@@ -0,0 +1,8 @@
+using Vintagestory.API.Common;
+
+namespace OrekiWoofsBees.Common;
+
+public interface IModEntity
+{
+    public Mod? Mod { get; }
+}

OrekiWoofsBees.Common/PlantPositionRegistryModSystem2.cs

@@ -13,7 +13,7 @@ namespace OrekiWoofsBees.Common;
 /// Instead of each beehive scanning its radius every tick, this registry
 /// incrementally scans blocks across all beehives to keep performance consistent
 /// </summary>
-public class PlantPositionRegistryModSystem2 : ModSystem, IPlantPositionRegistry
+public class PlantPositionRegistryModSystem2 : ModSystem, IPlantPositionRegistry, IModEntity
 {
     private readonly static BlockPos staticBlockPos = new(0);
 
@@ -26,6 +26,7 @@ public class PlantPositionRegistryModSystem2 : ModSystem, IPlantPositionRegistry
     private readonly Dictionary<StructVec3i, BeehiveScanCursor> beehives = [];
     private readonly HashSet<StructVec3i> flowerPositions = [];
     private readonly HashSet<StructVec3i> cropPositions = [];
+    private readonly Stopwatch stopwatch = new();
 
     // blocks below this are skipped
     private readonly Dictionary<(int X, int Z), int> soilFloorCache = [];
@@ -208,7 +209,7 @@ public class PlantPositionRegistryModSystem2 : ModSystem, IPlantPositionRegistry
         if (Api is null)
             return;
 
-        var stopwatch = Stopwatch.StartNew();
+        stopwatch.Restart();
         if (beehives.Count == 0)
             return;
 
@@ -279,11 +280,7 @@ public class PlantPositionRegistryModSystem2 : ModSystem, IPlantPositionRegistry
             }
         }
 
-        stopwatch.Stop();
+        stopwatch.StopAndLogTime(this, 0.01);
-        if (stopwatch.Elapsed.TotalSeconds > 0.2)
-        {
-            Mod.Logger.Warning($"{nameof(PlantPositionRegistryModSystem2)} {nameof(OnTick)} took {stopwatch.Elapsed.TotalSeconds:F2}s (beehives: {beehives.Count}).");
-        }
     }
 
     /// <summary>

RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorBeeSwarm.cs

@@ -13,7 +13,7 @@ using Vintagestory.API.MathTools;
 
 namespace RoamingBees.Behaviors;
 
-public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityBehavior(blockEntity), IBeeSpawnHandler, IBeeSpawnCatchup
+public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityBehavior(blockEntity), IBeeSpawnHandler, IBeeSpawnCatchup, IModEntity
 {
     private const float spawn_cooldown_seconds = 2f;
     private const float hover_spawn_cooldown_seconds = 0.1f;
@@ -41,6 +41,7 @@ public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityB
     private double migrationPhaseDurationHours = 5.0;
 
     private Vec3d windVec = new(1, 0, 0);
+    private readonly Stopwatch stopwatch = new();
 
     public int ActiveBeesCount => activeBees.Count;
     public int ActiveHoveringCount => activeBees.Count(b => b.Role == BeeRole.Hovering);
@@ -56,6 +57,8 @@ public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityB
     public float TimeSinceLastHoverSpawn { get; private set; } = hover_spawn_cooldown_seconds;
     public SwarmState SwarmState { get; private set; }
 
+    public Mod? Mod { get; private set; }
+
     public override void Initialize(ICoreAPI api, JsonObject properties)
     {
         if (initialized)
@@ -65,6 +68,7 @@ public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityB
         initialized = true;
 
         modSystem = api.ModLoader.GetModSystem<RoamingBeesModSystem>();
+        Mod = modSystem?.Mod;
         modSystem?.BeeSpawnPacketDistributor?.Register(Blockentity.Pos, this);
         modSystem?.ClientChannel?.SendPacket(new BeeCatchupRequestPacket { HivePosition = Pos });
         if (modSystem?.Mod.Info.Version.Contains("dev") == true && modSystem?.ClientChannel != null)
@@ -287,6 +291,18 @@ public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityB
         if (packet.Path is null || packet.Path.Length == 0)
             return;
 
+        if (catchup)
+        {
+            var totalDelta = Math.Abs(Api.World.Calendar.ElapsedSeconds - packet.TimeElapsedSeconds);
+            if (totalDelta > 240)
+            {
+                Mod?.Logger.Notification($"{nameof(BlockEntityBehaviorBeeSwarm)} {nameof(HandleBeeParticleSpawn)} totalDelta: {totalDelta}s, discarding");
+                return;
+            }
+        }
+
+        stopwatch.Restart();
+
         var points = packet.Path.Select(x => x.ToPoint()).ToArray();
         var bee = new InternalBeeParticle(packet.EntrancePosition, GetFrontDirection(), points, packet.Role, packet.DespawnPosition, packet);
         if (packet.Role == BeeRole.Hovering)
@@ -296,24 +312,19 @@ public class BlockEntityBehaviorBeeSwarm(BlockEntity blockEntity) : BlockEntityB
         {
             var totalDelta = Math.Abs(Api.World.Calendar.ElapsedSeconds - packet.TimeElapsedSeconds);
             if (modSystem?.Mod.Info.Version.Contains("dev") == true)
-                modSystem.Mod.Logger.Notification($"HandleBeeParticleSpawn catchup totalDelta: {totalDelta}s");
+                modSystem.Mod.Logger.Notification($"HandleBeeParticleSpawn totalDelta: {totalDelta}s");
                 
-            var stopwatch = Stopwatch.StartNew();
             for (var i = 0; i < totalDelta / 0.1f; i++)
                 bee.Step(0.1f, 0.1f); // todo
-            stopwatch.Stop();
-            if (stopwatch.Elapsed.TotalSeconds > 0.02)
-                modSystem?.Mod?.Logger.Warning($"{nameof(BlockEntityBehaviorBeeSwarm)} {nameof(HandleBeeParticleSpawn)} catchup took {stopwatch.Elapsed.TotalSeconds:F2}s");
         }
+        stopwatch.StopAndLogTime(this, 0.01);
     }
 
     private void OnTick(float dt)
     {
-        var stopwatch = Stopwatch.StartNew();
+        stopwatch.Restart();
         Update(dt);
-        stopwatch.Stop();
+        stopwatch.StopAndLogTime(this, 0.02);
-        if (stopwatch.Elapsed.TotalSeconds > 0.2)
-            modSystem?.Mod?.Logger.Warning($"{nameof(BlockEntityBehaviorBeeSwarm)} {nameof(OnTick)} took {stopwatch.Elapsed.TotalSeconds:F2}s");
     }
 
     private void Update(float dt)

RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorRoamingBees.cs

@@ -15,7 +15,7 @@ using Vintagestory.GameContent;
 
 namespace RoamingBees.Behaviors;
 
-public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEntityBehavior(blockEntity), IBeeSpawnHandler, IBeeSpawnCatchup
+public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEntityBehavior(blockEntity), IBeeSpawnHandler, IBeeSpawnCatchup, IModEntity
 {
     private const float spawn_cooldown_seconds = 1.5f;
     private const string flower_count_attribute = "roamingbees_flowerCount";
@@ -39,7 +39,7 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
 
     private ClimateCondition? climate;
     private Vec3d? windVec;
-
+    private readonly Stopwatch stopwatch = new();
     private readonly List<StructVec3i> flowerPositions = [];
     private readonly List<StructVec3i> cropPositions = [];
     private readonly List<Vector3> relativePlantPositions = [];
@@ -59,6 +59,7 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
     public float InitialScanProgress { get; private set; }
     public float RescanProgress { get; private set; }
 
+    public Mod? Mod { get; private set; }
 
     public override void Initialize(ICoreAPI api, JsonObject properties)
     {
@@ -73,6 +74,7 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
         frontDirections = VectorParsing.ParseVector3Map(properties["frontDirections"]);
 
         modSystem = api.ModLoader.GetModSystem<RoamingBeesModSystem>();
+        Mod = modSystem?.Mod;
         modSystem?.BeeSpawnPacketDistributor?.Register(Blockentity.Pos, this);
         modSystem?.ClientChannel?.SendPacket(new BeeCatchupRequestPacket { HivePosition = Pos });
         if (modSystem?.Mod.Info.Version.Contains("dev") == true && modSystem?.ClientChannel != null)
@@ -148,6 +150,7 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
 
     public void HandleBeeParticleSpawn(BeeSpawnPacket packet, bool catchup = false)
     {
+        stopwatch.Restart();
         if (Blockentity.Pos != packet.HivePosition)
             return;
 
@@ -163,6 +166,16 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
             return;
         }
 
+        if (catchup)
+        {
+            var totalDelta = Math.Abs(Api.World.Calendar.ElapsedSeconds - packet.TimeElapsedSeconds);
+            if (totalDelta > 240)
+            {
+                Mod?.Logger.Notification($"{nameof(BlockEntityBehaviorBeeSwarm)} {nameof(HandleBeeParticleSpawn)} totalDelta: {totalDelta}s, discarding");
+                return;
+            }
+        }
+
         var facing = packet.Facing ?? GetFacing();
         Vector3 entrancePosition = GetEntrancePosition(facing);
         var bee = new InternalBeeParticle(entrancePosition, GetFrontDirection(facing), [.. packet.Path.Select(x => x.ToPoint())], BeeRole.Forager, entrancePosition, packet);
@@ -173,13 +186,10 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
             if (modSystem?.Mod.Info.Version.Contains("dev") == true)
                 modSystem.Mod.Logger.Notification($"HandleBeeParticleSpawn catchup totalDelta: {totalDelta}s");
                 
-            var stopwatch = Stopwatch.StartNew();
             for (var i = 0; i < totalDelta / 0.1f; i++)
                 bee.Step(0.1f, 0.1f); // todo
-            stopwatch.Stop();
-            if (stopwatch.Elapsed.TotalSeconds > 0.02)
-                modSystem?.Mod?.Logger.Warning($"{nameof(BlockEntityBehaviorRoamingBees)} {nameof(HandleBeeParticleSpawn)} catchup took {stopwatch.Elapsed.TotalSeconds:F2}s");
         }
+        stopwatch.StopAndLogTime(this, 0.01);
     }
 
     public void Clear()
@@ -199,6 +209,7 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
         if (Block is BlockSkep && !Config.Instance.EnableOnVanillaSkeps)
             return;
 
+        stopwatch.Restart();
         var isFgc = Block?.Code?.Domain == "fromgoldencombs";
         var path = Block?.Code?.Path ?? string.Empty;
         var isFgcLangstroth = isFgc && path.Contains("langstrothstack", StringComparison.OrdinalIgnoreCase);
@@ -231,9 +242,13 @@ public class BlockEntityBehaviorRoamingBees(BlockEntity blockEntity) : BlockEnti
             TargetParticleCount = Config.Instance.RoamingBeesPerFgcCeramic;
 
         if (Api.Side == EnumAppSide.Server)
+        {
             UpdatePlantInfo();
+            stopwatch.LogTime(this, 0.05, "after UpdatePlantInfo");
+        }
 
         Update(dt);
+        stopwatch.StopAndLogTime(this, 0.05);
     }
 
     private void Update(float dt)

RoamingBees/RoamingBees/modinfo.json

@@ -7,7 +7,7 @@
         "OrekiWoof"
     ],
     "description": "Cute immersive roaming bees. Now on vanilla skeps and other mods' hives.",
-    "version": "2.0.0-dev.6",
+    "version": "2.0.0-dev.7",
     "dependencies": {
         "game": "1.21.0"
     }