diff --git a/src/main/java/com/livingworld/core/simulation/SimulationManager.java b/src/main/java/com/livingworld/core/simulation/SimulationManager.java index 5181afb..a51d2a2 100644 --- a/src/main/java/com/livingworld/core/simulation/SimulationManager.java +++ b/src/main/java/com/livingworld/core/simulation/SimulationManager.java @@ -76,9 +76,14 @@ public final class SimulationManager { List jobs = this.scheduler.pollJobsForCycle(); int nextJobIndex = 0; + boolean budgetOverrunRecorded = false; try { for (; nextJobIndex < jobs.size(); nextJobIndex++) { if (nextJobIndex > 0 && hasExceededTimeBudget(startTimeNanos)) { + if (this.profiler != null) { + this.profiler.recordBudgetOverrun(); + budgetOverrunRecorded = true; + } requeueJobs(jobs, nextJobIndex); break; } @@ -97,6 +102,10 @@ public final class SimulationManager { long durationMs = elapsedMilliseconds(startTimeNanos); this.scheduler.endCycle(durationMs); if (this.profiler != null) { + if (!budgetOverrunRecorded + && durationMs > this.scheduler.getMaxMillisecondsPerCycle()) { + this.profiler.recordBudgetOverrun(); + } this.profiler.endCycle(durationMs); } } @@ -126,6 +135,9 @@ public final class SimulationManager { } try { + if (this.profiler != null) { + this.profiler.beginModule(module.getModuleId()); + } ModuleUpdateResult result = module.updateRegion(new RegionUpdateContext(region)); if (result == null) { throw new IllegalStateException( @@ -133,7 +145,12 @@ public final class SimulationManager { } changed |= result.changedRegion(); - result.generatedEvents().forEach(this.eventBus::publish); + result.generatedEvents().forEach(event -> { + this.eventBus.publish(event); + if (this.profiler != null) { + this.profiler.recordEvent(); + } + }); result.warnings().forEach(warning -> LivingWorldLogger.warn( DiagnosticCategory.SIMULATION, "[" + module.getModuleId() + "] " + warning)); @@ -141,10 +158,17 @@ public final class SimulationManager { LivingWorldLogger.error(DiagnosticCategory.SIMULATION, "Module update failed for " + module.getModuleId() + " in region " + region.getCoordinate(), e); + } finally { + if (this.profiler != null) { + this.profiler.endModule(module.getModuleId()); + } } } region.updateLastSimulatedTick(simulationTick); + if (this.profiler != null) { + this.profiler.recordRegionUpdated(); + } if (changed) { this.regionManager.markDirty(region); } diff --git a/src/main/java/com/livingworld/core/simulation/SimulationProfiler.java b/src/main/java/com/livingworld/core/simulation/SimulationProfiler.java index ab2e8be..c3795ec 100644 --- a/src/main/java/com/livingworld/core/simulation/SimulationProfiler.java +++ b/src/main/java/com/livingworld/core/simulation/SimulationProfiler.java @@ -20,4 +20,22 @@ public interface SimulationProfiler { * @param durationMs the wall-clock duration in milliseconds */ void endCycle(long durationMs); + + default void beginModule(String moduleId) { + } + + default void endModule(String moduleId) { + } + + default void recordEvent() { + } + + default void recordRegionUpdated() { + } + + default void recordSave() { + } + + default void recordBudgetOverrun() { + } } diff --git a/src/main/java/com/livingworld/debug/SimulationProfileSnapshot.java b/src/main/java/com/livingworld/debug/SimulationProfileSnapshot.java new file mode 100644 index 0000000..ecba8a7 --- /dev/null +++ b/src/main/java/com/livingworld/debug/SimulationProfileSnapshot.java @@ -0,0 +1,38 @@ +package com.livingworld.debug; + +import java.util.LinkedHashMap; +import java.util.Map; + +/** + * Immutable snapshot of one simulation profiling cycle. + */ +public record SimulationProfileSnapshot( + long totalCycleNanos, + Map moduleTimings, + int eventsPublished, + int regionsUpdated, + int savesPerformed, + boolean budgetExceeded) { + + public SimulationProfileSnapshot { + if (totalCycleNanos < 0) { + throw new IllegalArgumentException("totalCycleNanos must not be negative"); + } + if (moduleTimings == null) { + throw new IllegalArgumentException("moduleTimings must not be null"); + } + if (eventsPublished < 0 || regionsUpdated < 0 || savesPerformed < 0) { + throw new IllegalArgumentException("profile counts must not be negative"); + } + moduleTimings = Map.copyOf(new LinkedHashMap<>(moduleTimings)); + } + + public String toHumanReadableString() { + return "cycle=" + (totalCycleNanos / 1_000_000.0) + "ms" + + ", modules=" + moduleTimings + + ", events=" + eventsPublished + + ", regions=" + regionsUpdated + + ", saves=" + savesPerformed + + ", budgetExceeded=" + budgetExceeded; + } +} diff --git a/src/main/java/com/livingworld/debug/SimulationProfiler.java b/src/main/java/com/livingworld/debug/SimulationProfiler.java new file mode 100644 index 0000000..711e9b9 --- /dev/null +++ b/src/main/java/com/livingworld/debug/SimulationProfiler.java @@ -0,0 +1,128 @@ +package com.livingworld.debug; + +import java.util.LinkedHashMap; +import java.util.Map; + +/** + * Measures simulation cycle and module cost using a monotonic clock. + */ +public final class SimulationProfiler + implements com.livingworld.core.simulation.SimulationProfiler { + + private long cycleStartNanos = -1L; + private long totalCycleNanos; + private final Map moduleStartNanos = new LinkedHashMap<>(); + private final Map moduleTimings = new LinkedHashMap<>(); + private int eventsPublished; + private int regionsUpdated; + private int savesPerformed; + private int budgetOverruns; + + public synchronized void beginCycle() { + if (cycleStartNanos >= 0L) { + throw new IllegalStateException("a profiling cycle is already active"); + } + totalCycleNanos = 0L; + moduleStartNanos.clear(); + moduleTimings.clear(); + eventsPublished = 0; + regionsUpdated = 0; + savesPerformed = 0; + budgetOverruns = 0; + cycleStartNanos = System.nanoTime(); + } + + public synchronized void endCycle() { + ensureCycleActive(); + if (!moduleStartNanos.isEmpty()) { + throw new IllegalStateException( + "cannot end cycle while modules are still active: " + moduleStartNanos.keySet()); + } + totalCycleNanos = System.nanoTime() - cycleStartNanos; + cycleStartNanos = -1L; + } + + @Override + public synchronized void startCycle(long simulationTick) { + beginCycle(); + } + + @Override + public synchronized void endCycle(long durationMs) { + endCycle(); + } + + @Override + public synchronized void beginModule(String moduleId) { + ensureCycleActive(); + validateModuleId(moduleId); + if (moduleStartNanos.putIfAbsent(moduleId, System.nanoTime()) != null) { + throw new IllegalStateException("module is already being profiled: " + moduleId); + } + } + + @Override + public synchronized void endModule(String moduleId) { + ensureCycleActive(); + validateModuleId(moduleId); + Long startedAt = moduleStartNanos.remove(moduleId); + if (startedAt == null) { + throw new IllegalStateException("module profiling was not started: " + moduleId); + } + long elapsed = System.nanoTime() - startedAt; + moduleTimings.merge(moduleId, elapsed, Long::sum); + } + + @Override + public synchronized void recordEvent() { + ensureCycleActive(); + eventsPublished++; + } + + @Override + public synchronized void recordRegionUpdated() { + ensureCycleActive(); + regionsUpdated++; + } + + @Override + public synchronized void recordSave() { + ensureCycleActive(); + savesPerformed++; + } + + @Override + public synchronized void recordBudgetOverrun() { + ensureCycleActive(); + budgetOverruns++; + } + + public synchronized SimulationProfileSnapshot createSnapshot() { + long cycleNanos = cycleStartNanos >= 0L + ? System.nanoTime() - cycleStartNanos + : totalCycleNanos; + return new SimulationProfileSnapshot( + cycleNanos, + moduleTimings, + eventsPublished, + regionsUpdated, + savesPerformed, + budgetOverruns > 0); + } + + public synchronized int getBudgetOverrunCount() { + return budgetOverruns; + } + + private void ensureCycleActive() { + if (cycleStartNanos < 0L) { + throw new IllegalStateException("no profiling cycle is active"); + } + } + + private static void validateModuleId(String moduleId) { + if (moduleId == null || moduleId.isBlank()) { + throw new IllegalArgumentException("moduleId must not be null or blank"); + } + } +} diff --git a/src/test/java/com/livingworld/debug/SimulationProfilerTest.java b/src/test/java/com/livingworld/debug/SimulationProfilerTest.java new file mode 100644 index 0000000..fffa4c7 --- /dev/null +++ b/src/test/java/com/livingworld/debug/SimulationProfilerTest.java @@ -0,0 +1,55 @@ +package com.livingworld.debug; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import org.junit.jupiter.api.Test; + +class SimulationProfilerTest { + + @Test + void recordsCycleModulesEventsRegionsSavesAndBudgetOverruns() { + SimulationProfiler profiler = new SimulationProfiler(); + + profiler.beginCycle(); + profiler.beginModule("soil"); + profiler.endModule("soil"); + profiler.recordEvent(); + profiler.recordRegionUpdated(); + profiler.recordSave(); + profiler.recordBudgetOverrun(); + profiler.endCycle(); + + SimulationProfileSnapshot snapshot = profiler.createSnapshot(); + assertTrue(snapshot.totalCycleNanos() >= 0); + assertTrue(snapshot.moduleTimings().get("soil") >= 0); + assertEquals(1, snapshot.eventsPublished()); + assertEquals(1, snapshot.regionsUpdated()); + assertEquals(1, snapshot.savesPerformed()); + assertTrue(snapshot.budgetExceeded()); + assertTrue(snapshot.toHumanReadableString().contains("soil")); + } + + @Test + void supportsExistingSimulationProfilerAdapterMethods() { + com.livingworld.core.simulation.SimulationProfiler profiler = + new SimulationProfiler(); + + profiler.startCycle(12); + profiler.beginModule("water"); + profiler.endModule("water"); + profiler.endCycle(1); + } + + @Test + void validatesProfilingLifecycle() { + SimulationProfiler profiler = new SimulationProfiler(); + + assertThrows(IllegalStateException.class, profiler::endCycle); + profiler.beginCycle(); + assertThrows(IllegalStateException.class, profiler::beginCycle); + assertThrows(IllegalArgumentException.class, () -> profiler.beginModule(" ")); + assertThrows(IllegalStateException.class, () -> profiler.endModule("soil")); + } +}