From fc518ee0ca82885a931c57b1c03a96cc0a53e506 Mon Sep 17 00:00:00 2001 From: Thomas Rudin Date: Mon, 16 Jul 2018 22:09:24 +0200 Subject: [PATCH] log query --- .../minetest/tileserver/TileRenderer.java | 15 ++++++++- .../accessor/BlocksRecordAccessor.java | 31 +++++++++++++++++-- .../tileserver/config/TileServerConfig.java | 4 +++ .../module/LoggingExecuteListener.java | 31 +++++++++++++++++++ .../provider/DSLContextProvider.java | 17 ++++++++-- .../tileserver/route/PlayerRoute.java | 23 ++++++++++++-- src/main/resources/logback.xml | 2 +- 7 files changed, 113 insertions(+), 10 deletions(-) create mode 100644 src/main/java/io/rudin/minetest/tileserver/module/LoggingExecuteListener.java diff --git a/src/main/java/io/rudin/minetest/tileserver/TileRenderer.java b/src/main/java/io/rudin/minetest/tileserver/TileRenderer.java index ef44390..8e3d3f6 100644 --- a/src/main/java/io/rudin/minetest/tileserver/TileRenderer.java +++ b/src/main/java/io/rudin/minetest/tileserver/TileRenderer.java @@ -98,7 +98,9 @@ public class TileRenderer { int z1 = mapblockInfo.z; int z2 = mapblockInfo.z + ((int)mapblockInfo.height * -1); - + + long start = System.currentTimeMillis(); + Integer count = ctx .select(DSL.count()) .from(BLOCKS) @@ -110,6 +112,12 @@ public class TileRenderer { .and(yCondition) ) .fetchOne(DSL.count()); + + long diff = System.currentTimeMillis() - start; + + if (diff > 250 && cfg.logQueryPerformance()){ + logger.warn("white-count-query took {} ms", diff); + } if (count == 0) { logger.debug("Fail-fast, got zero mapblock count for x={}-{} z={}-{}", x1,x2, z1,z2); @@ -297,6 +305,11 @@ public class TileRenderer { now = System.currentTimeMillis(); long timingZeroCountCheck = now - start; + + if (timingZeroCountCheck > 250 && cfg.logQueryPerformance()){ + logger.warn("count-zero-check took {} ms", timingZeroCountCheck); + } + start = now; long timingRender = 0; diff --git a/src/main/java/io/rudin/minetest/tileserver/accessor/BlocksRecordAccessor.java b/src/main/java/io/rudin/minetest/tileserver/accessor/BlocksRecordAccessor.java index a7db01e..2735acf 100644 --- a/src/main/java/io/rudin/minetest/tileserver/accessor/BlocksRecordAccessor.java +++ b/src/main/java/io/rudin/minetest/tileserver/accessor/BlocksRecordAccessor.java @@ -9,6 +9,8 @@ import io.rudin.minetest.tileserver.blockdb.tables.records.BlocksRecord; import io.rudin.minetest.tileserver.config.TileServerConfig; import jdk.nashorn.internal.ir.Block; import org.jooq.DSLContext; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import javax.inject.Inject; import javax.inject.Singleton; @@ -23,15 +25,19 @@ import static io.rudin.minetest.tileserver.blockdb.tables.Blocks.BLOCKS; @Singleton public class BlocksRecordAccessor extends CacheLoader> { + private static final Logger logger = LoggerFactory.getLogger(BlocksRecordAccessor.class); + @Inject - public BlocksRecordAccessor(DSLContext ctx){ + public BlocksRecordAccessor(DSLContext ctx, TileServerConfig cfg){ this.ctx = ctx; + this.cfg = cfg; this.cache = CacheBuilder.newBuilder() .maximumSize(5000) .expireAfterAccess(10, TimeUnit.MINUTES) .build(this); } + private final TileServerConfig cfg; private final LoadingCache> cache; @@ -46,6 +52,9 @@ public class BlocksRecordAccessor extends CacheLoader getTopyDownYStride(int x, int z, int minY, int maxY) { + + long start = System.currentTimeMillis(); + List list = ctx .selectFrom(BLOCKS) .where(BLOCKS.POSX.eq(x)) @@ -55,6 +64,12 @@ public class BlocksRecordAccessor extends CacheLoader 500 && cfg.logQueryPerformance()){ + logger.warn("getTopyDownYStride took {} ms", diff); + } + for (BlocksRecord record: list){ update(record); } @@ -69,11 +84,23 @@ public class BlocksRecordAccessor extends CacheLoader load(Coordinate coordinate) throws Exception { - return ctx + + long start = System.currentTimeMillis(); + + + Optional record = ctx .selectFrom(BLOCKS) .where(BLOCKS.POSX.eq(coordinate.x)) .and(BLOCKS.POSY.eq(coordinate.y)) .and(BLOCKS.POSZ.eq(coordinate.z)) .fetchOptional(); + + + long diff = System.currentTimeMillis() - start; + + if (diff > 500 && cfg.logQueryPerformance()){ + logger.warn("load took {} ms", diff); + } + return record; } } diff --git a/src/main/java/io/rudin/minetest/tileserver/config/TileServerConfig.java b/src/main/java/io/rudin/minetest/tileserver/config/TileServerConfig.java index af6d1fd..2f2c60b 100644 --- a/src/main/java/io/rudin/minetest/tileserver/config/TileServerConfig.java +++ b/src/main/java/io/rudin/minetest/tileserver/config/TileServerConfig.java @@ -46,6 +46,10 @@ public interface TileServerConfig extends Config { Logging stuff */ + @Key("log.query.performance") + @DefaultValue("false") + boolean logQueryPerformance(); + @Key("log.tile.updatetimings") @DefaultValue("false") boolean logTileUpdateTimings(); diff --git a/src/main/java/io/rudin/minetest/tileserver/module/LoggingExecuteListener.java b/src/main/java/io/rudin/minetest/tileserver/module/LoggingExecuteListener.java new file mode 100644 index 0000000..28c28e0 --- /dev/null +++ b/src/main/java/io/rudin/minetest/tileserver/module/LoggingExecuteListener.java @@ -0,0 +1,31 @@ +package io.rudin.minetest.tileserver.module; + +import org.jooq.ExecuteContext; +import org.jooq.impl.DefaultExecuteListener; +import org.jooq.tools.StopWatch; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class LoggingExecuteListener extends DefaultExecuteListener { + + private static final Logger logger = LoggerFactory.getLogger(LoggingExecuteListener.class); + + StopWatch watch; + + class SQLPerformanceWarning extends Exception {} + + @Override + public void executeStart(ExecuteContext ctx) { + super.executeStart(ctx); + watch = new StopWatch(); + } + + @Override + public void executeEnd(ExecuteContext ctx) { + super.executeEnd(ctx); + if (watch.split() > 5_000_000_000L) + logger.warn( + "Slow SQL", + new SQLPerformanceWarning()); + } +} diff --git a/src/main/java/io/rudin/minetest/tileserver/provider/DSLContextProvider.java b/src/main/java/io/rudin/minetest/tileserver/provider/DSLContextProvider.java index 1c4e3ba..b9f2dc9 100644 --- a/src/main/java/io/rudin/minetest/tileserver/provider/DSLContextProvider.java +++ b/src/main/java/io/rudin/minetest/tileserver/provider/DSLContextProvider.java @@ -4,7 +4,10 @@ import javax.inject.Inject; import javax.inject.Provider; import javax.inject.Singleton; +import io.rudin.minetest.tileserver.config.TileServerConfig; +import io.rudin.minetest.tileserver.module.LoggingExecuteListener; import org.jooq.DSLContext; +import org.jooq.ExecuteListener; import org.jooq.SQLDialect; import org.jooq.impl.DSL; @@ -14,15 +17,23 @@ import com.zaxxer.hikari.HikariDataSource; public class DSLContextProvider implements Provider { @Inject - public DSLContextProvider(HikariDataSource ds) { + public DSLContextProvider(HikariDataSource ds, TileServerConfig cfg) { this.ds = ds; + this.cfg = cfg; } - + + private final TileServerConfig cfg; + private final HikariDataSource ds; @Override public DSLContext get() { - return DSL.using(ds, SQLDialect.POSTGRES); + DSLContext ctx = DSL.using(ds, SQLDialect.POSTGRES); + + if (cfg.logQueryPerformance()) + ctx.configuration().set(new LoggingExecuteListener()); + + return ctx; } } diff --git a/src/main/java/io/rudin/minetest/tileserver/route/PlayerRoute.java b/src/main/java/io/rudin/minetest/tileserver/route/PlayerRoute.java index 3142210..166a29e 100644 --- a/src/main/java/io/rudin/minetest/tileserver/route/PlayerRoute.java +++ b/src/main/java/io/rudin/minetest/tileserver/route/PlayerRoute.java @@ -6,11 +6,15 @@ import static io.rudin.minetest.tileserver.blockdb.tables.PlayerMetadata.PLAYER_ import javax.inject.Inject; import javax.inject.Singleton; +import io.rudin.minetest.tileserver.accessor.BlocksRecordAccessor; import io.rudin.minetest.tileserver.blockdb.tables.pojos.PlayerMetadata; +import io.rudin.minetest.tileserver.config.TileServerConfig; import io.rudin.minetest.tileserver.entity.PlayerInfo; import org.jooq.DSLContext; import io.rudin.minetest.tileserver.blockdb.tables.pojos.Player; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import spark.Request; import spark.Response; import spark.Route; @@ -22,17 +26,24 @@ import java.util.List; @Singleton public class PlayerRoute implements Route { + private static final Logger logger = LoggerFactory.getLogger(PlayerRoute.class); + @Inject - public PlayerRoute(DSLContext ctx) { + public PlayerRoute(DSLContext ctx, TileServerConfig cfg) { this.ctx = ctx; + this.cfg = cfg; } - + + private final TileServerConfig cfg; + private final DSLContext ctx; @Override public Object handle(Request request, Response response) throws Exception { response.header("Content-Type", "application/json"); + long start = System.currentTimeMillis(); + Timestamp ts = new Timestamp(System.currentTimeMillis() - (3600L*1000L)); List players = ctx @@ -43,7 +54,7 @@ public class PlayerRoute implements Route { List list = new ArrayList<>(); - for (Player player: players){ + for (Player player: players) { List metadata = ctx .selectFrom(PLAYER_METADATA) @@ -53,6 +64,12 @@ public class PlayerRoute implements Route { list.add(new PlayerInfo(player, metadata)); } + long diff = System.currentTimeMillis() - start; + + if (diff > 250 && cfg.logQueryPerformance()){ + logger.warn("getTopyDownYStride took {} ms", diff); + } + return list; } diff --git a/src/main/resources/logback.xml b/src/main/resources/logback.xml index 31b959d..e4d6563 100644 --- a/src/main/resources/logback.xml +++ b/src/main/resources/logback.xml @@ -21,7 +21,7 @@ - +