Fixed Buffer leaks, cleanup Debug logging

This commit is contained in:
tom lee
2022-01-22 16:09:58 +08:00
parent 608dc443dc
commit 9580335692
6 changed files with 73 additions and 89 deletions
@@ -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;
@@ -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<LodBufferBuilder>(renderRange, playerRegionX, playerRegionZ);
buildableVbos = new MovableGridList<LodVertexBuffer[]>(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. <br><br>
* <p>
* 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 <br>
* and destroys any bound OpenGL objects. <br>
@@ -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
@@ -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)
@@ -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
@@ -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!");
}
}
}
@@ -48,7 +48,9 @@ public class MovableGridList<T> extends ArrayList<T> implements List<T> {
}
}
public void clear(Consumer<? super T> d) {
super.forEach(d);
super.forEach((t) -> {
if (t!=null) d.accept(t);
});
super.clear();
super.ensureCapacity(gridSize*gridSize);
for (int i=0; i<gridSize*gridSize; i++) {
@@ -176,8 +178,8 @@ public class MovableGridList<T> extends ArrayList<T> implements List<T> {
return true;
}
public void move(int newCenterX, int newCenterY, Consumer<? super T> d) {
if (centerX == newCenterX && centerY == newCenterY) return;
public boolean move(int newCenterX, int newCenterY, Consumer<? super T> d) {
if (centerX == newCenterX && centerY == newCenterY) return false;
int deltaX = newCenterX - centerX;
int deltaY = newCenterY - centerY;
@@ -190,7 +192,7 @@ public class MovableGridList<T> extends ArrayList<T> implements List<T> {
// update the new center
centerX = newCenterX;
centerY = newCenterY;
return;
return true;
}
centerX = newCenterX;
centerY = newCenterY;
@@ -200,7 +202,8 @@ public class MovableGridList<T> extends ArrayList<T> implements List<T> {
for (int y=0; y<gridSize; y++) {
if (x-deltaX<0 || y-deltaY<0 ||
x-deltaX>=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<T> extends ArrayList<T> implements List<T> {
}
}
}
return true;
}