BUG #16241: Degraded hash join performance

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-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

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 i wasn't aware that i might have to check the "Output" section of a node to find potential performance problems. How do you find 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) but i wasn't aware that i might have to check the "Output" section of a node to find potential performance problems. How do you 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

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