Thread: BUG #16241: Degraded hash join performance
The following bug has been logged on the website:
Bug reference: 16241
Logged by: Thomas Butz
Email address: tbutz@optitool.de
PostgreSQL version: 12.1
Operating system: Modified postgres:12 docker image (Debian Buster)
Description:
I'm currently analyzing a slowdown in the performance of our OSM tile
rendering toolchain. While the following query finishes quite fast with
PostgreSQL 11.4/Postgis 2.5 it takes a lot longer using PostgreSQL
12.1/Postgis 3.0:
SELECT ST_AsBinary("way") AS geom,"construction","highway","name","tunnel"
FROM (SELECT
way,
CASE WHEN substr(highway, length(highway)-4, 5) = '_link' THEN
substr(highway, 0, length(highway)-4) ELSE highway END,
CASE WHEN (tunnel = 'yes' OR tunnel = 'building_passage' OR
covered = 'yes') THEN 'yes' ELSE 'no' END AS tunnel,
construction,
localized_streetname as name,
CASE
WHEN oneway IN ('yes', '-1') THEN oneway
WHEN junction IN ('roundabout') AND (oneway IS NULL OR NOT
oneway IN ('no', 'reversible')) THEN 'yes'
ELSE NULL
END AS oneway,
horse, bicycle
FROM planet_osm_line l
JOIN (VALUES -- this join is also putting a condition on what is
selected. features not matching it do not make it into the results.
('motorway', 380),
('trunk', 370),
('primary', 360),
('secondary', 350),
('tertiary', 340),
('residential', 330),
('unclassified', 330),
('road', 330),
('living_street', 320),
('pedestrian', 310),
('raceway', 300),
('motorway_link', 240),
('trunk_link', 230),
('primary_link', 220),
('secondary_link', 210),
('tertiary_link', 200),
('service', 150),
('construction', 10)
) AS ordertable (highway, prio)
USING (highway)
WHERE highway IN ('motorway', 'motorway_link', 'trunk',
'trunk_link', 'primary', 'primary_link', 'secondary', 'secondary_link',
'tertiary',
'tertiary_link', 'residential', 'unclassified',
'road', 'service', 'pedestrian', 'raceway', 'living_street',
'construction')
AND (name IS NOT NULL
OR oneway IN ('yes', '-1')
OR junction IN ('roundabout'))
ORDER BY
z_order DESC, -- put important roads first
COALESCE(layer, 0), -- put top layered roads first
length(name) DESC, -- Try to fit big labels in first
name DESC, -- Force a consistent ordering between differently
named streets
l.osm_id DESC -- Force an ordering for streets of the same name,
e.g. dualized roads
) AS roads_text_name WHERE "way" &&
ST_SetSRID('BOX3D(1222380.956336539 6339381.37785938,1233387.888409604
6350388.309932444)'::box3d, 3857)
I've uploaded detailed EXPLAINE ANALYZE output for both scenarios:
PostgreSQL 11.4 (execution time: 140.5ms)
https://explain.depesz.com/s/BsO7
PostgreSQL 12.1 (execution time: 3394.2ms)
https://explain.depesz.com/s/TMLO
The settings/hardware on both machines is nearly identical. The only
difference is the imported data volume which is higher for the 12.1
server(europe vs germany/austria/switzerland) but that shouldn't impact the
hash join performance as the number of rows at this point should be roughly
the same.
The only culprit seems to be that the hash join takes a lot longer to finish
and i can't figure out why.
Hi, On 2020-02-03 15:33:02 +0000, PG Bug reporting form wrote: > The following bug has been logged on the website: > > Bug reference: 16241 > Logged by: Thomas Butz > Email address: tbutz@optitool.de > PostgreSQL version: 12.1 > Operating system: Modified postgres:12 docker image (Debian Buster) > Description: > > I'm currently analyzing a slowdown in the performance of our OSM tile > rendering toolchain. While the following query finishes quite fast with > PostgreSQL 11.4/Postgis 2.5 it takes a lot longer using PostgreSQL > 12.1/Postgis 3.0: Hm. This sounds somehow familar. I first thought it might be a bug that I'm literally just now am trying to find again, because I made a note to fix it before the next set of minor releases. Without writing down the bug number :(. But the bug I am thinking of was around hash *aggregates* and subplans, not joins. It'd be useful if you could get a perf profile with callgraphs. You would have to install debugging symbols for both postgres and postgis, and then do something like: SELECT pg_backend_pid(); to get the backend pid perf record --call-graph dwarf -p $pid_of_session and then run the query a times in the session you got the pid for and then cancel the perf record run with ctrl-c You can then look at the perf profile interactively with perf report --no-children and send the created file of perf report --no-children > somefile-no-children perf report --children > somefile-children - Andres
I've executed the query twice and attached the generated reports.
> Hi,
>
> On 2020-02-03 15:33:02 +0000, PG Bug reporting form wrote:
>> The following bug has been logged on the website:
>>
>> Bug reference: 16241
>> Logged by: Thomas Butz
>> Email address: tbutz@optitool.de
>> PostgreSQL version: 12.1
>> Operating system: Modified postgres:12 docker image (Debian Buster)
>> Description:
>>
>> I'm currently analyzing a slowdown in the performance of our OSM tile
>> rendering toolchain. While the following query finishes quite fast with
>> PostgreSQL 11.4/Postgis 2.5 it takes a lot longer using PostgreSQL
>> 12.1/Postgis 3.0:
>
> Hm. This sounds somehow familar.
>
> I first thought it might be a bug that I'm literally just now am trying
> to find again, because I made a note to fix it before the next set of
> minor releases. Without writing down the bug number :(.
>
> But the bug I am thinking of was around hash *aggregates* and subplans,
> not joins.
>
> It'd be useful if you could get a perf profile with callgraphs. You
> would have to install debugging symbols for both postgres and postgis,
> and then do something like:
>
> SELECT pg_backend_pid(); to get the backend pid
> perf record --call-graph dwarf -p $pid_of_session
> and then run the query a times in the session you got the pid for
> and then cancel the perf record run with ctrl-c
>
> You can then look at the perf profile interactively with
> perf report --no-children
> and send the created file of
> perf report --no-children > somefile-no-children
> perf report --children > somefile-children
>
> - Andres
Thomas Butz
> Hi,
>
> On 2020-02-03 15:33:02 +0000, PG Bug reporting form wrote:
>> The following bug has been logged on the website:
>>
>> Bug reference: 16241
>> Logged by: Thomas Butz
>> Email address: tbutz@optitool.de
>> PostgreSQL version: 12.1
>> Operating system: Modified postgres:12 docker image (Debian Buster)
>> Description:
>>
>> I'm currently analyzing a slowdown in the performance of our OSM tile
>> rendering toolchain. While the following query finishes quite fast with
>> PostgreSQL 11.4/Postgis 2.5 it takes a lot longer using PostgreSQL
>> 12.1/Postgis 3.0:
>
> Hm. This sounds somehow familar.
>
> I first thought it might be a bug that I'm literally just now am trying
> to find again, because I made a note to fix it before the next set of
> minor releases. Without writing down the bug number :(.
>
> But the bug I am thinking of was around hash *aggregates* and subplans,
> not joins.
>
> It'd be useful if you could get a perf profile with callgraphs. You
> would have to install debugging symbols for both postgres and postgis,
> and then do something like:
>
> SELECT pg_backend_pid(); to get the backend pid
> perf record --call-graph dwarf -p $pid_of_session
> and then run the query a times in the session you got the pid for
> and then cancel the perf record run with ctrl-c
>
> You can then look at the perf profile interactively with
> perf report --no-children
> and send the created file of
> perf report --no-children > somefile-no-children
> perf report --children > somefile-children
>
> - Andres
Thomas Butz
Attachment
Hi,
On 2020-02-04 10:02:45 +0100, Thomas Butz wrote:
> I've executed the query twice and attached the generated reports.
Interesting! The no-children one clearly shows that a lot of the the
time is spent evaluating regular expressions (there's other regex
functions in the profile too):
23.36% postgres postgres [.] subcolor
and that this is inside a stack of plpgsql functions:
| | |--18.95%--exec_stmt_block
| | | exec_stmt
| | | plpgsql_exec_function
| | | plpgsql_call_handler
| | | ExecInterpExpr
| | | ExecEvalExpr (inlined)
| | | exec_eval_simple_expr
| | | (inlined)
[...]
| | | plpgsql_exec_function
| | | plpgsql_call_handler
| | | ExecInterpExpr
| | | ExecEvalExpr (inlined)
| | | exec_eval_simple_expr (inlined)
[...]
| | | plpgsql_exec_function
| | | plpgsql_call_handler
| | | ExecInterpExpr
| | | ExecEvalExpr (inlined)
[...]
I'm not aware of any relevant regular expression evaluation changes
between 11 and 12. Tom, does this trigger anything?
Thomas, could you provide a EXPLAIN (ANALYZE, VERBOSE) for both
versions? Clearly the hash join is where the time is spent:
-> Hash Join (cost=1.000..6436.030 rows=44 width=517) (actual time=5.532..3383.213 rows=2779 loops=1)
Buffers: shared hit=9077
-> Index Scan using planet_osm_hstore_line_way_idx on planet_osm_hstore_line planet_osm_hstore_line
(cost=0.550..6419.380rows=491 width=352) (actual time=0.423..19.147 rows=2779 loops=1)
Index Cond: (planet_osm_hstore_line.way &&
'01030000A0110F00000100000005000000AF78D2F4ECA632411CD92E58CD2E58410000000000000000AF78D2F4ECA63241E4EED5138D3958410000000000000000D3CF6EE3EBD13241E4EED5138D3958410000000000000000D3CF6EE3EBD132411CD92E58CD2E58410000000000000000AF78D2F4ECA632411CD92E58CD2E58410000000000000000'::geometry)
Filter: ((((planet_osm_hstore_line.tags -> 'name'::text) IS NOT NULL) OR
((planet_osm_hstore_line.tags-> 'oneway'::text) = ANY ('{yes,-1}'::text[])) OR ((planet_osm_hstore_line.tags ->
'junction'::text)= 'roundabout'::text)) AND ((planet_osm_hstore_line.tags -> 'highway'::text) = ANY
('{motorway,motorway_link,trunk,trunk_link,primary,primary_link,secondary,secondary_link,tertiary,tertiary_link,residential,unclassified,road,service,pedestrian,raceway,living_street,construction}'::text[])))
Buffers: shared hit=9077
-> Hash (cost=0.230..0.230 rows=18 width=32) (actual time=0.029..0.030 rows=18 loops=1)
-> Values Scan (cost=0.000..0.230 rows=18 width=32) (actual time=0.003..0.017 rows=18 loops=1)
but I don't think it's the hash condition itself - there's no plpgsql
functions necessary for the join as far as I can tell. A VERBOSE EXPLAIN
might help up with knowing what the function being called actually is.
It seems quite possible that all that time is spent inside plpgsql
functions that are part of postgis. And that the postgis version
difference between 2.5 and 3.0 is the relevant part here, not the
postgres version difference. Or it's just in the application code:
The sort step shows among others the following column to be sorted on:
osml10n_get_streetname_from_tags(planet_osm_hstore_line.tags, true, false, ' - '::text, 'de'::text,
planet_osm_hstore_line.way,NULL::text)) DESC
which is actually likely computed as the output of the HashJoin
node. And is the only obvious candidate for a plpgsql function
potentially taking a lot of the time.
Is that function defined exactly the same between the version? Is the
underlying dataset roughly the same size? I suggest running the query
without it, and checking how long it takes.
Regards,
Andres
I was able to reduce it to a minimal example:
SELECT localized_streetname
FROM planet_osm_line
WHERE "way" && ST_SetSRID('BOX3D(1222380.956336539 6339381.37785938,1233387.888409604 6350388.309932444)'::box3d,
3857)
Your diagnosis with osml10n_get_streetname_from_tags was spot on. I'm going to report it to the author of the osml10n
extension.
Thank you for your help!
PS: I've created the execution plans using EXPLAIN (ANALYZE, VERBOSE, COSTS, BUFFERS, TIMING, SUMMARY, FORMAT json) but
iwasn't aware that i might have to check the "Output" section of a node to find potential performance problems. How do
youfind such slow outputs without using perf?
> Von: "Andres Freund" <andres@anarazel.de>
> An: "Thomas Butz" <tbutz@optitool.de>, "Tom Lane" <tgl@sss.pgh.pa.us>
> CC: "pgsql-bugs" <pgsql-bugs@lists.postgresql.org>
> Gesendet: Dienstag, 4. Februar 2020 14:44:08
> Betreff: Re: BUG #16241: Degraded hash join performance
> Hi,
>
>
> On 2020-02-04 10:02:45 +0100, Thomas Butz wrote:
>> I've executed the query twice and attached the generated reports.
>
> Interesting! The no-children one clearly shows that a lot of the the
> time is spent evaluating regular expressions (there's other regex
> functions in the profile too):
>
> 23.36% postgres postgres [.] subcolor
>
> and that this is inside a stack of plpgsql functions:
>
> | | |--18.95%--exec_stmt_block
> | | | exec_stmt
> | | | plpgsql_exec_function
> | | | plpgsql_call_handler
> | | | ExecInterpExpr
> | | | ExecEvalExpr (inlined)
> | | | exec_eval_simple_expr
> | | | (inlined)
> [...]
> | | | plpgsql_exec_function
> | | | plpgsql_call_handler
> | | | ExecInterpExpr
> | | | ExecEvalExpr (inlined)
> | | | exec_eval_simple_expr (inlined)
> [...]
> | | | plpgsql_exec_function
> | | | plpgsql_call_handler
> | | | ExecInterpExpr
> | | | ExecEvalExpr (inlined)
> [...]
>
>
> I'm not aware of any relevant regular expression evaluation changes
> between 11 and 12. Tom, does this trigger anything?
>
> Thomas, could you provide a EXPLAIN (ANALYZE, VERBOSE) for both
> versions? Clearly the hash join is where the time is spent:
>
> -> Hash Join (cost=1.000..6436.030 rows=44 width=517) (actual
> time=5.532..3383.213 rows=2779 loops=1)
> Buffers: shared hit=9077
> -> Index Scan using planet_osm_hstore_line_way_idx on planet_osm_hstore_line
> planet_osm_hstore_line (cost=0.550..6419.380 rows=491 width=352) (actual
> time=0.423..19.147 rows=2779 loops=1)
> Index Cond: (planet_osm_hstore_line.way &&
>
'01030000A0110F00000100000005000000AF78D2F4ECA632411CD92E58CD2E58410000000000000000AF78D2F4ECA63241E4EED5138D3958410000000000000000D3CF6EE3EBD13241E4EED5138D3958410000000000000000D3CF6EE3EBD132411CD92E58CD2E58410000000000000000AF78D2F4ECA632411CD92E58CD2E58410000000000000000'::geometry)
> Filter: ((((planet_osm_hstore_line.tags -> 'name'::text) IS NOT NULL) OR
> ((planet_osm_hstore_line.tags -> 'oneway'::text) = ANY ('{yes,-1}'::text[])) OR
> ((planet_osm_hstore_line.tags -> 'junction'::text) = 'roundabout'::text)) AND
> ((planet_osm_hstore_line.tags -> 'highway'::text) = ANY
>
('{motorway,motorway_link,trunk,trunk_link,primary,primary_link,secondary,secondary_link,tertiary,tertiary_link,residential,unclassified,road,service,pedestrian,raceway,living_street,construction}'::text[])))
> Buffers: shared hit=9077
> -> Hash (cost=0.230..0.230 rows=18 width=32) (actual time=0.029..0.030 rows=18
> loops=1)
> -> Values Scan (cost=0.000..0.230 rows=18 width=32) (actual time=0.003..0.017
> rows=18 loops=1)
>
> but I don't think it's the hash condition itself - there's no plpgsql
> functions necessary for the join as far as I can tell. A VERBOSE EXPLAIN
> might help up with knowing what the function being called actually is.
>
> It seems quite possible that all that time is spent inside plpgsql
> functions that are part of postgis. And that the postgis version
> difference between 2.5 and 3.0 is the relevant part here, not the
> postgres version difference. Or it's just in the application code:
>
> The sort step shows among others the following column to be sorted on:
> osml10n_get_streetname_from_tags(planet_osm_hstore_line.tags, true, false, ' -
> '::text, 'de'::text, planet_osm_hstore_line.way, NULL::text)) DESC
> which is actually likely computed as the output of the HashJoin
> node. And is the only obvious candidate for a plpgsql function
> potentially taking a lot of the time.
>
> Is that function defined exactly the same between the version? Is the
> underlying dataset roughly the same size? I suggest running the query
> without it, and checking how long it takes.
>
> Regards,
>
> Andres
--
Thomas Butz
Hi,
On 2020-02-04 15:49:10 +0100, Thomas Butz wrote:
> I was able to reduce it to a minimal example:
>
> SELECT localized_streetname
> FROM planet_osm_line
> WHERE "way" && ST_SetSRID('BOX3D(1222380.956336539 6339381.37785938,1233387.888409604 6350388.309932444)'::box3d,
3857)
>
> Your diagnosis with osml10n_get_streetname_from_tags was spot on. I'm going to report it to the author of the osml10n
extension.
Cool. Still worth checking whether there's a 11 vs 12 issue inside that function.
> Thank you for your help!
>
> PS: I've created the execution plans using EXPLAIN (ANALYZE, VERBOSE, COSTS, BUFFERS, TIMING, SUMMARY, FORMAT json)
buti wasn't aware that i might have to check the "Output" section of a node to find potential performance problems. How
doyou find such slow outputs without using perf?
It's not trivial, unfortunately :(. You can use track_functions to get
more insight, but that's better for server-wide analysis, than query
specific ones. auto_explain also has options to track nested queries,
which might help as well.
I hope we can extend EXPLAIN with more information about this kind of
thing at some point.
Regards,
Andres
Andres Freund <andres@anarazel.de> writes:
> Interesting! The no-children one clearly shows that a lot of the the
> time is spent evaluating regular expressions (there's other regex
> functions in the profile too):
> 23.36% postgres postgres [.] subcolor
Huh ...
> I'm not aware of any relevant regular expression evaluation changes
> between 11 and 12. Tom, does this trigger anything?
(1) Nope, I'm not either; the last non-back-patched change in that
code was c54159d44 in v10.
(2) subcolor() is part of regex compilation, not execution, which makes
one wonder why it's showing up at all. Maybe the regex cache in
adt/regexp.c is overflowing and preventing useful caching? But
that didn't change in v12 either. Are these test cases really
100% equivalent? I'm wondering if there are a few more "hot"
regex patterns in the v12 data ...
(3) Where the heck is the regex use coming from at all? I don't
see any regex operators in the plan. Maybe it's inside the
plpgsql function?
regards, tom lane
Hi, On 2020-02-04 11:00:29 -0500, Tom Lane wrote: > Andres Freund <andres@anarazel.de> writes: > > Interesting! The no-children one clearly shows that a lot of the the > > time is spent evaluating regular expressions (there's other regex > > functions in the profile too): > > 23.36% postgres postgres [.] subcolor > > Huh ... > > > I'm not aware of any relevant regular expression evaluation changes > > between 11 and 12. Tom, does this trigger anything? > > (1) Nope, I'm not either; the last non-back-patched change in that > code was c54159d44 in v10. > > (2) subcolor() is part of regex compilation, not execution, which makes > one wonder why it's showing up at all. Maybe the regex cache in > adt/regexp.c is overflowing and preventing useful caching? But > that didn't change in v12 either. Are these test cases really > 100% equivalent? I'm wondering if there are a few more "hot" > regex patterns in the v12 data ... They are not 100% equivalent, but the part of the plan we see is very similar rowcount wise. It's possible that the functions differ more however, there are different postgis versions involved, and apparently also an "osml10n" extension. > (3) Where the heck is the regex use coming from at all? I don't > see any regex operators in the plan. Maybe it's inside the > plpgsql function? It definitely is. The stack shows at least two levels of plpgsql functions. And Thomas has since confirmed that removing the functioncall fixes the issue. Based on the name I think this is somewhere around this: https://github.com/giggls/mapnik-german-l10n/blob/master/plpgsql/get_localized_name_from_tags.sql#L120 The callgraph indicates that most of the cost comes from within textregexreplace_noopt. Not clear why the cache isn't fixing this - there are no variables in the regexp_replace calls as far as I can see. Greetings, Andres Freund
Hi, On 2020-02-04 11:00:29 -0500, Tom Lane wrote: > Andres Freund <andres@anarazel.de> writes: > > Interesting! The no-children one clearly shows that a lot of the the > > time is spent evaluating regular expressions (there's other regex > > functions in the profile too): > > 23.36% postgres postgres [.] subcolor > > Huh ... > > > I'm not aware of any relevant regular expression evaluation changes > > between 11 and 12. Tom, does this trigger anything? > > (1) Nope, I'm not either; the last non-back-patched change in that > code was c54159d44 in v10. > > (2) subcolor() is part of regex compilation, not execution, which makes > one wonder why it's showing up at all. Maybe the regex cache in > adt/regexp.c is overflowing and preventing useful caching? But > that didn't change in v12 either. Are these test cases really > 100% equivalent? I'm wondering if there are a few more "hot" > regex patterns in the v12 data ... They are not 100% equivalent, but the part of the plan we see is very similar rowcount wise. It's possible that the functions differ more however, there are different postgis versions involved, and apparently also an "osml10n" extension. > (3) Where the heck is the regex use coming from at all? I don't > see any regex operators in the plan. Maybe it's inside the > plpgsql function? It definitely is. The stack shows at least two levels of plpgsql functions. And Thomas has since confirmed that removing the functioncall fixes the issue. Based on the name I think this is somewhere around this: https://github.com/giggls/mapnik-german-l10n/blob/master/plpgsql/get_localized_name_from_tags.sql#L120 The callgraph indicates that most of the cost comes from within textregexreplace_noopt. Not clear why the cache isn't fixing this - there are no variables in the regexp_replace calls as far as I can see. Greetings, Andres Freund
I've opened an issue: https://github.com/giggls/mapnik-german-l10n/issues/40 I suspect that the number of executed regexp_replace calls is the culprit here. The cache of regexp.c seems to be limited to 32 entries which might be to low to keep all involved regexes cached. > Hi, > > On 2020-02-04 11:00:29 -0500, Tom Lane wrote: >> Andres Freund <andres@anarazel.de> writes: >> > Interesting! The no-children one clearly shows that a lot of the the >> > time is spent evaluating regular expressions (there's other regex >> > functions in the profile too): >> > 23.36% postgres postgres [.] subcolor >> >> Huh ... >> >> > I'm not aware of any relevant regular expression evaluation changes >> > between 11 and 12. Tom, does this trigger anything? >> >> (1) Nope, I'm not either; the last non-back-patched change in that >> code was c54159d44 in v10. >> >> (2) subcolor() is part of regex compilation, not execution, which makes >> one wonder why it's showing up at all. Maybe the regex cache in >> adt/regexp.c is overflowing and preventing useful caching? But >> that didn't change in v12 either. Are these test cases really >> 100% equivalent? I'm wondering if there are a few more "hot" >> regex patterns in the v12 data ... > > They are not 100% equivalent, but the part of the plan we see is very > similar rowcount wise. It's possible that the functions differ more > however, there are different postgis versions involved, and apparently > also an "osml10n" extension. > > >> (3) Where the heck is the regex use coming from at all? I don't >> see any regex operators in the plan. Maybe it's inside the >> plpgsql function? > > It definitely is. The stack shows at least two levels of plpgsql > functions. And Thomas has since confirmed that removing the functioncall > fixes the issue. > > Based on the name I think this is somewhere around this: > https://github.com/giggls/mapnik-german-l10n/blob/master/plpgsql/get_localized_name_from_tags.sql#L120 > The callgraph indicates that most of the cost comes from within > textregexreplace_noopt. > > Not clear why the cache isn't fixing this - there are no variables in > the regexp_replace calls as far as I can see. > > Greetings, > > Andres Freund -- Thomas Butz