Skip to content
This repository was archived by the owner on Apr 7, 2019. It is now read-only.

Commit fc518ee

Browse files
naturefreshmilknaturefreshmilk
committed
log query
1 parent 1967243 commit fc518ee

File tree

7 files changed

+113
-10
lines changed

7 files changed

+113
-10
lines changed

‎src/main/java/io/rudin/minetest/tileserver/TileRenderer.java

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -98,7 +98,9 @@ public byte[] render(int tileX, int tileY, int zoom) throws IllegalArgumentExcep
9898

9999
int z1 = mapblockInfo.z;
100100
int z2 = mapblockInfo.z + ((int)mapblockInfo.height * -1);
101-
101+
102+
long start = System.currentTimeMillis();
103+
102104
Integer count = ctx
103105
.select(DSL.count())
104106
.from(BLOCKS)
@@ -110,6 +112,12 @@ public byte[] render(int tileX, int tileY, int zoom) throws IllegalArgumentExcep
110112
.and(yCondition)
111113
)
112114
.fetchOne(DSL.count());
115+
116+
long diff = System.currentTimeMillis() - start;
117+
118+
if (diff > 250 && cfg.logQueryPerformance()){
119+
logger.warn("white-count-query took {} ms", diff);
120+
}
113121

114122
if (count == 0) {
115123
logger.debug("Fail-fast, got zero mapblock count for x={}-{} z={}-{}", x1,x2, z1,z2);
@@ -297,6 +305,11 @@ public BufferedImage renderImage(int tileX, int tileY, int zoom) throws IllegalA
297305

298306
now = System.currentTimeMillis();
299307
long timingZeroCountCheck = now - start;
308+
309+
if (timingZeroCountCheck > 250 && cfg.logQueryPerformance()){
310+
logger.warn("count-zero-check took {} ms", timingZeroCountCheck);
311+
}
312+
300313
start = now;
301314

302315
long timingRender = 0;

‎src/main/java/io/rudin/minetest/tileserver/accessor/BlocksRecordAccessor.java

Lines changed: 29 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,8 @@
99
import io.rudin.minetest.tileserver.config.TileServerConfig;
1010
import jdk.nashorn.internal.ir.Block;
1111
import org.jooq.DSLContext;
12+
import org.slf4j.Logger;
13+
import org.slf4j.LoggerFactory;
1214

1315
import javax.inject.Inject;
1416
import javax.inject.Singleton;
@@ -23,15 +25,19 @@
2325
@Singleton
2426
public class BlocksRecordAccessor extends CacheLoader<Coordinate, Optional<BlocksRecord>> {
2527

28+
private static final Logger logger = LoggerFactory.getLogger(BlocksRecordAccessor.class);
29+
2630
@Inject
27-
public BlocksRecordAccessor(DSLContext ctx){
31+
public BlocksRecordAccessor(DSLContext ctx, TileServerConfig cfg){
2832
this.ctx = ctx;
33+
this.cfg = cfg;
2934
this.cache = CacheBuilder.newBuilder()
3035
.maximumSize(5000)
3136
.expireAfterAccess(10, TimeUnit.MINUTES)
3237
.build(this);
3338
}
3439

40+
private final TileServerConfig cfg;
3541

3642
private final LoadingCache<Coordinate, Optional<BlocksRecord>> cache;
3743

@@ -46,6 +52,9 @@ public Optional<BlocksRecord> get(Coordinate coords){
4652
}
4753

4854
public List<BlocksRecord> getTopyDownYStride(int x, int z, int minY, int maxY) {
55+
56+
long start = System.currentTimeMillis();
57+
4958
List<BlocksRecord> list = ctx
5059
.selectFrom(BLOCKS)
5160
.where(BLOCKS.POSX.eq(x))
@@ -55,6 +64,12 @@ public List<BlocksRecord> getTopyDownYStride(int x, int z, int minY, int maxY) {
5564
.orderBy(BLOCKS.POSY.desc())
5665
.fetch();
5766

67+
long diff = System.currentTimeMillis() - start;
68+
69+
if (diff > 500 && cfg.logQueryPerformance()){
70+
logger.warn("getTopyDownYStride took {} ms", diff);
71+
}
72+
5873
for (BlocksRecord record: list){
5974
update(record);
6075
}
@@ -69,11 +84,23 @@ public void update(BlocksRecord block){
6984

7085
@Override
7186
public Optional<BlocksRecord> load(Coordinate coordinate) throws Exception {
72-
return ctx
87+
88+
long start = System.currentTimeMillis();
89+
90+
91+
Optional<BlocksRecord> record = ctx
7392
.selectFrom(BLOCKS)
7493
.where(BLOCKS.POSX.eq(coordinate.x))
7594
.and(BLOCKS.POSY.eq(coordinate.y))
7695
.and(BLOCKS.POSZ.eq(coordinate.z))
7796
.fetchOptional();
97+
98+
99+
long diff = System.currentTimeMillis() - start;
100+
101+
if (diff > 500 && cfg.logQueryPerformance()){
102+
logger.warn("load took {} ms", diff);
103+
}
104+
return record;
78105
}
79106
}

‎src/main/java/io/rudin/minetest/tileserver/config/TileServerConfig.java

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -46,6 +46,10 @@ public interface TileServerConfig extends Config {
4646
Logging stuff
4747
*/
4848

49+
@Key("log.query.performance")
50+
@DefaultValue("false")
51+
boolean logQueryPerformance();
52+
4953
@Key("log.tile.updatetimings")
5054
@DefaultValue("false")
5155
boolean logTileUpdateTimings();

‎src/main/java/io/rudin/minetest/tileserver/module/LoggingExecuteListener.java

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
package io.rudin.minetest.tileserver.module;
2+
3+
import org.jooq.ExecuteContext;
4+
import org.jooq.impl.DefaultExecuteListener;
5+
import org.jooq.tools.StopWatch;
6+
import org.slf4j.Logger;
7+
import org.slf4j.LoggerFactory;
8+
9+
public class LoggingExecuteListener extends DefaultExecuteListener {
10+
11+
private static final Logger logger = LoggerFactory.getLogger(LoggingExecuteListener.class);
12+
13+
StopWatch watch;
14+
15+
class SQLPerformanceWarning extends Exception {}
16+
17+
@Override
18+
public void executeStart(ExecuteContext ctx) {
19+
super.executeStart(ctx);
20+
watch = new StopWatch();
21+
}
22+
23+
@Override
24+
public void executeEnd(ExecuteContext ctx) {
25+
super.executeEnd(ctx);
26+
if (watch.split() > 5_000_000_000L)
27+
logger.warn(
28+
"Slow SQL",
29+
new SQLPerformanceWarning());
30+
}
31+
}

‎src/main/java/io/rudin/minetest/tileserver/provider/DSLContextProvider.java

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,10 @@
44
import javax.inject.Provider;
55
import javax.inject.Singleton;
66

7+
import io.rudin.minetest.tileserver.config.TileServerConfig;
8+
import io.rudin.minetest.tileserver.module.LoggingExecuteListener;
79
import org.jooq.DSLContext;
10+
import org.jooq.ExecuteListener;
811
import org.jooq.SQLDialect;
912
import org.jooq.impl.DSL;
1013

@@ -14,15 +17,23 @@
1417
public class DSLContextProvider implements Provider<DSLContext> {
1518

1619
@Inject
17-
public DSLContextProvider(HikariDataSource ds) {
20+
public DSLContextProvider(HikariDataSource ds, TileServerConfig cfg) {
1821
this.ds = ds;
22+
this.cfg = cfg;
1923
}
20-
24+
25+
private final TileServerConfig cfg;
26+
2127
private final HikariDataSource ds;
2228

2329
@Override
2430
public DSLContext get() {
25-
return DSL.using(ds, SQLDialect.POSTGRES);
31+
DSLContext ctx = DSL.using(ds, SQLDialect.POSTGRES);
32+
33+
if (cfg.logQueryPerformance())
34+
ctx.configuration().set(new LoggingExecuteListener());
35+
36+
return ctx;
2637
}
2738

2839
}

‎src/main/java/io/rudin/minetest/tileserver/route/PlayerRoute.java

Lines changed: 20 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -6,11 +6,15 @@
66
import javax.inject.Inject;
77
import javax.inject.Singleton;
88

9+
import io.rudin.minetest.tileserver.accessor.BlocksRecordAccessor;
910
import io.rudin.minetest.tileserver.blockdb.tables.pojos.PlayerMetadata;
11+
import io.rudin.minetest.tileserver.config.TileServerConfig;
1012
import io.rudin.minetest.tileserver.entity.PlayerInfo;
1113
import org.jooq.DSLContext;
1214

1315
import io.rudin.minetest.tileserver.blockdb.tables.pojos.Player;
16+
import org.slf4j.Logger;
17+
import org.slf4j.LoggerFactory;
1418
import spark.Request;
1519
import spark.Response;
1620
import spark.Route;
@@ -22,17 +26,24 @@
2226
@Singleton
2327
public class PlayerRoute implements Route {
2428

29+
private static final Logger logger = LoggerFactory.getLogger(PlayerRoute.class);
30+
2531
@Inject
26-
public PlayerRoute(DSLContext ctx) {
32+
public PlayerRoute(DSLContext ctx, TileServerConfig cfg) {
2733
this.ctx = ctx;
34+
this.cfg = cfg;
2835
}
29-
36+
37+
private final TileServerConfig cfg;
38+
3039
private final DSLContext ctx;
3140

3241
@Override
3342
public Object handle(Request request, Response response) throws Exception {
3443
response.header("Content-Type", "application/json");
3544

45+
long start = System.currentTimeMillis();
46+
3647
Timestamp ts = new Timestamp(System.currentTimeMillis() - (3600L*1000L));
3748

3849
List<Player> players = ctx
@@ -43,7 +54,7 @@ public Object handle(Request request, Response response) throws Exception {
4354

4455
List<PlayerInfo> list = new ArrayList<>();
4556

46-
for (Player player: players){
57+
for (Player player: players) {
4758

4859
List<PlayerMetadata> metadata = ctx
4960
.selectFrom(PLAYER_METADATA)
@@ -53,6 +64,12 @@ public Object handle(Request request, Response response) throws Exception {
5364
list.add(new PlayerInfo(player, metadata));
5465
}
5566

67+
long diff = System.currentTimeMillis() - start;
68+
69+
if (diff > 250 && cfg.logQueryPerformance()){
70+
logger.warn("getTopyDownYStride took {} ms", diff);
71+
}
72+
5673
return list;
5774
}
5875

‎src/main/resources/logback.xml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,7 +21,7 @@
2121
</encoder>
2222
</appender>
2323

24-
<logger name="org.jooq.Constants" level="WARN"></logger>
24+
<logger name="org.jooq" level="WARN"/>
2525
<logger name="io.rudin.minetest.tileserver.TileRenderer" level="INFO"/>
2626

2727
<root level="info">

0 commit comments

Comments
 (0)