Issue
I have a Spring Boot app which uses Hibernate to generate the below query to a postgresql database. On a fast, local system (6 fast cores with HT, lots of ram, fast ssd) the query to the database runs at a reasonable 12-65 ms.
To my surprise, once I deployed to one of Digital Ocean's virtual servers, the response of the same query dropped to an unacceptable 150-250 ms or higher. Since this is still a test environment, with almost no data on or traffic to the server, I wasn't really expecting even the cheapest servers, with only 1 shared CPU and 2gb of ram, to have any problems with this query. Am I simply in the wrong here? Upgrading the CPU to something heavier increased the performance back to what I was expecting.
In any case, is there anything wrong with the below query? Can it be optimized further? Since it's an important part of the app, I want it to be as performant as possible. Since the joins are likely taking the majority of the execution time, I'm considering smashing all the tables together into one table, at which point I'd only need a large where clause to achieve the same but without the joins. Would that be faster?
select
mapcellent0_.gameworld_id as gameworl1_10_0_,
mapcellent0_.id as id2_10_0_,
villageent1_.gameworld_id as gameworl1_17_1_,
villageent1_.village_id as village_2_17_1_,
playerenti2_.gameworld_id as gameworl1_13_2_,
playerenti2_.id as id2_13_2_,
kingdoment3_.gameworld_id as gameworl1_8_3_,
kingdoment3_.kingdom_id as kingdom_2_8_3_,
mapcellent0_.kingdom_id as kingdom_3_10_0_,
mapcellent0_.landscape as landscap4_10_0_,
mapcellent0_.oasis as oasis5_10_0_,
mapcellent0_.res_type as res_type6_10_0_,
mapcellent0_.x as x7_10_0_,
mapcellent0_.y as y8_10_0_,
villageent1_.is_city as is_city3_17_1_,
villageent1_.is_main_village as is_main_4_17_1_,
villageent1_.kingdom_id as kingdom_5_17_1_,
villageent1_.map_id as map_id6_17_1_,
villageent1_.name as name7_17_1_,
villageent1_.player_id as player_i8_17_1_,
villageent1_.population as populati9_17_1_,
villageent1_.tribe_id as tribe_i10_17_1_,
villageent1_.x as x11_17_1_,
villageent1_.y as y12_17_1_,
playerenti2_.external_login_token as external3_13_2_,
playerenti2_.kingdom_id as kingdom_4_13_2_,
playerenti2_.name as name5_13_2_,
playerenti2_.role as role6_13_2_,
playerenti2_.treasures as treasure7_13_2_,
playerenti2_.tribe_id as tribe_id8_13_2_,
kingdoment3_.creation_time as creation3_8_3_,
kingdoment3_.kingdom_tag as kingdom_4_8_3_,
kingdoment3_.victory_points as victory_5_8_3_
from
map_cells mapcellent0_
left outer join
villages villageent1_
on mapcellent0_.gameworld_id=villageent1_.gameworld_id
and mapcellent0_.id=villageent1_.map_id
left outer join
players playerenti2_
on villageent1_.gameworld_id=playerenti2_.gameworld_id
and villageent1_.player_id=playerenti2_.id
left outer join
kingdoms kingdoment3_
on playerenti2_.gameworld_id=kingdoment3_.gameworld_id
and playerenti2_.kingdom_id=kingdoment3_.kingdom_id
where
mapcellent0_.gameworld_id=?
and (
mapcellent0_.x in (
? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ?
)
)
and (
mapcellent0_.y in (
? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ?
)
)
order by
mapcellent0_.x asc
Running EXPLAIN ANALYZE on the query on the fast machine produces the following:
(see https://explain.depesz.com/s/IYcK for a graphical presentation)
"Sort (cost=241.63..242.01 rows=152 width=216) (actual time=1.471..1.475 rows=121 loops=1)"
" Sort Key: mapcellent0_.x"
" Sort Method: quicksort Memory: 47kB"
" -> Hash Left Join (cost=191.63..236.12 rows=152 width=216) (actual time=1.252..1.432 rows=121 loops=1)"
" Hash Cond: ((playerenti2_.gameworld_id = kingdoment3_.gameworld_id) AND (playerenti2_.kingdom_id = kingdoment3_.kingdom_id))"
" -> Hash Right Join (cost=189.69..233.35 rows=152 width=181) (actual time=1.203..1.363 rows=121 loops=1)"
" Hash Cond: ((playerenti2_.gameworld_id = villageent1_.gameworld_id) AND (playerenti2_.id = villageent1_.player_id))"
" -> Seq Scan on players playerenti2_ (cost=0.00..35.34 rows=907 width=77) (actual time=0.019..0.102 rows=907 loops=1)"
" Filter: (gameworld_id = '7fe13a96-f540-4263-9de0-6d20da44fecb'::uuid)"
" -> Hash (cost=187.41..187.41 rows=152 width=104) (actual time=1.153..1.154 rows=121 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 21kB"
" -> Hash Right Join (cost=117.65..187.41 rows=152 width=104) (actual time=0.466..1.107 rows=121 loops=1)"
" Hash Cond: ((villageent1_.gameworld_id = mapcellent0_.gameworld_id) AND (villageent1_.map_id = mapcellent0_.id))"
" -> Seq Scan on villages villageent1_ (cost=0.00..57.41 rows=2353 width=60) (actual time=0.008..0.326 rows=2353 loops=1)"
" Filter: (gameworld_id = '7fe13a96-f540-4263-9de0-6d20da44fecb'::uuid)"
" -> Hash (cost=115.37..115.37 rows=152 width=44) (actual time=0.435..0.435 rows=121 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 17kB"
" -> Index Scan using idx_map_cell_y_only on map_cells mapcellent0_ (cost=0.29..115.37 rows=152 width=44) (actual time=0.035..0.400 rows=121 loops=1)"
" Index Cond: (y = ANY ('{-5,-4,-3,-2,-1,0,1,2,3,4,5}'::integer[]))"
" Filter: ((gameworld_id = '7fe13a96-f540-4263-9de0-6d20da44fecb'::uuid) AND (x = ANY ('{-5,-4,-3,-2,-1,0,1,2,3,4,5}'::integer[])))"
" Rows Removed by Filter: 1190"
" -> Hash (cost=1.43..1.43 rows=34 width=35) (actual time=0.028..0.028 rows=34 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 11kB"
" -> Seq Scan on kingdoms kingdoment3_ (cost=0.00..1.43 rows=34 width=35) (actual time=0.005..0.008 rows=34 loops=1)"
" Filter: (gameworld_id = '7fe13a96-f540-4263-9de0-6d20da44fecb'::uuid)"
"Planning Time: 0.600 ms"
"Execution Time: 1.575 ms"
EDIT, slow machine's explain(buffers, analyze):
Sort (cost=253.87..254.25 rows=152 width=216) (actual time=11.517..11.545 rows=121 loops=1)
Sort Key: mapcellent0_.x
Sort Method: quicksort Memory: 47kB
Buffers: shared hit=23 read=99
I/O Timings: read=7.506
-> Hash Left Join (cost=211.99..248.36 rows=152 width=216) (actual time=10.175..11.374 rows=121 loops=1)
Hash Cond: ((playerenti2_.gameworld_id = kingdoment3_.gameworld_id) AND (playerenti2_.kingdom_id = kingdoment3_.kingdom_id))
Buffers: shared hit=20 read=99
I/O Timings: read=7.506
-> Hash Right Join (cost=210.19..245.73 rows=152 width=181) (actual time=9.684..10.826 rows=121 loops=1)
Hash Cond: ((playerenti2_.gameworld_id = villageent1_.gameworld_id) AND (playerenti2_.id = villageent1_.player_id))
Buffers: shared hit=20 read=98
I/O Timings: read=7.121
-> Seq Scan on players playerenti2_ (cost=0.00..27.64 rows=851 width=77) (actual time=0.377..1.291 rows=850 loops=1)
Filter: (gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid)
Buffers: shared read=17
I/O Timings: read=1.073
-> Hash (cost=207.91..207.91 rows=152 width=104) (actual time=9.267..9.281 rows=121 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 21kB
Buffers: shared hit=17 read=81
I/O Timings: read=6.049
-> Hash Right Join (cost=109.65..207.91 rows=152 width=104) (actual time=5.617..9.147 rows=121 loops=1)
Hash Cond: ((villageent1_.gameworld_id = mapcellent0_.gameworld_id) AND (villageent1_.map_id = mapcellent0_.id))
Buffers: shared hit=17 read=81
I/O Timings: read=6.049
-> Seq Scan on villages villageent1_ (cost=0.00..85.76 rows=2381 width=60) (actual time=0.362..2.983 rows=2380 loops=1)
Filter: (gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid)
Buffers: shared read=56
I/O Timings: read=2.145
-> Hash (cost=107.37..107.37 rows=152 width=44) (actual time=5.176..5.188 rows=121 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 17kB
Buffers: shared hit=17 read=25
I/O Timings: read=3.904
-> Index Scan using idx_map_cell_y_only on map_cells mapcellent0_ (cost=0.29..107.37 rows=152 width=44) (actual time=1.403..5.054 rows=121 loops=1)
Index Cond: (y = ANY ('{-5,-4,-3,-2,-1,0,1,2,3,4,5}'::integer[]))
Filter: ((gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid) AND (x = ANY ('{-5,-4,-3,-2,-1,0,1,2,3,4,5}'::integer[])))
Rows Removed by Filter: 1190
Buffers: shared hit=17 read=25
I/O Timings: read=3.904
-> Hash (cost=1.36..1.36 rows=29 width=35) (actual time=0.446..0.447 rows=29 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 10kB
Buffers: shared read=1
I/O Timings: read=0.385
-> Seq Scan on kingdoms kingdoment3_ (cost=0.00..1.36 rows=29 width=35) (actual time=0.402..0.415 rows=29 loops=1)
Filter: (gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid)
Buffers: shared read=1
I/O Timings: read=0.385
Planning Time: 15.927 ms
Execution Time: 11.724 ms
(49 rows)
https://explain.depesz.com/s/1eEb
Running it once more gave me:
Sort (cost=253.87..254.25 rows=152 width=216) (actual time=2.174..2.187 rows=121 loops=1)
Sort Key: mapcellent0_.x
Sort Method: quicksort Memory: 47kB
Buffers: shared hit=113
-> Hash Left Join (cost=211.99..248.36 rows=152 width=216) (actual time=1.644..2.075 rows=121 loops=1)
Hash Cond: ((playerenti2_.gameworld_id = kingdoment3_.gameworld_id) AND (playerenti2_.kingdom_id = kingdoment3_.kingdom_id))
Buffers: shared hit=113
-> Hash Right Join (cost=210.19..245.73 rows=152 width=181) (actual time=1.614..1.983 rows=121 loops=1)
Hash Cond: ((playerenti2_.gameworld_id = villageent1_.gameworld_id) AND (playerenti2_.id = villageent1_.player_id))
Buffers: shared hit=112
-> Seq Scan on players playerenti2_ (cost=0.00..27.64 rows=851 width=77) (actual time=0.005..0.193 rows=850 loops=1)
Filter: (gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid)
Buffers: shared hit=17
-> Hash (cost=207.91..207.91 rows=152 width=104) (actual time=1.593..1.594 rows=121 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 21kB
Buffers: shared hit=95
-> Hash Right Join (cost=109.65..207.91 rows=152 width=104) (actual time=0.630..1.545 rows=121 loops=1)
Hash Cond: ((villageent1_.gameworld_id = mapcellent0_.gameworld_id) AND (villageent1_.map_id = mapcellent0_.id))
Buffers: shared hit=95
-> Seq Scan on villages villageent1_ (cost=0.00..85.76 rows=2381 width=60) (actual time=0.009..0.490 rows=2380 loops=1)
Filter: (gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid)
Buffers: shared hit=56
-> Hash (cost=107.37..107.37 rows=152 width=44) (actual time=0.602..0.603 rows=121 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 17kB
Buffers: shared hit=39
-> Index Scan using idx_map_cell_y_only on map_cells mapcellent0_ (cost=0.29..107.37 rows=152 width=44) (actual time=0.047..0.558 rows=121 loops=1)
Index Cond: (y = ANY ('{-5,-4,-3,-2,-1,0,1,2,3,4,5}'::integer[]))
Filter: ((gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid) AND (x = ANY ('{-5,-4,-3,-2,-1,0,1,2,3,4,5}'::integer[])))
Rows Removed by Filter: 1190
Buffers: shared hit=39
-> Hash (cost=1.36..1.36 rows=29 width=35) (actual time=0.020..0.020 rows=29 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 10kB
Buffers: shared hit=1
-> Seq Scan on kingdoms kingdoment3_ (cost=0.00..1.36 rows=29 width=35) (actual time=0.004..0.011 rows=29 loops=1)
Filter: (gameworld_id = '2fb2192a-9373-41e9-9119-6e73d2a07154'::uuid)
Buffers: shared hit=1
Planning Time: 1.374 ms
Execution Time: 2.309 ms
(38 rows)
EDIT 2:
A good point about these queries actually not being that slow when done directly on the database itself. I think I've been too focussed on optimizing the query itself.
I'm sending requests to my (slow) server which can take anywhere from 80 to 300 ms to complete. Basically, I'm scrolling around on a site that sends requests for map data it doesn't yet have in local javascript storage. After scrolling around, starting from the same position, I would expect postgres' caches to be warmed up.
Part of the code that's generating the SQL to send to the server is being measured by a simple println statement:
val pointsFromDbInMs = measureTimeMillis {
mapCells = mapRepository.findByIdGameworldIdAndXInAndYInOrderByX(gameworldId,
points.map { it.x }.distinct(),
points.map { it.y }.distinct())
}
println("Got ${mapCells.size} points from database in: $pointsFromDbInMs ms")
I measured everything from the REST controller before this, and all code afterwards. This is the only thing that takes any non-negligible ms to complete. So if it isn't the database itself that's taking a long time completing the query, it's whatever's between Hibernate/Spring boot and the database...? Or it's simply that the poor single core processor cannot turn the postgres records into Java/Kotlin objects fast enough..?
Solution
If you want to know where the time is spent, use a profiler like the Async Profiler: https://github.com/jvm-profiling-tools/async-profiler
IntelliJ has a nice integration for it, but you can also run it yourself: https://www.jetbrains.com/help/idea/async-profiler.html
Answered By - Christian Beikov
