Thread: BUG #16241: Degraded hash join performance

BUG #16241: Degraded hash join performance

From
PG Bug reporting form
Date:
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.


Re: BUG #16241: Degraded hash join performance

From
Andres Freund
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Thomas Butz
Date:
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
Attachment

Re: BUG #16241: Degraded hash join performance

From
Andres Freund
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Thomas Butz
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Andres Freund
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Tom Lane
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Andres Freund
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Andres Freund
Date:
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



Re: BUG #16241: Degraded hash join performance

From
Thomas Butz
Date:
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