diff --git a/build-logic/src/main/kotlin/terasology-metrics.gradle.kts b/build-logic/src/main/kotlin/terasology-metrics.gradle.kts index 9362c649346..4d137947b05 100644 --- a/build-logic/src/main/kotlin/terasology-metrics.gradle.kts +++ b/build-logic/src/main/kotlin/terasology-metrics.gradle.kts @@ -70,7 +70,7 @@ tasks.withType { reports { junitXml.required.set(true) } - jvmArgs("-Xms512m", "-Xmx1024m") + jvmArgs("-Xms512m", "-Xmx4096m") // Make sure the natives have been extracted, but only for multi-workspace setups (not for solo module builds) if (project.name != project(":").name) { diff --git a/engine-tests/build.gradle.kts b/engine-tests/build.gradle.kts index 94bb5b95933..411f5453a6c 100644 --- a/engine-tests/build.gradle.kts +++ b/engine-tests/build.gradle.kts @@ -118,11 +118,16 @@ tasks.withType { // `gradlew :engine-tests:filesystemSideEffectTest` - see that task below. val filesystemSideEffects = "filesystem-side-effects" +// Diagnostic/manual tests - report timings for comparison, not pass/fail checks. Not run +// automatically anywhere. Opt in with `gradlew :engine-tests:integrationTestDiagnostic`, +// or target one directly: `gradlew :engine-tests:integrationTestDiagnostic --tests ManyUsersChunkLoadTest`. +val diagnostic = "diagnostic" + tasks.named("test") { dependsOn(tasks.getByPath(":extractNatives")) description = "Runs all tests (slow)" useJUnitPlatform { - excludeTags(filesystemSideEffects) + excludeTags(filesystemSideEffects, diagnostic) } systemProperty("junit.jupiter.execution.timeout.default", "4m") } @@ -132,7 +137,7 @@ tasks.register("unitTest") { group = "Verification" description = "Runs unit tests (fast)" useJUnitPlatform { - excludeTags("MteTest", "TteTest", filesystemSideEffects) + excludeTags("MteTest", "TteTest", filesystemSideEffects, diagnostic) } systemProperty("junit.jupiter.execution.timeout.default", "1m") } @@ -153,7 +158,7 @@ tasks.register("integrationTest") { description = "Runs integration tests (slow) tagged with 'MteTest' or 'TteTest', exclude tests tagged 'flaky'." useJUnitPlatform { - excludeTags("flaky") + excludeTags("flaky", diagnostic) includeTags("MteTest", "TteTest") } systemProperty("junit.jupiter.execution.timeout.default", "5m") @@ -166,10 +171,22 @@ tasks.register("integrationTestFlaky") { useJUnitPlatform { includeTags("MteTest & flaky", "TteTest & flaky") + excludeTags(diagnostic) } systemProperty("junit.jupiter.execution.timeout.default", "5m") } +tasks.register("integrationTestDiagnostic") { + dependsOn(tasks.getByPath(":extractNatives")) + group = "Verification" + description = "Runs integration tests tagged 'diagnostic' - manual/timing tools, not pass/fail regression checks. Opt-in." + + useJUnitPlatform { + includeTags(diagnostic) + } + systemProperty("junit.jupiter.execution.timeout.default", "10m") +} + idea { module { // Change around the output a bit diff --git a/engine-tests/src/main/java/org/terasology/engine/integrationenvironment/ChunkRegionFuture.java b/engine-tests/src/main/java/org/terasology/engine/integrationenvironment/ChunkRegionFuture.java index d70a01e9b62..9d03e61ab9c 100644 --- a/engine-tests/src/main/java/org/terasology/engine/integrationenvironment/ChunkRegionFuture.java +++ b/engine-tests/src/main/java/org/terasology/engine/integrationenvironment/ChunkRegionFuture.java @@ -132,12 +132,17 @@ public BlockRegionc getChunkRegion() { } protected void onChunkRelevant(Chunk chunk) { + // Only chunks actually inside the requested region count toward completion. Without this, + // any relevant chunk anywhere - e.g. a padding/margin chunk outside what was asked for - + // could satisfy loadedChunks.size() >= chunks.volume() and resolve the future before the + // requested chunk(s) themselves are actually available. + if (!chunks.isValid() || !chunks.contains(chunk.getPosition())) { + return; + } loadedChunks.add(chunk); - if (chunks.isValid()) { - logger.debug("Got chunk {} / {}", loadedChunks.size(), chunks.volume()); - if (loadedChunks.size() >= chunks.volume() && !future.isDone()) { - future.set(this); - } + logger.debug("Got chunk {} / {}", loadedChunks.size(), chunks.volume()); + if (loadedChunks.size() >= chunks.volume() && !future.isDone()) { + future.set(this); } } diff --git a/engine-tests/src/test/java/org/terasology/engine/integrationenvironment/ManyUsersChunkLoadTest.java b/engine-tests/src/test/java/org/terasology/engine/integrationenvironment/ManyUsersChunkLoadTest.java new file mode 100644 index 00000000000..8d88e402b7a --- /dev/null +++ b/engine-tests/src/test/java/org/terasology/engine/integrationenvironment/ManyUsersChunkLoadTest.java @@ -0,0 +1,185 @@ +// Copyright 2026 The Terasology Foundation +// SPDX-License-Identifier: Apache-2.0 +package org.terasology.engine.integrationenvironment; + +import com.google.common.util.concurrent.Futures; +import com.google.common.util.concurrent.ListenableFuture; +import org.joml.Vector3f; +import org.joml.Vector3i; +import org.joml.Vector3ic; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.TestReporter; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.terasology.engine.entitySystem.entity.EntityManager; +import org.terasology.engine.integrationenvironment.jupiter.IntegrationEnvironment; +import org.terasology.engine.logic.location.LocationComponent; +import org.terasology.engine.network.NetworkMode; +import org.terasology.engine.particles.components.ParticleEmitterComponent; +import org.terasology.engine.particles.components.affectors.VelocityAffectorComponent; +import org.terasology.engine.particles.components.generators.ColorRangeGeneratorComponent; +import org.terasology.engine.particles.functions.affectors.VelocityAffectorFunction; +import org.terasology.engine.particles.functions.generators.ColorRangeGeneratorFunction; +import org.terasology.engine.world.block.BlockRegion; +import org.terasology.engine.world.chunks.ChunkProvider; + +import java.util.ArrayList; +import java.util.List; + +import static com.google.common.truth.Truth.assertThat; + +/** + * Diagnostic load test for https://github.com/MovingBlocks/Terasology/issues/5150. + *

+ * Two things are measured: + *

    + *
  1. Whether several players exploring different parts of the world at once makes the host's + * per-tick chunk processing (see {@code LocalChunkProvider}) slower per-chunk than a single + * player doing the same thing alone - i.e. does concurrent generation contend.
    2. + *
  2. How long it takes to reload those same chunks - now populated with persistent entities - + * from disk, all at once. This exercises {@code ChunkStoreInternal.restoreEntities()} (see its + * own timing/count log line) under concurrent load, which is the path suspected of causing the + * multi-second main-thread stalls seen after loading a real saved world.
    3. + *
+ * Not a pass/fail regression test - it reports timings for manual comparison. Re-run with a different + * {@link #NUM_USERS} or {@link #ENTITIES_PER_USER} to see how the numbers move. + */ +@IntegrationEnvironment(networkMode = NetworkMode.LISTEN_SERVER) +public class ManyUsersChunkLoadTest { + private static final Logger logger = LoggerFactory.getLogger(ManyUsersChunkLoadTest.class); + + private static final int NUM_USERS = 8; + // Chunks are 32x64x32 blocks; space "users" 512 blocks apart so their regions (and whatever + // padding RelevanceSystem adds around them) never overlap and load genuinely distinct chunks. + private static final int USER_SPACING = 512; + // Half-width, in blocks, of the area each simulated user forces relevant - a few chunks across. + private static final int REGION_HALF_SIZE = 48; + // Persistent entities to place in each user's area, to give restoreEntities() something real to do. + private static final int ENTITIES_PER_USER = 50; + + // A prior run timed out waiting for concurrent reloads with entities to finish (default 30s game + // time / 60s safety). Raised here to find out whether that's a severe-but-finite stall or a true + // hang - see https://github.com/MovingBlocks/Terasology/issues/5150. + private static final long RELOAD_TIMEOUT_MS = 300_000; + + @Test + // Heavy: spins up 9 engines (1 host + 8 simulated clients, each its own TerasologyEngine) to + // simulate 8 players exploring distinct regions concurrently, then bulk-reloads all their chunks + // from disk at once. Reports timings for manual comparison, not a pass/fail regression check - + // see class javadoc. + @Tag("diagnostic") + public void manySimulatedUsersLoadDifferentAreasConcurrently(ModuleTestingHelper helper, TestReporter reporter) + throws Exception { + helper.setSafetyTimeoutMs(RELOAD_TIMEOUT_MS + 60_000); + + // Baseline: how long does a single, uncontended region take to become relevant? + long baselineStart = System.currentTimeMillis(); + helper.runUntil(helper.makeBlocksRelevant(regionFor(0))); + long baselineMs = System.currentTimeMillis() - baselineStart; + reporter.publishEntry("baseline_solo_region_ms", String.valueOf(baselineMs)); + logger.info("Baseline (solo, no other clients): region 0 relevant in {}ms", baselineMs); + + // Connect NUM_USERS clients - real network/entity overhead per "user", same as real players joining. + long connectStart = System.currentTimeMillis(); + for (int i = 0; i < NUM_USERS; i++) { + helper.createClient(); + } + helper.awaitClients(NUM_USERS); + long connectMs = System.currentTimeMillis() - connectStart; + reporter.publishEntry("connect_" + NUM_USERS + "_clients_ms", String.valueOf(connectMs)); + logger.info("{} clients connected and registered on host in {}ms", NUM_USERS, connectMs); + + // Now force NUM_USERS distinct, spread-out regions relevant concurrently - simulating each + // connected user exploring their own area of the world at the same time. + long concurrentStart = System.currentTimeMillis(); + List> futures = new ArrayList<>(); + for (int i = 1; i <= NUM_USERS; i++) { + futures.add(helper.makeBlocksRelevant(regionFor(i))); + } + List regions = helper.runUntil(Futures.allAsList(futures)); + long concurrentMs = System.currentTimeMillis() - concurrentStart; + reporter.publishEntry("concurrent_" + NUM_USERS + "_regions_ms", String.valueOf(concurrentMs)); + logger.info("{} concurrent regions all relevant in {}ms ({}ms/region average, vs {}ms solo baseline)", + NUM_USERS, concurrentMs, concurrentMs / NUM_USERS, baselineMs); + assertThat(concurrentMs).isGreaterThan(0); + + // Populate each user's area with persistent entities (default EntityInfoComponent: persisted, + // not always-relevant, no owner) so they get bucketed into that chunk's EntityStore on save - + // see SaveTransaction.createChunkPosToUnsavedOwnerLessEntitiesMap(). + // + // Bare LocationComponent-only entities turned out too cheap to reproduce the multi-second + // real-world stalls (0-2ms/chunk even with 25 entities - see prior run). The real log showed + // repeated "Field rawDataMask#...ParticleSystemFunction will not be serialised" warnings during + // the stall, which only fire when ParticleEmitterComponent's generatorFunctionMap/ + // affectorFunctionMap (Map) actually hold + // entries - so give each entity one of each, to walk that same nested-reflection path. + EntityManager entityManager = helper.getHostContext().get(EntityManager.class); + for (int i = 1; i <= NUM_USERS; i++) { + int centerX = i * USER_SPACING; + for (int e = 0; e < ENTITIES_PER_USER; e++) { + float offset = e - ENTITIES_PER_USER / 2f; + ParticleEmitterComponent emitter = new ParticleEmitterComponent(); + emitter.generatorFunctionMap.put(new ColorRangeGeneratorComponent(), new ColorRangeGeneratorFunction()); + emitter.affectorFunctionMap.put(new VelocityAffectorComponent(), new VelocityAffectorFunction()); + entityManager.create(new LocationComponent(new Vector3f(centerX + offset, 40, 0)), emitter); + } + } + logger.info("Created {} persistent particle-emitter entities across {} regions ({} each)", + NUM_USERS * ENTITIES_PER_USER, NUM_USERS, ENTITIES_PER_USER); + + // Force every chunk in every region to unload (queuing its now-entity-populated state for + // save, synchronously - see ReadWriteStorageManager.deactivateChunk()) and immediately reload + // from that saved state - all concurrently. This is the same LocalChunkProvider path a real + // "host game" on a previously-explored save goes through, and it's what ChunkStoreInternal's + // restoreEntities() timing/count log line (added for this investigation) reports on. + ChunkProvider chunkProvider = helper.getHostContext().get(ChunkProvider.class); + List allChunkPositions = new ArrayList<>(); + for (ChunkRegionFuture region : regions) { + for (Vector3ic chunkPos : region.getChunkRegion()) { + allChunkPositions.add(new Vector3i(chunkPos)); + } + } + logger.info("Reloading {} chunks (unload + immediate reload from disk) across {} regions concurrently", + allChunkPositions.size(), NUM_USERS); + + long reloadStart = System.currentTimeMillis(); + for (Vector3ic pos : allChunkPositions) { + chunkProvider.reloadChunk(pos); + } + // Poll in short slices rather than one long wait, so we can tell steady-but-slow progress + // apart from a true stall on a fixed set of chunks (and know which ones, if so). + long pollIntervalMs = 5_000; + long elapsedMs = 0; + List stillPending; + while (true) { + helper.runUntil(pollIntervalMs, () -> allChunkPositions.stream().allMatch(chunkProvider::isChunkReady)); + elapsedMs = System.currentTimeMillis() - reloadStart; + stillPending = allChunkPositions.stream().filter(pos -> !chunkProvider.isChunkReady(pos)).toList(); + if (stillPending.isEmpty()) { + break; + } + logger.info("{}ms elapsed: {}/{} chunks still not ready: {}", + elapsedMs, stillPending.size(), allChunkPositions.size(), stillPending); + if (elapsedMs >= RELOAD_TIMEOUT_MS) { + throw new AssertionError(String.format( + "Timed out after %dms with %d/%d chunks still not ready: %s", + elapsedMs, stillPending.size(), allChunkPositions.size(), stillPending)); + } + } + long reloadMs = System.currentTimeMillis() - reloadStart; + reporter.publishEntry("reload_" + allChunkPositions.size() + "_chunks_with_entities_ms", String.valueOf(reloadMs)); + logger.info("{} chunks (~{} entities each) reloaded from disk in {}ms ({}ms/chunk average) - " + + "see ChunkStoreInternal log lines above for per-chunk restoreEntities() timings", + allChunkPositions.size(), ENTITIES_PER_USER, reloadMs, reloadMs / allChunkPositions.size()); + + assertThat(reloadMs).isGreaterThan(0); + } + + private static BlockRegion regionFor(int userIndex) { + int centerX = userIndex * USER_SPACING; + return new BlockRegion( + centerX - REGION_HALF_SIZE, 0, -REGION_HALF_SIZE, + centerX + REGION_HALF_SIZE, 63, REGION_HALF_SIZE); + } +} diff --git a/engine-tests/src/test/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProviderTest.java b/engine-tests/src/test/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProviderTest.java index f3e30457202..db408b57ae3 100644 --- a/engine-tests/src/test/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProviderTest.java +++ b/engine-tests/src/test/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProviderTest.java @@ -116,30 +116,54 @@ private Future requestCreatingOrLoadingArea(Vector3ic chunkPosition) { return requestCreatingOrLoadingArea(chunkPosition, 1); } + /** + * A single {@link LocalChunkProvider#update()} call only processes as many ready chunks as fit in + * its per-tick time budget. {@link #requestCreatingOrLoadingArea} requests a full 3x3x3 neighbourhood + * (needed so the centre chunk's own light merging can complete - see LightMerger.requiredChunks), + * so more than just the centre chunk can end up ready at once; this loops update() until the one + * this test actually cares about has been processed, rather than assuming one call is enough. + */ + private void updateUntilChunkReady(Vector3ic chunkPosition) throws TimeoutException { + long deadline = System.currentTimeMillis() + TimeUnit.SECONDS.toMillis(WAIT_CHUNK_IS_READY_IN_SECONDS); + while (!chunkProvider.isChunkReady(chunkPosition)) { + if (System.currentTimeMillis() > deadline) { + throw new TimeoutException("Chunk " + chunkPosition + " was not ready within " + + WAIT_CHUNK_IS_READY_IN_SECONDS + " seconds"); + } + chunkProvider.update(); + } + } + @Test void testGenerateSingleChunk() throws InterruptedException, ExecutionException, TimeoutException { Vector3i chunkPosition = new Vector3i(0, 0, 0); requestCreatingOrLoadingArea(chunkPosition).get(WAIT_CHUNK_IS_READY_IN_SECONDS, TimeUnit.SECONDS); - chunkProvider.update(); + updateUntilChunkReady(chunkPosition); + // requestCreatingOrLoadingArea also requests the surrounding neighbourhood (needed for the + // centre chunk's own light merging), so other chunks' OnChunkGenerated/OnChunkLoaded events + // can legitimately be interleaved with the centre's - filter by position rather than assuming + // a fixed index. final ArgumentCaptor eventArgumentCaptor = ArgumentCaptor.forClass(Event.class); verify(worldEntity, atLeast(2)).send(eventArgumentCaptor.capture()); Assertions.assertAll("WorldEvents not valid", () -> { - Event mustBeOnGeneratedEvent = eventArgumentCaptor.getAllValues().get(0); - Assertions.assertTrue(mustBeOnGeneratedEvent instanceof OnChunkGenerated, - "First world event must be OnChunkGenerated"); - Assertions.assertEquals(((OnChunkGenerated) mustBeOnGeneratedEvent).getChunkPos(), - chunkPosition, - "Chunk position at event not expected"); + Optional onChunkGenerated = eventArgumentCaptor.getAllValues().stream() + .filter(OnChunkGenerated.class::isInstance) + .map(OnChunkGenerated.class::cast) + .filter(e -> e.getChunkPos().equals(chunkPosition)) + .findFirst(); + Assertions.assertTrue(onChunkGenerated.isPresent(), + "Must have an OnChunkGenerated event for the requested chunk"); }, () -> { - Event mustBeOnLoadedEvent = eventArgumentCaptor.getAllValues().get(1); - Assertions.assertTrue(mustBeOnLoadedEvent instanceof OnChunkLoaded, - "Second world event must be OnChunkLoaded"); - Assertions.assertEquals(chunkPosition, - ((OnChunkLoaded) mustBeOnLoadedEvent).getChunkPos(), - "Chunk position at event not expected"); + Optional onChunkLoaded = eventArgumentCaptor.getAllValues().stream() + .filter(OnChunkLoaded.class::isInstance) + .map(OnChunkLoaded.class::cast) + .filter(e -> e.getChunkPos().equals(chunkPosition)) + .findFirst(); + Assertions.assertTrue(onChunkLoaded.isPresent(), + "Must have an OnChunkLoaded event for the requested chunk"); }); } @@ -149,38 +173,49 @@ void testGenerateSingleChunkWithBlockLifeCycle() throws InterruptedException, Ex blockAtBlockManager.setLifecycleEventsRequired(true); blockAtBlockManager.setEntity(mock(EntityRef.class)); requestCreatingOrLoadingArea(chunkPosition).get(WAIT_CHUNK_IS_READY_IN_SECONDS, TimeUnit.SECONDS); - chunkProvider.update(); + updateUntilChunkReady(chunkPosition); + // requestCreatingOrLoadingArea also requests the surrounding neighbourhood (needed for the + // centre chunk's own light merging), so other chunks' OnChunkGenerated/OnChunkLoaded events + // can legitimately be interleaved with the centre's - filter by position rather than assuming + // a fixed index. final ArgumentCaptor worldEventCaptor = ArgumentCaptor.forClass(Event.class); verify(worldEntity, atLeast(2)).send(worldEventCaptor.capture()); Assertions.assertAll("World Events not valid", () -> { - Event mustBeOnGeneratedEvent = worldEventCaptor.getAllValues().get(0); - Assertions.assertTrue(mustBeOnGeneratedEvent instanceof OnChunkGenerated, - "First world event must be OnChunkGenerated"); - Assertions.assertEquals(((OnChunkGenerated) mustBeOnGeneratedEvent).getChunkPos(), - chunkPosition, - "Chunk position at event not expected"); + Optional onChunkGenerated = worldEventCaptor.getAllValues().stream() + .filter(OnChunkGenerated.class::isInstance) + .map(OnChunkGenerated.class::cast) + .filter(e -> e.getChunkPos().equals(chunkPosition)) + .findFirst(); + Assertions.assertTrue(onChunkGenerated.isPresent(), + "Must have an OnChunkGenerated event for the requested chunk"); }, () -> { - Event mustBeOnLoadedEvent = worldEventCaptor.getAllValues().get(1); - Assertions.assertTrue(mustBeOnLoadedEvent instanceof OnChunkLoaded, - "Second world event must be OnChunkLoaded"); - Assertions.assertEquals(chunkPosition, - ((OnChunkLoaded) mustBeOnLoadedEvent).getChunkPos(), - "Chunk position at event not expected"); + Optional onChunkLoaded = worldEventCaptor.getAllValues().stream() + .filter(OnChunkLoaded.class::isInstance) + .map(OnChunkLoaded.class::cast) + .filter(e -> e.getChunkPos().equals(chunkPosition)) + .findFirst(); + Assertions.assertTrue(onChunkLoaded.isPresent(), + "Must have an OnChunkLoaded event for the requested chunk"); }); //TODO, it is not clear if the activate/addedBlocks event logic is correct. //See https://github.com/MovingBlocks/Terasology/issues/3244 + // Block lifecycle events carry only in-chunk positions/counts, not which chunk they came from, + // so with multiple chunks now generating blocks there's no way to attribute a specific event to + // this chunk - check that activation happened at all rather than assuming it's the first event. final ArgumentCaptor blockEventCaptor = ArgumentCaptor.forClass(Event.class); verify(blockAtBlockManager.getEntity(), atLeast(1)).send(blockEventCaptor.capture()); - Event mustBeOnActivatedBlocks = blockEventCaptor.getAllValues().get(0); - Assertions.assertTrue(mustBeOnActivatedBlocks instanceof OnActivatedBlocks, - "First block event must be OnActivatedBlocks"); - Assertions.assertTrue(((OnActivatedBlocks) mustBeOnActivatedBlocks).blockCount() > 0, - "Block count on activate must be non zero"); + Optional onActivatedBlocks = blockEventCaptor.getAllValues().stream() + .filter(OnActivatedBlocks.class::isInstance) + .map(OnActivatedBlocks.class::cast) + .filter(e -> e.blockCount() > 0) + .findFirst(); + Assertions.assertTrue(onActivatedBlocks.isPresent(), + "Must have an OnActivatedBlocks event with a non-zero block count"); } @Test @@ -191,19 +226,24 @@ void testLoadSingleChunk() throws InterruptedException, ExecutionException, Time storageManager.add(chunk); requestCreatingOrLoadingArea(chunkPosition).get(WAIT_CHUNK_IS_READY_IN_SECONDS, TimeUnit.SECONDS); - chunkProvider.update(); + updateUntilChunkReady(chunkPosition); Assertions.assertTrue(((TestChunkStore) storageManager.loadChunkStore(chunkPosition)).isEntityRestored(), "Entities must be restored by loading"); + // requestCreatingOrLoadingArea also requests the surrounding neighbourhood (needed for the + // centre chunk's own light merging); those neighbours are freshly generated rather than + // loaded (only the centre position was added to storageManager), so filter by both event + // type and chunk position rather than assuming index 0 is necessarily this chunk's OnChunkLoaded. final ArgumentCaptor eventArgumentCaptor = ArgumentCaptor.forClass(Event.class); verify(worldEntity, atLeast(1)).send(eventArgumentCaptor.capture()); - Event mustBeOnLoadedEvent = eventArgumentCaptor.getAllValues().get(0); - Assertions.assertTrue(mustBeOnLoadedEvent instanceof OnChunkLoaded, - "Second world event must be OnChunkLoaded"); - Assertions.assertEquals(chunkPosition, - ((OnChunkLoaded) mustBeOnLoadedEvent).getChunkPos(), - "Chunk position at event not expected"); + Optional onChunkLoaded = eventArgumentCaptor.getAllValues().stream() + .filter(OnChunkLoaded.class::isInstance) + .map(OnChunkLoaded.class::cast) + .filter(e -> e.getChunkPos().equals(chunkPosition)) + .findFirst(); + Assertions.assertTrue(onChunkLoaded.isPresent(), + "Must have an OnChunkLoaded event for the requested chunk"); } @Test @@ -216,39 +256,50 @@ void testLoadSingleChunkWithBlockLifecycle() throws InterruptedException, Execut blockAtBlockManager.setEntity(mock(EntityRef.class)); requestCreatingOrLoadingArea(chunkPosition).get(WAIT_CHUNK_IS_READY_IN_SECONDS, TimeUnit.SECONDS); - chunkProvider.update(); + updateUntilChunkReady(chunkPosition); Assertions.assertTrue(((TestChunkStore) storageManager.loadChunkStore(chunkPosition)).isEntityRestored(), "Entities must be restored by loading"); - + // requestCreatingOrLoadingArea also requests the surrounding neighbourhood (needed for the + // centre chunk's own light merging); those neighbours are freshly generated rather than + // loaded (only the centre position was added to storageManager), so filter by both event + // type and chunk position rather than assuming index 0 is necessarily this chunk's OnChunkLoaded. final ArgumentCaptor eventArgumentCaptor = ArgumentCaptor.forClass(Event.class); verify(worldEntity, atLeast(1)).send(eventArgumentCaptor.capture()); - Event mustBeOnLoadedEvent = eventArgumentCaptor.getAllValues().get(0); - Assertions.assertTrue(mustBeOnLoadedEvent instanceof OnChunkLoaded, - "Second world event must be OnChunkLoaded"); - Assertions.assertEquals(chunkPosition, - ((OnChunkLoaded) mustBeOnLoadedEvent).getChunkPos(), - "Chunk position at event not expected"); + Optional onChunkLoaded = eventArgumentCaptor.getAllValues().stream() + .filter(OnChunkLoaded.class::isInstance) + .map(OnChunkLoaded.class::cast) + .filter(e -> e.getChunkPos().equals(chunkPosition)) + .findFirst(); + Assertions.assertTrue(onChunkLoaded.isPresent(), + "Must have an OnChunkLoaded event for the requested chunk"); //TODO, it is not clear if the activate/addedBlocks event logic is correct. //See https://github.com/MovingBlocks/Terasology/issues/3244 + // Block lifecycle events carry only in-chunk positions/counts, not which chunk they came from, + // so with multiple chunks now loading/generating blocks there's no way to attribute a specific + // event to this chunk - check that both kinds happened at all rather than assuming fixed indices. final ArgumentCaptor blockEventCaptor = ArgumentCaptor.forClass(Event.class); verify(blockAtBlockManager.getEntity(), atLeast(2)).send(blockEventCaptor.capture()); Assertions.assertAll("Block events not valid", () -> { - Event mustBeOnAddedBlocks = blockEventCaptor.getAllValues().get(0); - Assertions.assertTrue(mustBeOnAddedBlocks instanceof OnAddedBlocks, - "First block event must be OnAddedBlocks"); - Assertions.assertTrue(((OnAddedBlocks) mustBeOnAddedBlocks).blockCount() > 0, - "Block count on activate must be non zero"); + Optional onAddedBlocks = blockEventCaptor.getAllValues().stream() + .filter(OnAddedBlocks.class::isInstance) + .map(OnAddedBlocks.class::cast) + .filter(e -> e.blockCount() > 0) + .findFirst(); + Assertions.assertTrue(onAddedBlocks.isPresent(), + "Must have an OnAddedBlocks event with a non-zero block count"); }, () -> { - Event mustBeOnActivatedBlocks = blockEventCaptor.getAllValues().get(1); - Assertions.assertTrue(mustBeOnActivatedBlocks instanceof OnActivatedBlocks, - "First block event must be OnActivatedBlocks"); - Assertions.assertTrue(((OnActivatedBlocks) mustBeOnActivatedBlocks).blockCount() > 0, - "Block count on activate must be non zero"); + Optional onActivatedBlocks = blockEventCaptor.getAllValues().stream() + .filter(OnActivatedBlocks.class::isInstance) + .map(OnActivatedBlocks.class::cast) + .filter(e -> e.blockCount() > 0) + .findFirst(); + Assertions.assertTrue(onActivatedBlocks.isPresent(), + "Must have an OnActivatedBlocks event with a non-zero block count"); }); } @@ -260,19 +311,37 @@ void testUnloadChunkAndDeactivationBlock() throws InterruptedException, TimeoutE requestCreatingOrLoadingArea(chunkPosition).get(WAIT_CHUNK_IS_READY_IN_SECONDS, TimeUnit.SECONDS); - //Wait BeforeDeactivateBlocks event + // requestCreatingOrLoadingArea also requests the surrounding neighbourhood (needed for the + // centre chunk's own light merging), and with an empty RelevanceSystem every loaded chunk gets + // unloaded - so wait for the REQUESTED chunk's own BeforeChunkUnload specifically (it carries a + // position, so it's filterable), not just the first unload from any chunk in the batch. + Assertions.assertTimeoutPreemptively(Duration.of(WAIT_CHUNK_IS_READY_IN_SECONDS, ChronoUnit.SECONDS), + () -> { + ArgumentCaptor worldEventCaptor = ArgumentCaptor.forClass(Event.class); + while (worldEventCaptor.getAllValues() + .stream() + .filter(BeforeChunkUnload.class::isInstance) + .map(BeforeChunkUnload.class::cast) + .noneMatch(e -> e.getChunkPos().equals(chunkPosition))) { + chunkProvider.update(); + worldEventCaptor = ArgumentCaptor.forClass(Event.class); + verify(worldEntity, atLeast(1)).send(worldEventCaptor.capture()); + } + } + ); + + // BeforeDeactivateBlocks carries no chunk position (see the TODO/issue #3244 below), so once + // the requested chunk's own unload has started, keep updating until deactivation for *some* + // chunk with lifecycle blocks has happened - the best that's attributable given the event's shape. Assertions.assertTimeoutPreemptively(Duration.of(WAIT_CHUNK_IS_READY_IN_SECONDS, ChronoUnit.SECONDS), () -> { ArgumentCaptor blockEventCaptor = ArgumentCaptor.forClass(Event.class); - while (!blockEventCaptor.getAllValues() + while (blockEventCaptor.getAllValues() .stream() - .filter((e) -> e instanceof BeforeDeactivateBlocks) - .map((e) -> (BeforeDeactivateBlocks) e) - .findFirst().isPresent()) { + .noneMatch(BeforeDeactivateBlocks.class::isInstance)) { chunkProvider.update(); blockEventCaptor = ArgumentCaptor.forClass(Event.class); verify(blockAtBlockManager.getEntity(), atLeast(1)).send(blockEventCaptor.capture()); - } } ); @@ -283,13 +352,11 @@ void testUnloadChunkAndDeactivationBlock() throws InterruptedException, TimeoutE .stream() .filter((e) -> e instanceof BeforeChunkUnload) .map((e) -> (BeforeChunkUnload) e) + .filter(e -> e.getChunkPos().equals(chunkPosition)) .findFirst(); Assertions.assertTrue(beforeChunkUnload.isPresent(), - "World events must have BeforeChunkUnload event when chunk was unload"); - Assertions.assertEquals(chunkPosition, - beforeChunkUnload.get().getChunkPos(), - "Chunk position at event not expected"); + "World events must have a BeforeChunkUnload event for the requested chunk"); //TODO, it is not clear if the activate/addedBlocks event logic is correct. //See https://github.com/MovingBlocks/Terasology/issues/3244 diff --git a/engine/src/main/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProvider.java b/engine/src/main/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProvider.java index f226d76f891..d330a99f38a 100644 --- a/engine/src/main/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProvider.java +++ b/engine/src/main/java/org/terasology/engine/world/chunks/localChunkProvider/LocalChunkProvider.java @@ -92,6 +92,11 @@ public class LocalChunkProvider implements ChunkProvider { private final Map chunkCache; private final Map> generateQueuedEntities = new ConcurrentHashMap<>(); + // The ChunkStore loaded (from disk) for a chunk in createOrLoadChunk()'s async task, carried + // through to processReadyChunk() so it isn't read from disk, decompressed, and re-parsed a + // second time there just to reach restoreEntities() - mirrors how generateQueuedEntities + // above already carries a freshly *generated* chunk's entities across the same handoff. + private final Map loadedChunkStores = new ConcurrentHashMap<>(); private final StorageManager storageManager; private final WorldGenerator generator; @@ -140,6 +145,7 @@ protected ListenableFuture createOrLoadChunk(Vector3ic chunkPos) { generateQueuedEntities.put(chunk.getPosition(), buffer.getAll()); } else { chunk = chunkStore.getChunk(); + loadedChunkStores.put(chunk.getPosition(), chunkStore); } return chunk; }); @@ -171,13 +177,14 @@ public void setWorldEntity(EntityRef worldEntity) { private void processReadyChunk(final Chunk chunk) { Vector3ic chunkPos = chunk.getPosition(); if (chunkCache.get(chunkPos) != null) { + loadedChunkStores.remove(chunkPos); return; // TODO move it in pipeline; } chunkCache.put(new Vector3i(chunkPos), chunk); chunk.markReady(); //TODO, it is not clear if the activate/addedBlocks event logic is correct. //See https://github.com/MovingBlocks/Terasology/issues/3244 - ChunkStore store = this.storageManager.loadChunkStore(chunkPos); + ChunkStore store = loadedChunkStores.remove(chunkPos); TShortObjectMap mappings = createBatchBlockEventMappings(chunk); if (store != null) { store.restoreEntities(); @@ -381,6 +388,8 @@ public void dispose() { chunk.dispose(); } chunkCache.clear(); + loadedChunkStores.clear(); + generateQueuedEntities.clear(); /* * The chunk monitor needs to clear chunk references, so it's important * that no new chunk get created @@ -414,6 +423,12 @@ public void purgeWorld() { chunk.dispose(); }); chunkCache.clear(); + // Positions in-flight or orphaned (early-returned/canceled) in these maps may have been + // populated from the world we're about to delete; a stale entry surviving here could + // later be matched to a freshly-generated chunk at the same position after the purge, + // wrongly restoring entities from the deleted world onto it. + loadedChunkStores.clear(); + generateQueuedEntities.clear(); storageManager.deleteWorld(); worldEntity.send(new PurgeWorldEvent()); diff --git a/engine/src/main/java/org/terasology/engine/world/chunks/pipeline/ChunkProcessingPipeline.java b/engine/src/main/java/org/terasology/engine/world/chunks/pipeline/ChunkProcessingPipeline.java index 34726ff03ba..d89818d06a8 100644 --- a/engine/src/main/java/org/terasology/engine/world/chunks/pipeline/ChunkProcessingPipeline.java +++ b/engine/src/main/java/org/terasology/engine/world/chunks/pipeline/ChunkProcessingPipeline.java @@ -6,6 +6,7 @@ import com.google.common.base.Preconditions; import com.google.common.collect.Lists; import com.google.common.collect.Maps; +import com.google.common.collect.Sets; import com.google.common.util.concurrent.ListenableFuture; import com.google.common.util.concurrent.SettableFuture; import org.joml.Vector3ic; @@ -16,10 +17,13 @@ import org.terasology.engine.world.chunks.Chunk; import org.terasology.engine.world.chunks.pipeline.stages.ChunkTask; import org.terasology.engine.world.chunks.pipeline.stages.ChunkTaskProvider; +import org.terasology.engine.world.chunks.pipeline.stages.SingleChunkTask; +import java.util.Collections; import java.util.Comparator; import java.util.List; import java.util.Map; +import java.util.Set; import java.util.concurrent.CancellationException; import java.util.concurrent.ExecutionException; import java.util.concurrent.Future; @@ -28,6 +32,7 @@ import java.util.concurrent.TimeUnit; import java.util.function.Function; import java.util.function.Supplier; +import java.util.function.UnaryOperator; import static com.google.common.primitives.Ints.constrainToRange; @@ -43,12 +48,34 @@ public class ChunkProcessingPipeline { Runtime.getRuntime().availableProcessors() - 2, 1, 4); private static final Logger logger = LoggerFactory.getLogger(ChunkProcessingPipeline.class); + /** + * How long the reactor waits for a stage to complete before checking whether the pipeline has + * gone idle. See {@link #skipBlockedStages()}. + */ + private static final long POLL_INTERVAL_MS = 5000; + /** + * Consecutive idle polls (i.e. {@code POLL_INTERVAL_MS * IDLE_POLLS_BEFORE_SKIP} of pipeline-wide + * silence) before positions with an unmet requirement are forced past their current stage. + */ + private static final int IDLE_POLLS_BEFORE_SKIP = 2; + private final List stages = Lists.newArrayList(); private final Thread reactor; private final ChunkExecutorCompletionService chunkProcessor; private final ThreadPoolExecutor executor; private final Function chunkProvider; private final Map chunkProcessingInfoMap = Maps.newConcurrentMap(); + /** + * Positions currently waiting on a requirement that isn't available yet. A position lands here + * whether the requirement is merely late (still being processed, or not yet requested but about + * to be) or will genuinely never arrive (outside anything ever requested) - those two cases look + * identical at the moment a requirement is found missing. {@link #skipBlockedStages()} is what + * tells them apart, by waiting to see whether the whole pipeline stays quiet long enough that + * "still coming" stops being plausible. + */ + private final Set blockedPositions = Sets.newConcurrentHashSet(); + /** Reactor-thread-only; counts consecutive poll timeouts with nothing completing anywhere. */ + private int consecutiveIdlePolls; private int threadIndex; /** @@ -80,7 +107,15 @@ public ChunkProcessingPipeline(int chunkThreads, Function chun private void chunkTaskHandler() { try { while (!executor.isTerminated()) { - PositionFuture future = (PositionFuture) chunkProcessor.take(); + PositionFuture future = + (PositionFuture) chunkProcessor.poll(POLL_INTERVAL_MS, TimeUnit.MILLISECONDS); + if (future == null) { + if (!blockedPositions.isEmpty() && ++consecutiveIdlePolls >= IDLE_POLLS_BEFORE_SKIP) { + skipBlockedStages(); + } + continue; + } + consecutiveIdlePolls = 0; ChunkProcessingInfo chunkProcessingInfo = chunkProcessingInfoMap.get(future.getPosition()); if (chunkProcessingInfo == null) { continue; // chunk processing was cancelled. @@ -138,17 +173,75 @@ private void processChunkInfo(ChunkProcessingInfo info) { ChunkTask chunkTask = info.getChunkTask(); List requirements = chunkTask.getRequirements(); List requiredChunks = Lists.newArrayListWithCapacity(requirements.size()); + boolean blocked = false; for (Vector3ic pos : requirements) { Chunk chunk = getChunkBy(info.getChunkTaskProvider(), pos); if (chunk != null) { requiredChunks.add(chunk); } else { - return; + // Could be being processed but not far enough along yet, could be not requested yet + // but about to be, or could be a position nothing will ever request. Those look + // identical here; skipBlockedStages() is what tells them apart. + blocked = true; + break; } } + if (blocked) { + blockedPositions.add(info.getPosition()); + return; + } + blockedPositions.remove(info.getPosition()); info.setCurrentFuture(runTask(chunkTask, requiredChunks)); } + /** + * Force every position still waiting on a requirement past its current stage, once the whole + * pipeline has gone quiet for {@link #IDLE_POLLS_BEFORE_SKIP} consecutive polls. + *

+ * Multi-chunk stages ask for a neighbourhood around their own position - {@link + * org.terasology.engine.world.propagation.light.LightMerger#requiredChunks LightMerger} wants the + * full 3x3x3. At the edge of the loaded world some of those neighbours were never requested by + * anyone, so they are in neither the chunk cache nor this pipeline and never will be. Widening + * the loaded region cannot fix that: the wider region just has its own outer shell with the same + * problem. There is always a boundary. + *

+ * A blocked position isn't necessarily stuck like that, though - it might just be waiting on a + * neighbour that was requested moments ago and hasn't finished its own earlier stages yet. Acting + * the instant a requirement is found missing would wrongly cut that wait short. So this only fires + * after sustained pipeline-wide silence: if nothing anywhere has completed for multiple poll + * intervals, whatever's still blocked is not "about to arrive" in any meaningful sense, genuinely + * unobtainable or not. + *

+ * A skipped chunk is passed through its stage unchanged. For light merging that means its outward + * faces keep whatever lighting the earlier per-chunk stages produced; when a neighbour is loaded + * later, that neighbour's own merge propagates across the shared face and corrects it. Being + * ready with imperfect edge lighting beats never becoming ready at all, which is what happened + * before - those chunks sat in {@link #chunkProcessingInfoMap} forever, and anything that later + * needed them (a chunk reload, say) inherited the stall. + */ + private void skipBlockedStages() { + consecutiveIdlePolls = 0; + List toSkip = Lists.newArrayList(blockedPositions); + blockedPositions.clear(); + for (Vector3ic pos : toSkip) { + ChunkProcessingInfo info = chunkProcessingInfoMap.get(pos); + if (info != null && info.getCurrentFuture() == null) { + skipStage(info); + } + } + } + + private void skipStage(ChunkProcessingInfo info) { + ChunkTaskProvider stage = info.getChunkTaskProvider(); + logger.debug("Skipping stage [{}] for chunk {}: still missing part of its required neighbourhood " + + "after {}ms of pipeline-wide idle", + stage == null ? "?" : stage.getName(), info.getPosition(), POLL_INTERVAL_MS * IDLE_POLLS_BEFORE_SKIP); + Chunk chunk = info.getChunk(); + ChunkTask passThrough = new SingleChunkTask( + (stage == null ? "?" : stage.getName()) + " (skipped)", info.getPosition(), UnaryOperator.identity()); + info.setCurrentFuture(runTask(passThrough, Collections.singletonList(chunk))); + } + private Chunk getChunkBy(ChunkTaskProvider requiredStage, Vector3ic position) { Chunk chunk = chunkProvider.apply(position); if (chunk == null) {