From b8e85336993ce0a1b92ed213408947dde739ac68 Mon Sep 17 00:00:00 2001 From: OrekiWoof Date: Sun, 29 Mar 2026 09:41:08 +0200 Subject: [PATCH] perf logging, cap catchup loops --- .timetracker | 42 ++++++++++++++++++- .../BlockEntityReusableBeehive.cs | 42 ++++++++++++++----- OrekiWoofsBees.Common/DiagnosticsUtil.cs | 30 +++++++++++++ OrekiWoofsBees.Common/IModEntity.cs | 8 ++++ .../PlantPositionRegistryModSystem2.cs | 11 ++--- .../Behaviors/BlockEntityBehaviorBeeSwarm.cs | 31 +++++++++----- .../BlockEntityBehaviorRoamingBees.cs | 27 +++++++++--- RoamingBees/RoamingBees/modinfo.json | 2 +- RoamingBees/build.sh | 0 9 files changed, 158 insertions(+), 35 deletions(-) create mode 100644 OrekiWoofsBees.Common/DiagnosticsUtil.cs create mode 100644 OrekiWoofsBees.Common/IModEntity.cs mode change 100644 => 100755 RoamingBees/build.sh diff --git a/.timetracker b/.timetracker index c97fc9c..5a70fb3 100644 --- a/.timetracker +++ b/.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 } ] } \ No newline at end of file diff --git a/OrekiWoofsBeehives/BlockEntities/BlockEntityReusableBeehive.cs b/OrekiWoofsBeehives/BlockEntities/BlockEntityReusableBeehive.cs index 21c12e6..f959976 100644 --- a/OrekiWoofsBeehives/BlockEntities/BlockEntityReusableBeehive.cs +++ b/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(); 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(); - if (stopwatch.Elapsed.TotalSeconds > 0.2) - { - var modSystem = Api.GetOrekiWoofsBeehives(); - modSystem?.Mod?.Logger.Warning($"{nameof(BlockEntityReusableBeehive)} {nameof(OnGameTick)} took {stopwatch.Elapsed.TotalSeconds:F2}s"); - } + stopwatch.StopAndLogTime(this, 0.05); } 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; diff --git a/OrekiWoofsBees.Common/DiagnosticsUtil.cs b/OrekiWoofsBees.Common/DiagnosticsUtil.cs new file mode 100644 index 0000000..2560ff9 --- /dev/null +++ b/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( + 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( + 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"); + } +} \ No newline at end of file diff --git a/OrekiWoofsBees.Common/IModEntity.cs b/OrekiWoofsBees.Common/IModEntity.cs new file mode 100644 index 0000000..c481d80 --- /dev/null +++ b/OrekiWoofsBees.Common/IModEntity.cs @@ -0,0 +1,8 @@ +using Vintagestory.API.Common; + +namespace OrekiWoofsBees.Common; + +public interface IModEntity +{ + public Mod? Mod { get; } +} \ No newline at end of file diff --git a/OrekiWoofsBees.Common/PlantPositionRegistryModSystem2.cs b/OrekiWoofsBees.Common/PlantPositionRegistryModSystem2.cs index 2613354..408c29a 100644 --- a/OrekiWoofsBees.Common/PlantPositionRegistryModSystem2.cs +++ b/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 /// -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 beehives = []; private readonly HashSet flowerPositions = []; private readonly HashSet 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(); - if (stopwatch.Elapsed.TotalSeconds > 0.2) - { - Mod.Logger.Warning($"{nameof(PlantPositionRegistryModSystem2)} {nameof(OnTick)} took {stopwatch.Elapsed.TotalSeconds:F2}s (beehives: {beehives.Count})."); - } + stopwatch.StopAndLogTime(this, 0.01); } /// diff --git a/RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorBeeSwarm.cs b/RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorBeeSwarm.cs index e010f90..51e09f1 100644 --- a/RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorBeeSwarm.cs +++ b/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(); + 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(); - if (stopwatch.Elapsed.TotalSeconds > 0.2) - modSystem?.Mod?.Logger.Warning($"{nameof(BlockEntityBehaviorBeeSwarm)} {nameof(OnTick)} took {stopwatch.Elapsed.TotalSeconds:F2}s"); + stopwatch.StopAndLogTime(this, 0.02); } private void Update(float dt) diff --git a/RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorRoamingBees.cs b/RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorRoamingBees.cs index 8f875c6..f428bec 100644 --- a/RoamingBees/RoamingBees/Behaviors/BlockEntityBehaviorRoamingBees.cs +++ b/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 flowerPositions = []; private readonly List cropPositions = []; private readonly List 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(); + 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) diff --git a/RoamingBees/RoamingBees/modinfo.json b/RoamingBees/RoamingBees/modinfo.json index 4bd08ed..b2a2538 100644 --- a/RoamingBees/RoamingBees/modinfo.json +++ b/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" } diff --git a/RoamingBees/build.sh b/RoamingBees/build.sh old mode 100644 new mode 100755