log query

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;

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<Coordinate, Optional<BlocksRecord>> {
 
+    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<Coordinate, Optional<BlocksRecord>> cache;
 
@@ -46,6 +52,9 @@ public class BlocksRecordAccessor extends CacheLoader<Coordinate, Optional<Block
     }
 
     public List<BlocksRecord> getTopyDownYStride(int x, int z, int minY, int maxY) {
+
+        long start = System.currentTimeMillis();
+
         List<BlocksRecord> list = ctx
                 .selectFrom(BLOCKS)
                 .where(BLOCKS.POSX.eq(x))
@@ -55,6 +64,12 @@ public class BlocksRecordAccessor extends CacheLoader<Coordinate, Optional<Block
                 .orderBy(BLOCKS.POSY.desc())
                 .fetch();
 
+        long diff = System.currentTimeMillis() - start;
+
+        if (diff > 500 && cfg.logQueryPerformance()){
+            logger.warn("getTopyDownYStride took {} ms", diff);
+        }
+
         for (BlocksRecord record: list){
             update(record);
         }
@@ -69,11 +84,23 @@ public class BlocksRecordAccessor extends CacheLoader<Coordinate, Optional<Block
 
     @Override
     public Optional<BlocksRecord> load(Coordinate coordinate) throws Exception {
-        return ctx
+
+        long start = System.currentTimeMillis();
+
+
+        Optional<BlocksRecord> 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;
     }
 }

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();

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());
+    }
+}

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<DSLContext> {
 
 	@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;
 	}
 
 }

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<Player> players = ctx
@@ -43,7 +54,7 @@ public class PlayerRoute implements Route {
 
 		List<PlayerInfo> list = new ArrayList<>();
 
-		for (Player player: players){
+		for (Player player: players) {
 
 			List<PlayerMetadata> 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;
 	}
 

src/main/resources/logback.xml

@@ -21,7 +21,7 @@
         </encoder>
     </appender>
 
-    <logger name="org.jooq.Constants" level="WARN"></logger>
+    <logger name="org.jooq" level="WARN"/>
     <logger name="io.rudin.minetest.tileserver.TileRenderer" level="INFO"/>
 
     <root level="info">