-
-
Notifications
You must be signed in to change notification settings - Fork 227
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
very slow queries through martin #1315
Comments
Hi @pcace |
Hi @sharkAndshark, I am in a similar situation.
![]() And martin takes ~6 seconds:
![]() |
thanks for reporting! This is very concerning. Would it be possible to check if the issue is the same if an older martin version is used? |
I did a quick test on different versions of martin. It seems to work pretty well from versions 0.9.0 to 0.11.6. I can see a noticeable regression when I use v0.12.0. |
@jahermosilla thank you!!! I will have to dig deeper into what has happened at that point. One thing that MIGHT help figure it out: would it be possible for you to run some sort of a stress test, e.g. request a tile in a loop using something like Oha, but make sure to use
Ensure that there are no running queries in-between running different Martin versions. This way we can:
|
@nyurik, here are the results: Martin configkeep_alive: 75
listen_addresses: "0.0.0.0:3000"
worker_processes: 8
cache_size_mb: 0
preferred_encoding: gzip
postgres:
connection_string: "postgresql://postgres:postgres@db:5432/db"
default_srid: 4326
pool_size: 4
disable_bounds: false
functions:
tiles:
schema: geo
function: tiles
source_id_format: "{function}"
buffer: 64
minzoom: 14
maxzoom: 25 v0.11.6❯ oha -z 120s http://localhost:5000/tiles/14/8176/6234
Summary:
Success rate: 100.00%
Total: 120.0008 secs
Slowest: 5.7591 secs
Fastest: 0.4354 secs
Average: 5.2303 secs
Requests/sec: 9.7666
Total data: 1000.03 MiB
Size/request: 912.68 KiB
Size/sec: 8.33 MiB
Response time histogram:
0.435 [1] |
0.968 [6] |
1.500 [5] |
2.033 [7] |
2.565 [5] |
3.097 [4] |
3.630 [5] |
4.162 [6] |
4.694 [4] |
5.227 [173] |■■■■■■
5.759 [906] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
Response time distribution:
10.00% in 5.1610 secs
25.00% in 5.2564 secs
50.00% in 5.3421 secs
75.00% in 5.4183 secs
90.00% in 5.4833 secs
95.00% in 5.5236 secs
99.00% in 5.5984 secs
99.90% in 5.7440 secs
99.99% in 5.7591 secs
Details (average, fastest, slowest):
DNS+dialup: 0.0070 secs, 0.0008 secs, 0.1211 secs
DNS-lookup: 0.0017 secs, 0.0000 secs, 0.0129 secs
Status code distribution:
[200] 1122 responses
Error distribution:
[50] aborted due to deadline v0.12.0❯ oha -z 120s http://localhost:5000/tiles/14/8176/6234
Summary:
Success rate: 100.00%
Total: 120.0021 secs
Slowest: 89.4509 secs
Fastest: 6.0141 secs
Average: 50.6991 secs
Requests/sec: 1.0916
Total data: 63.30 MiB
Size/request: 800.22 KiB
Size/sec: 540.14 KiB
Response time histogram:
6.014 [1] |■
14.358 [7] |■■■■■■■■■■■
22.701 [8] |■■■■■■■■■■■■
31.045 [4] |■■■■■■
39.389 [4] |■■■■■■
47.733 [5] |■■■■■■■■
56.076 [9] |■■■■■■■■■■■■■■
64.420 [12] |■■■■■■■■■■■■■■■■■■■
72.764 [20] |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
81.107 [10] |■■■■■■■■■■■■■■■■
89.451 [1] |■
Response time distribution:
10.00% in 16.0105 secs
25.00% in 31.0666 secs
50.00% in 60.8164 secs
75.00% in 69.5884 secs
90.00% in 74.7607 secs
95.00% in 77.9642 secs
99.00% in 89.4509 secs
99.90% in 89.4509 secs
99.99% in 89.4509 secs
Details (average, fastest, slowest):
DNS+dialup: 0.0046 secs, 0.0000 secs, 0.0778 secs
DNS-lookup: 0.0016 secs, 0.0000 secs, 0.0105 secs
Status code distribution:
[200] 81 responses
Error distribution:
[50] aborted due to deadline Running queries during test on v.0.11.6 (every second) datname | pid | state | query | age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.004907
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.195591
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.196385
db | 1616 | active | SELECT ST_AsMVT(tile, 'tiles', 4096, 'geometry') FROM (\r +| 00:00:00.246769
| | | select\r +|
| | | [OMITED],
+|
| | | ST_AsMVTGeom(\r
+|
| | | ST_Transform(ST_CurveToLine(x.geometry), 3857),\r
+|
| | | ST_TileEnvelope(z, x, y),\r
+|
| | | 4096, 64, true\r
+|
| | | ) AS geometry\r
+|
| | | FROM [OMITED] xx\r
| | | WHERE xx.geometry && ST_TileEnvelope(z, x, y)\r
+|
| | | ) as tile WHERE geometry IS NOT NULL
|
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.24677
(5 rows)
Fri May 17 14:00:41 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.054727
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.113057
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.328635
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.371165
(4 rows)
Fri May 17 14:00:42 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.002267
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.13379
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.231671
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.294789
(4 rows)
Fri May 17 14:00:43 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.04163
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.114376
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.203973
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.246527
(4 rows)
Fri May 17 14:00:44 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.136439
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.185399
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.294084
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.294088
(4 rows)
Fri May 17 14:00:45 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.162713
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.187907
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.272371
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.353877
(4 rows)
Fri May 17 14:00:46 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.274781
(1 row)
Fri May 17 14:00:47 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.081421
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.114244
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.168092
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.37592
(4 rows)
Fri May 17 14:00:48 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.136693
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.209694
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.326173
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.386165
(4 rows)
Fri May 17 14:00:49 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.134637
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.349381
(2 rows)
Fri May 17 14:00:50 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.05008
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.15786
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.177105
(3 rows)
Fri May 17 14:00:51 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.019662
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.021038
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.278052
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.283921
(4 rows)
Fri May 17 14:00:52 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.0795
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.100143
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.377697
(3 rows)
Fri May 17 14:00:53 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1596 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.128012
db | 1595 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.164013
db | 1589 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.259666
db | 1590 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.313145
(4 rows)
Running queries during test on v.0.12.0(every second)db=# SELECT datname, pid, state, query, age(clock_timestamp(), query_start) AS age
FROM pg_stat_activity
WHERE state <> 'idle'
AND query NOT LIKE '% FROM pg_stat_activity %'
ORDER BY age;
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
db=# \watch 1
Fri May 17 13:57:40 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:57:41 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:57:42 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:57:43 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:57:44 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
^C
db=# \watch 1
Fri May 17 13:58:04 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:05 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1374 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.020556
db | 1388 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.020561
(2 rows)
Fri May 17 13:58:06 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:07 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:08 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:09 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:10 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:11 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1373 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.000724
db | 1389 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.096582
db | 1388 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.096583
(3 rows)
Fri May 17 13:58:12 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:13 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:14 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:15 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:16 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:17 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+-----------------
db | 1389 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.121798
db | 1373 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.128111
db | 1374 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.165167
(3 rows)
Fri May 17 13:58:18 2024 (every 1s)
datname | pid | state | query
| age
---------+------+--------+------------------------------------------------------------------------------------------------+----------------
db | 1373 | active | SELECT "geo"."tiles"($1::integer, $2::integer, $3::integer) AS tile | 00:00:00.33792
(1 row)
Fri May 17 13:58:19 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:20 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows)
Fri May 17 13:58:21 2024 (every 1s)
datname | pid | state | query | age
---------+-----+-------+-------+-----
(0 rows) |
From what I can see from the results it seems martin is doing something when processing a tile that is blocking/enqueueing other request? |
I wish more users would do as much testing to help as you! There's clearly a hiccup somewhere in Martin. The next step is to use something like |
Thank you for your helpful guidance @nyurik ! I'll try it! What steps should I take? I'm not very familiar with Rust but if you guide me a little bit, I'll take some time and come back with the results. |
Running a quick perf test seems to indicate the culprit is Brotli :( I ran a few minute perf test using cargo flamegraph and The flamegraph below can be examined interactively here. |
Another confirmation for this is that when I run |
* Decides which encoding to use depending on both `Accept-Encode` and the preferred encoding (chooses the preferred one in case brotli and gzip have the same q value) * Uses `gzip` by default This will fix #1315
Hi there,
i am trying to find out why martin is so much slower then a direct query to the db.
this:
http://localhost:3000/query_tile/10/544/339
takes >13s to get the tile from the server via martin.
the martin log looks like this:
using the function directly:
EXPLAIN (ANALYZE,VERBOSE) select query_tile(10,544,339)
results in:
so there is a gap of 13s where something happens.
i thought it might be the compression, but compressing the mvt tile from the db cannot take 13s. for comparison, the attached file takes 0.05s to compress using gzip. (is this comparable?)
how can i narrow down what the issue is? i have attached the resulting tile here.
All rows have spacial indices and are clustered.
339.zip
PS.: this is the martin config (changing from brotli to gzip does not make a huge difference):
The text was updated successfully, but these errors were encountered: