From 9580335692f948bfd8b3fb90e19a777dcf8d404c Mon Sep 17 00:00:00 2001 From: tom lee Date: Sat, 22 Jan 2022 16:09:58 +0800 Subject: [PATCH] Fixed Buffer leaks, cleanup Debug logging --- .../com/seibel/lod/core/api/EventApi.java | 7 +- .../LodBufferBuilderFactory.java | 96 +++++++------------ .../core/builders/lodBuilding/LodBuilder.java | 4 +- .../handlers/LodDimensionFileHandler.java | 33 ++++--- .../core/objects/opengl/LodVertexBuffer.java | 8 +- .../seibel/lod/core/util/MovableGridList.java | 14 ++- 6 files changed, 73 insertions(+), 89 deletions(-) diff --git a/src/main/java/com/seibel/lod/core/api/EventApi.java b/src/main/java/com/seibel/lod/core/api/EventApi.java index 162ec4b2b..a7468bc6a 100644 --- a/src/main/java/com/seibel/lod/core/api/EventApi.java +++ b/src/main/java/com/seibel/lod/core/api/EventApi.java @@ -49,6 +49,7 @@ import com.seibel.lod.core.wrapperInterfaces.world.IWorldWrapper; */ public class EventApi { + public static final boolean ENABLE_STACK_DUMP_LOGGING = false; public static final EventApi INSTANCE = new EventApi(); private static final IMinecraftWrapper MC = SingletonHandler.get(IMinecraftWrapper.class); @@ -101,7 +102,8 @@ public class EventApi /** This is also called when a new dimension loads */ public void worldLoadEvent(IWorldWrapper world) { - ClientApi.LOGGER.info("WorldLoadEvent called here for "+ (world.getWorldType() == WorldType.ClientWorld ? + if (ENABLE_STACK_DUMP_LOGGING) + ClientApi.LOGGER.info("WorldLoadEvent called here for "+ (world.getWorldType() == WorldType.ClientWorld ? "clientLevel" : "serverLevel"), new RuntimeException()); // Always ignore ServerWorld event if (world.getWorldType() == WorldType.ServerWorld) return; @@ -125,7 +127,8 @@ public class EventApi /** This is also called when the user disconnects from a server+ */ public void worldUnloadEvent(IWorldWrapper world) { - ClientApi.LOGGER.info("WorldUnloadEvent called here for "+ (world.getWorldType() == WorldType.ClientWorld ? "clientLevel" : "serverLevel"), new RuntimeException()); + if (ENABLE_STACK_DUMP_LOGGING) + ClientApi.LOGGER.info("WorldUnloadEvent called here for "+ (world.getWorldType() == WorldType.ClientWorld ? "clientLevel" : "serverLevel"), new RuntimeException()); // If it's single player, ignore the client side world unload event // Note: using isCurrentlyOnSinglePlayerServer as often API call unload event AFTER setting MC to not be in a singlePlayerServer if (isCurrentlyOnSinglePlayerServer && world.getWorldType() == WorldType.ClientWorld) return; diff --git a/src/main/java/com/seibel/lod/core/builders/bufferBuilding/LodBufferBuilderFactory.java b/src/main/java/com/seibel/lod/core/builders/bufferBuilding/LodBufferBuilderFactory.java index 3661eadd2..40616a27a 100644 --- a/src/main/java/com/seibel/lod/core/builders/bufferBuilding/LodBufferBuilderFactory.java +++ b/src/main/java/com/seibel/lod/core/builders/bufferBuilding/LodBufferBuilderFactory.java @@ -71,29 +71,26 @@ import com.seibel.lod.core.wrapperInterfaces.minecraft.IMinecraftWrapper; */ public class LodBufferBuilderFactory { + + //TODO: Do some Perf logging of Buffer Building + public static final boolean ENABLE_BUFFER_PERF_LOGGING = false; + public static final boolean ENABLE_BUFFER_SWAP_LOGGING = false; + public static final boolean ENABLE_BUFFER_UPLOAD_LOGGING = false; + public static final boolean ENABLE_LAG_SPIKE_LOGGING = false; + public static final long LAG_SPIKE_THRESOLD_NS = TimeUnit.NANOSECONDS.convert(16, TimeUnit.MILLISECONDS); + public static class LagSpikeCatcher { long timer = System.nanoTime(); public LagSpikeCatcher() {} public void end(String source) { + if (!ENABLE_LAG_SPIKE_LOGGING) return; timer = System.nanoTime() - timer; - if (timer> 16000000) { //16 ms - ClientApi.LOGGER.debug("NOTE: "+source+" took "+Duration.ofNanos(timer)+"!"); + if (timer > LAG_SPIKE_THRESOLD_NS) { + ClientApi.LOGGER.info("LagSpikeCatcher: "+source+" took "+Duration.ofNanos(timer)+"!"); } - } } - - public static class Pos { - public int x; - public int y; - - public Pos(int xx, int yy) { - x = xx; - y = yy; - } - } - private static final ILodConfigWrapperSingleton CONFIG = SingletonHandler.get(ILodConfigWrapperSingleton.class); private static final IMinecraftWrapper MC = SingletonHandler.get(IMinecraftWrapper.class); @@ -232,11 +229,6 @@ public class LodBufferBuilderFactory return true; } - // this was pulled out as a separate method so that it could be - // more easily edited by hot swapping. Because, As far as James is aware - // you can't hot swap lambda expressions. - private static final boolean enableLogging = true; - private void generateLodBuffersThread(LodRenderer renderer, LodDimension lodDim, int playerX, int playerY, int playerZ, boolean fullRegen) { @@ -264,6 +256,12 @@ public class LodBufferBuilderFactory if (fullRegen || tooFar || buildableBuffers==null || buildableVbos==null || setsToRender==null || vertexOptimizerCache==null) { + if (buildableVbos != null) { + buildableVbos.clear((bs) -> { + for (LodVertexBuffer b : bs) if (b!=null) b.close(); + }); + } + renderRange = lodDim.getWidth()/2; //get lodDim half width buildableBuffers = new MovableGridList(renderRange, playerRegionX, playerRegionZ); buildableVbos = new MovableGridList(renderRange, playerRegionX, playerRegionZ); @@ -284,7 +282,7 @@ public class LodBufferBuilderFactory vboZ = buildableCenterBlockZ; buildableBuffers.move(playerRegionX, playerRegionZ); buildableVbos.move(playerRegionX, playerRegionZ, (bs) -> { - if (bs!=null) for (LodVertexBuffer b : bs) if (b!=null) b.close(); + for (LodVertexBuffer b : bs) if (b!=null) b.close(); }); setsToRender.move(playerRegionX, playerRegionZ); vertexOptimizerCache.move(playerRegionX, playerRegionZ); @@ -362,8 +360,8 @@ public class LodBufferBuilderFactory long endTime = System.currentTimeMillis(); long buildTime = endTime - startTime; long executeTime = executeEnd - executeStart; - if (enableLogging) - ClientApi.LOGGER.debug("Thread Build("+nodeToRenderThreads.size()+"/"+(lodDim.getWidth()*lodDim.getWidth())+ (fullRegen ? "FULL" : "")+") time: " + buildTime + " ms" + '\n' + + if (ENABLE_BUFFER_PERF_LOGGING) + ClientApi.LOGGER.info("Thread Build("+nodeToRenderThreads.size()+"/"+(lodDim.getWidth()*lodDim.getWidth())+ (fullRegen ? "FULL" : "")+") time: " + buildTime + " ms" + '\n' + "thread execute time: " + executeTime + " ms"); //================================// @@ -388,8 +386,8 @@ public class LodBufferBuilderFactory // upload the new buffers uploadBuffers(posToUpload); long uploadTime = System.currentTimeMillis() - startUploadTime; - if (enableLogging) - ClientApi.LOGGER.debug("Thread Upload time: " + uploadTime + " ms"); + if (ENABLE_BUFFER_PERF_LOGGING) + ClientApi.LOGGER.info("Thread Upload time: " + uploadTime + " ms"); } catch (Exception e) { @@ -401,7 +399,7 @@ public class LodBufferBuilderFactory } catch (Exception e) { - ClientApi.LOGGER.warn("\"LodNodeBufferBuilder.generateLodBuffersAsync\" ran into trouble: "); + ClientApi.LOGGER.error("\"LodNodeBufferBuilder.generateLodBuffersAsync\" ran into trouble: "); e.printStackTrace(); } finally @@ -573,35 +571,6 @@ public class LodBufferBuilderFactory // BufferBuilder related methods // //===============================// - /** - * Called from the LodRenderer to create the - * BufferBuilders.

- *

- * May have to wait for the bufferLock to open. - */ - - private void setupBuffersTOBEREMOVED(int regionX, int regionZ) { - //TODO: Impl actual multibuffers - //int regionMemoryRequired = DEFAULT_MEMORY_ALLOCATION; - //int numberOfBuffers; - LodVertexBuffer[] vbos = buildableVbos.get(regionX, regionZ); - if (vbos != null) - for (LodVertexBuffer vbo : vbos) { - if (vbo!=null) vbo.close(); - } - /* - if (regionMemoryRequired > LodUtil.MAX_ALLOCATABLE_DIRECT_MEMORY) - { - // TODO shouldn't this be determined with regionMemoryRequired? - // always allocating the max memory is a bit expensive isn't it? - numberOfBuffers = (int) regionMemoryRequired / LodUtil.MAX_ALLOCATABLE_DIRECT_MEMORY + 1; - } else { - numberOfBuffers = 1; - }*/ - - vbos = buildableVbos.setAndGet(regionX, regionZ, new LodVertexBuffer[1]); - } - /** * Sets the buffers and Vbos to null, forcing them to be recreated
* and destroys any bound OpenGL objects.
@@ -628,22 +597,20 @@ public class LodBufferBuilderFactory GLProxy.getInstance().recordOpenGlCall(() -> { // destroy the VBOs if they aren't already if (toBeDeletedBuildableVbos != null) { - for (LodVertexBuffer[] vbos : toBeDeletedBuildableVbos) { - if (vbos == null) continue; + toBeDeletedBuildableVbos.clear((vbos) -> { for (LodVertexBuffer vbo : vbos) { if (vbo == null) continue; vbo.close(); } - } + }); } if (toBeDeletedDrawableVbos != null) { - for (LodVertexBuffer[] vbos : toBeDeletedDrawableVbos) { - if (vbos == null) continue; + toBeDeletedDrawableVbos.clear((vbos) -> { for (LodVertexBuffer vbo : vbos) { if (vbo == null) continue; vbo.close(); } - } + }); } }); } @@ -737,9 +704,11 @@ public class LodBufferBuilderFactory } } totalBuffers += (requiredFullBuffers+1); - ClientApi.LOGGER.info("Uploaded {} sub buffers for {}", (requiredFullBuffers+1), p); + if (ENABLE_BUFFER_UPLOAD_LOGGING) + ClientApi.LOGGER.info("Uploaded {} sub buffers for {}", (requiredFullBuffers+1), p); } - ClientApi.LOGGER.info("UploadBuffers uploaded "+bytesUploaded+" bytes, with {} sub buffers", totalBuffers); + if (ENABLE_BUFFER_UPLOAD_LOGGING) + ClientApi.LOGGER.info("UploadBuffers uploaded "+bytesUploaded+" bytes, with {} sub buffers", totalBuffers); } /** Uploads the uploadBuffer so the GPU can use it. */ @@ -863,7 +832,8 @@ public class LodBufferBuilderFactory private boolean swapBuffers() { bufferLock.lock(); - ClientApi.LOGGER.debug("Lod Swap Buffers"); + if (ENABLE_BUFFER_SWAP_LOGGING) + ClientApi.LOGGER.info("Lod Swap Buffers"); { boolean shouldRegenBuff = true; try diff --git a/src/main/java/com/seibel/lod/core/builders/lodBuilding/LodBuilder.java b/src/main/java/com/seibel/lod/core/builders/lodBuilding/LodBuilder.java index 1923776db..f5adb6ddb 100644 --- a/src/main/java/com/seibel/lod/core/builders/lodBuilding/LodBuilder.java +++ b/src/main/java/com/seibel/lod/core/builders/lodBuilding/LodBuilder.java @@ -181,8 +181,8 @@ public class LodBuilder int subX = i/16; int subZ = i%16; writeVerticalData(data, i*maxVerticalData, maxVerticalData, chunk, config, subX, subZ); - if (DataPointUtil.isVoid(data[i*maxVerticalData])) - ClientApi.LOGGER.info("Datapoint is Void: {}, {}", chunk.getMinX()+subX, chunk.getMinZ()+subZ); + //if (DataPointUtil.isVoid(data[i*maxVerticalData])) + // ClientApi.LOGGER.debug("Datapoint is Void: {}, {}", chunk.getMinX()+subX, chunk.getMinZ()+subZ); if (!DataPointUtil.doesItExist(data[i*maxVerticalData])) throw new RuntimeException("Datapoint does not exist at "+ chunk.getMinX()+subX +", "+ chunk.getMinZ()+subZ); if (DataPointUtil.getGenerationMode(data[i*maxVerticalData]) != config.distanceGenerationMode.complexity) diff --git a/src/main/java/com/seibel/lod/core/handlers/LodDimensionFileHandler.java b/src/main/java/com/seibel/lod/core/handlers/LodDimensionFileHandler.java index 9c20f3110..f0c9b8690 100644 --- a/src/main/java/com/seibel/lod/core/handlers/LodDimensionFileHandler.java +++ b/src/main/java/com/seibel/lod/core/handlers/LodDimensionFileHandler.java @@ -24,9 +24,7 @@ import java.nio.file.Files; import java.nio.file.StandardCopyOption; import java.time.Duration; import java.time.Instant; -import java.util.ArrayList; import java.util.ConcurrentModificationException; -import java.util.HashSet; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; @@ -38,7 +36,6 @@ import org.apache.commons.compress.compressors.xz.XZCompressorInputStream; import org.apache.commons.compress.compressors.xz.XZCompressorOutputStream; import com.seibel.lod.core.api.ClientApi; -import com.seibel.lod.core.enums.config.DistanceGenerationMode; import com.seibel.lod.core.enums.config.VerticalQuality; import com.seibel.lod.core.objects.lod.LodDimension; import com.seibel.lod.core.objects.lod.LodRegion; @@ -59,6 +56,9 @@ import com.seibel.lod.core.util.LodUtil; */ public class LodDimensionFileHandler { + public static final boolean ENABLE_SAVE_THREAD_LOGGING = true; + public static final boolean ENABLE_SAVE_REGION_LOGGING = false; + /** This is the dimension that owns this file handler */ private final LodDimension lodDimension; @@ -161,10 +161,6 @@ public class LodDimensionFileHandler } } } - - - - } @@ -286,8 +282,10 @@ public class LodDimensionFileHandler File file = new File(getFileBasePath() + vertQual + File.separatorChar + DETAIL_FOLDER_NAME_PREFIX + dataContainer.detailLevel + File.separatorChar + FILE_NAME_PREFIX + "." + posX + "." + posZ + FILE_EXTENSION); - if (file.exists()) - throw new IllegalStateException("saveDirect(...) should only be used for converting old save structure!"); + if (file.exists()) { + ClientApi.LOGGER.warn("LOD file write warn. Unable to write [" + file + "] because the newer version file already exist! Skipping this position..."); + return; + } if (!file.getParentFile().exists()) file.getParentFile().mkdirs(); try { @@ -337,7 +335,7 @@ public class LodDimensionFileHandler } trySaveRegionsToBeSaved(); if (blockUntilFinished) { - ClientApi.LOGGER.info("Blocking until lod file save finishes!"); + if (ENABLE_SAVE_THREAD_LOGGING) ClientApi.LOGGER.info("Blocking until lod file save finishes!"); try { fileWritingThreadPool.shutdown(); boolean worked = fileWritingThreadPool.awaitTermination(30, TimeUnit.SECONDS); @@ -374,7 +372,8 @@ public class LodDimensionFileHandler boolean isStarted = isFileWritingThreadRunning.get(); if (!isStarted) throw new ConcurrentModificationException("WriterMain Triggered but the thead state is not started!?"); - ClientApi.LOGGER.info("Lod File Writer started. To-be-written-regions: "+regionToSave.size()); + if (ENABLE_SAVE_THREAD_LOGGING) + ClientApi.LOGGER.info("Lod File Writer started. To-be-written-regions: "+regionToSave.size()); Instant start = Instant.now(); // Note: Since regionToSave is a ConcurrentHashMap, and the .values() return one that support concurrency, // this for loop should be safe and loop until all values are gone. @@ -387,11 +386,13 @@ public class LodDimensionFileHandler if (!regionToSave.remove(r.getRegionPos(), r)) continue; r.needSaving = false; Instant i = Instant.now(); - ClientApi.LOGGER.info("Lod: Saving Region "+r.getRegionPos()); + if (ENABLE_SAVE_REGION_LOGGING) + ClientApi.LOGGER.info("Lod: Saving Region "+r.getRegionPos()); saveRegionToFile(r); Instant j = Instant.now(); Duration d = Duration.between(i, j); - ClientApi.LOGGER.info("Lod: Region "+r.getRegionPos()+" save finish. Took "+d); + if (ENABLE_SAVE_REGION_LOGGING) + ClientApi.LOGGER.info("Lod: Region "+r.getRegionPos()+" save finish. Took "+d); } catch (Exception e) { @@ -402,7 +403,8 @@ public class LodDimensionFileHandler } } Instant end = Instant.now(); - ClientApi.LOGGER.info("Lod File Writer completed. Took "+Duration.between(start, end)); + if (ENABLE_SAVE_THREAD_LOGGING) + ClientApi.LOGGER.info("Lod File Writer completed. Took "+Duration.between(start, end)); // Use Memory order Release to release any memory changes on setting this boolean // (Corresponding call is the this::saveRegions(...)::...compareAndExchangeAcquire(false, true);) // isFileWritingThreadRunning.setRelease(false); @@ -424,7 +426,8 @@ public class LodDimensionFileHandler { // Get the old file File oldFile = getRegionFile(region.regionPosX, region.regionPosZ, detailLevel, region.getVerticalQuality()); - ClientApi.LOGGER.debug("saving region [" + region.regionPosX + ", " + region.regionPosZ + "] detail "+detailLevel+" to file."); + if (ENABLE_SAVE_REGION_LOGGING) + ClientApi.LOGGER.debug("saving region [" + region.regionPosX + ", " + region.regionPosZ + "] detail "+detailLevel+" to file."); boolean isFileFullyGened = false; // make sure the file and folder exists diff --git a/src/main/java/com/seibel/lod/core/objects/opengl/LodVertexBuffer.java b/src/main/java/com/seibel/lod/core/objects/opengl/LodVertexBuffer.java index 8113a0a3d..8c85d3116 100644 --- a/src/main/java/com/seibel/lod/core/objects/opengl/LodVertexBuffer.java +++ b/src/main/java/com/seibel/lod/core/objects/opengl/LodVertexBuffer.java @@ -47,7 +47,7 @@ public class LodVertexBuffer implements AutoCloseable this.id = GL32.glGenBuffers(); this.isBufferStorage = isBufferStorage; count++; - ClientApi.LOGGER.info("LodVertexBuffer Count: "+count); + ClientApi.LOGGER.debug("LodVertexBuffer Count: "+count); } @@ -64,7 +64,11 @@ public class LodVertexBuffer implements AutoCloseable } this.id = -1; count--; - ClientApi.LOGGER.info("LodVertexBuffer Count: "+count); + ClientApi.LOGGER.debug("LodVertexBuffer Count: "+count); + if (count==0) ClientApi.LOGGER.info("All LodVerrtexBuffer is freed."); + } else { + ClientApi.LOGGER.error("LodVertexBuffer double close!"); + } } } \ No newline at end of file diff --git a/src/main/java/com/seibel/lod/core/util/MovableGridList.java b/src/main/java/com/seibel/lod/core/util/MovableGridList.java index 9ccfacfa4..29c570ed6 100644 --- a/src/main/java/com/seibel/lod/core/util/MovableGridList.java +++ b/src/main/java/com/seibel/lod/core/util/MovableGridList.java @@ -48,7 +48,9 @@ public class MovableGridList extends ArrayList implements List { } } public void clear(Consumer d) { - super.forEach(d); + super.forEach((t) -> { + if (t!=null) d.accept(t); + }); super.clear(); super.ensureCapacity(gridSize*gridSize); for (int i=0; i extends ArrayList implements List { return true; } - public void move(int newCenterX, int newCenterY, Consumer d) { - if (centerX == newCenterX && centerY == newCenterY) return; + public boolean move(int newCenterX, int newCenterY, Consumer d) { + if (centerX == newCenterX && centerY == newCenterY) return false; int deltaX = newCenterX - centerX; int deltaY = newCenterY - centerY; @@ -190,7 +192,7 @@ public class MovableGridList extends ArrayList implements List { // update the new center centerX = newCenterX; centerY = newCenterY; - return; + return true; } centerX = newCenterX; centerY = newCenterY; @@ -200,7 +202,8 @@ public class MovableGridList extends ArrayList implements List { for (int y=0; y=gridSize || y-deltaY>=gridSize) { - d.accept(_getDirect(x,y)); + T t = _getDirect(x,y); + if (t!=null) d.accept(t); } } } @@ -250,6 +253,7 @@ public class MovableGridList extends ArrayList implements List { } } } + return true; }