Proposal: add a debug message about using geqo
Hi,
During query tuning, users may want to check if GEQO is used or not
to generate a plan. However, users can not know it by simply counting
the number of tables that appear in SQL. I know we can know it by
enabling GEQO_DEBUG flag, but it needs recompiling, so I think it is
inconvenient.
So, I would like to propose to add a debug level message that shows
when PostgreSQL use GEQO. That enables users to easily see it by
just changing log_min_messages.
Use cases are as follows:
- When investigating about the result of planning, user can determine
whether the plan is chosen by the standard planning or GEQO.
- When tuning PostgreSQL, user can determine the suitable value of
geqo_threshold parameter.
Best regards.
--
KAWAMOTO Masaya <kawamoto@sraoss.co.jp>
SRA OSS, Inc. Japan
Attachments:
debugmessage_about_geqo.patchapplication/octet-stream; name=debugmessage_about_geqo.patchDownload
diff --git a/src/backend/optimizer/path/allpaths.c b/src/backend/optimizer/path/allpaths.c
index d84f66a81b..fffcead927 100644
--- a/src/backend/optimizer/path/allpaths.c
+++ b/src/backend/optimizer/path/allpaths.c
@@ -3290,7 +3290,11 @@ make_rel_from_joinlist(PlannerInfo *root, List *joinlist)
if (join_search_hook)
return (*join_search_hook) (root, levels_needed, initial_rels);
else if (enable_geqo && levels_needed >= geqo_threshold)
+ {
+ elog(DEBUG1, "the number of join nodes %d is larger than geqo_threshold %d",
+ levels_needed, geqo_threshold);
return geqo(root, levels_needed, initial_rels);
+ }
else
return standard_join_search(root, levels_needed, initial_rels);
}
If we add that information to EXPLAIN output, the user won't need
access to server logs.
May be we need it in both the places.
On Tue, May 10, 2022 at 6:35 AM KAWAMOTO Masaya <kawamoto@sraoss.co.jp> wrote:
Hi,
During query tuning, users may want to check if GEQO is used or not
to generate a plan. However, users can not know it by simply counting
the number of tables that appear in SQL. I know we can know it by
enabling GEQO_DEBUG flag, but it needs recompiling, so I think it is
inconvenient.So, I would like to propose to add a debug level message that shows
when PostgreSQL use GEQO. That enables users to easily see it by
just changing log_min_messages.Use cases are as follows:
- When investigating about the result of planning, user can determine
whether the plan is chosen by the standard planning or GEQO.- When tuning PostgreSQL, user can determine the suitable value of
geqo_threshold parameter.Best regards.
--
KAWAMOTO Masaya <kawamoto@sraoss.co.jp>
SRA OSS, Inc. Japan
--
Best Wishes,
Ashutosh Bapat
On Tue, 10 May 2022 18:49:54 +0530
Ashutosh Bapat <ashutosh.bapat.oss@gmail.com> wrote:
If we add that information to EXPLAIN output, the user won't need
access to server logs.May be we need it in both the places.
That sounds a nice idea. But I don't think that postgres shows in the
EXPLAIN output why the plan is selected. Would it be appropriate to
show that GEQO is used in EXPLAIN output?
As a test, I created a patch that add information about GEQO to
EXPLAIN output by the GEQO option. The output example is as follows.
What do you think about the location and content of information about GEQO?
postgres=# explain (geqo) select o.id, o.date, c.name as customer_name, bar.amount as total_amount
from orders o join customer c on o.customer_id = c.id
join (select foo.id as id, sum(foo.amount) as amount
from (select od.order_id as id, p.name as name, od.quantity as quantity, (p.price * od.quantity) as amount
from order_detail od join product p on od.product_id = p.id
) as foo
group by id) as bar on o.id = bar.id ;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Hash Join (cost=118.75..155.04 rows=200 width=48)
Hash Cond: (o.customer_id = c.id)
-> Hash Join (cost=94.58..130.34 rows=200 width=20)
Hash Cond: (o.id = bar.id)
-> Seq Scan on orders o (cost=0.00..30.40 rows=2040 width=12)
-> Hash (cost=92.08..92.08 rows=200 width=12)
-> Subquery Scan on bar (cost=88.08..92.08 rows=200 width=12)
-> HashAggregate (cost=88.08..90.08 rows=200 width=12)
Group Key: od.order_id
-> Hash Join (cost=37.00..72.78 rows=2040 width=12)
Hash Cond: (od.product_id = p.id)
-> Seq Scan on order_detail od (cost=0.00..30.40 rows=2040 width=12)
-> Hash (cost=22.00..22.00 rows=1200 width=8)
-> Seq Scan on product p (cost=0.00..22.00 rows=1200 width=8)
-> Hash (cost=16.30..16.30 rows=630 width=36)
-> Seq Scan on customer c (cost=0.00..16.30 rows=630 width=36)
GeqoDetails: GEQO: used, geqo_threshold: 3, Max join nodes: 3
(17 rows)
postgres=# set geqo_threshold to 16;
SET
postgres=# explain (geqo) select ... ;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Hash Join (cost=118.75..155.04 rows=200 width=48)
Hash Cond: (o.customer_id = c.id)
-> Hash Join (cost=94.58..130.34 rows=200 width=20)
Hash Cond: (o.id = bar.id)
-> Seq Scan on orders o (cost=0.00..30.40 rows=2040 width=12)
-> Hash (cost=92.08..92.08 rows=200 width=12)
-> Subquery Scan on bar (cost=88.08..92.08 rows=200 width=12)
-> HashAggregate (cost=88.08..90.08 rows=200 width=12)
Group Key: od.order_id
-> Hash Join (cost=37.00..72.78 rows=2040 width=12)
Hash Cond: (od.product_id = p.id)
-> Seq Scan on order_detail od (cost=0.00..30.40 rows=2040 width=12)
-> Hash (cost=22.00..22.00 rows=1200 width=8)
-> Seq Scan on product p (cost=0.00..22.00 rows=1200 width=8)
-> Hash (cost=16.30..16.30 rows=630 width=36)
-> Seq Scan on customer c (cost=0.00..16.30 rows=630 width=36)
GeqoDetails: GEQO: not used, geqo_threshold: 16, Max join nodes: 3
(17 rows)
postgres=# explain (analyze, settings, geqo) select ...;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
--------------------------
Hash Join (cost=118.75..155.04 rows=200 width=48) (actual time=0.104..0.113 rows=3 loops=1)
Hash Cond: (o.customer_id = c.id)
-> Hash Join (cost=94.58..130.34 rows=200 width=20) (actual time=0.042..0.048 rows=3 loops=1)
Hash Cond: (o.id = bar.id)
-> Seq Scan on orders o (cost=0.00..30.40 rows=2040 width=12) (actual time=0.003..0.005 rows=3 loops=1)
-> Hash (cost=92.08..92.08 rows=200 width=12) (actual time=0.034..0.037 rows=3 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
-> Subquery Scan on bar (cost=88.08..92.08 rows=200 width=12) (actual time=0.031..0.035 rows=3 loops=1)
-> HashAggregate (cost=88.08..90.08 rows=200 width=12) (actual time=0.030..0.033 rows=3 loops=1)
Group Key: od.order_id
Batches: 1 Memory Usage: 56kB
-> Hash Join (cost=37.00..72.78 rows=2040 width=12) (actual time=0.016..0.023 rows=7 loops=
1)
Hash Cond: (od.product_id = p.id)
-> Seq Scan on order_detail od (cost=0.00..30.40 rows=2040 width=12) (actual time=0.0
03..0.004 rows=7 loops=1)
-> Hash (cost=22.00..22.00 rows=1200 width=8) (actual time=0.007..0.008 rows=4 loops=
1)
Buckets: 2048 Batches: 1 Memory Usage: 17kB
-> Seq Scan on product p (cost=0.00..22.00 rows=1200 width=8) (actual time=0.00
4..0.006 rows=4 loops=1)
-> Hash (cost=16.30..16.30 rows=630 width=36) (actual time=0.019..0.020 rows=3 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
-> Seq Scan on customer c (cost=0.00..16.30 rows=630 width=36) (actual time=0.014..0.016 rows=3 loops=1)
Settings: geqo_threshold = '16'
GeqoDetails: GEQO: not used, geqo_threshold: 16, Max join nodes: 3
Planning Time: 0.516 ms
Execution Time: 0.190 ms
(24 rows)
On Tue, May 10, 2022 at 6:35 AM KAWAMOTO Masaya <kawamoto@sraoss.co.jp> wrote:
Hi,
During query tuning, users may want to check if GEQO is used or not
to generate a plan. However, users can not know it by simply counting
the number of tables that appear in SQL. I know we can know it by
enabling GEQO_DEBUG flag, but it needs recompiling, so I think it is
inconvenient.So, I would like to propose to add a debug level message that shows
when PostgreSQL use GEQO. That enables users to easily see it by
just changing log_min_messages.Use cases are as follows:
- When investigating about the result of planning, user can determine
whether the plan is chosen by the standard planning or GEQO.- When tuning PostgreSQL, user can determine the suitable value of
geqo_threshold parameter.Best regards.
--
KAWAMOTO Masaya <kawamoto@sraoss.co.jp>
SRA OSS, Inc. Japan--
Best Wishes,
Ashutosh Bapat
--
KAWAMOTO Masaya <kawamoto@sraoss.co.jp>
SRA OSS, Inc. Japan
Attachments:
add_geqo_info_to_explain.patchapplication/octet-stream; name=add_geqo_info_to_explain.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index d2a2479822..27109311f7 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -24,6 +24,7 @@
#include "nodes/extensible.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
+#include "optimizer/paths.h"
#include "parser/analyze.h"
#include "parser/parsetree.h"
#include "rewrite/rewriteHandler.h"
@@ -153,7 +154,7 @@ static void ExplainIndentText(ExplainState *es);
static void ExplainJSONLineEnding(ExplainState *es);
static void ExplainYAMLLineStarting(ExplainState *es);
static void escape_yaml(StringInfo buf, const char *str);
-
+static void ExplainPrintGeqoDetails(ExplainState *es, QueryDesc *queryDesc);
/*
@@ -190,6 +191,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
es->wal = defGetBoolean(opt);
else if (strcmp(opt->defname, "settings") == 0)
es->settings = defGetBoolean(opt);
+ else if (strcmp(opt->defname, "geqo") == 0)
+ es->geqo = defGetBoolean(opt);
else if (strcmp(opt->defname, "timing") == 0)
{
timing_set = true;
@@ -620,6 +623,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
plannedstmt->queryId, es);
}
+ /* Print info about details option */
+ if (es->geqo)
+ ExplainPrintGeqoDetails(es, queryDesc);
+
/* Show buffer usage in planning */
if (bufusage)
{
@@ -742,6 +749,50 @@ ExplainPrintSettings(ExplainState *es)
}
}
+void
+ExplainPrintGeqoDetails(ExplainState *es, QueryDesc *queryDesc)
+{
+ if (!enable_geqo)
+ return;
+
+ if (es->format != EXPLAIN_FORMAT_TEXT)
+ {
+ ExplainOpenGroup("GeqoDetails", "GeqoDetails", true, es);
+
+ if (queryDesc->plannedstmt->geqoFlag)
+ ExplainPropertyText("GEQO", "used", es);
+ else
+ ExplainPropertyText("GEQO", "not used", es);
+ ExplainPropertyInteger("geqo_threshold", NULL, geqo_threshold, es);
+
+ ExplainPropertyInteger("Max join nodes", NULL,
+ queryDesc->plannedstmt->max_nodes_in_join_search, es);
+
+ ExplainCloseGroup("GeqoDetails", "GeqoDetails", true, es);
+ }
+ else
+ {
+ StringInfoData str;
+
+ initStringInfo(&str);
+
+ if (queryDesc->plannedstmt->geqoFlag)
+ appendStringInfo(&str, "GEQO: used");
+ else
+ appendStringInfo(&str, "GEQO: not used");
+
+ appendStringInfoString(&str, ", ");
+ appendStringInfo(&str, "geqo_threshold: %d", geqo_threshold);
+
+ appendStringInfoString(&str, ", ");
+ appendStringInfo(&str, "Max join nodes: %d",
+ queryDesc->plannedstmt->max_nodes_in_join_search);
+
+ ExplainPropertyText("GeqoDetails", str.data, es);
+ }
+
+}
+
/*
* ExplainPrintPlan -
* convert a QueryDesc's plan tree to text and append it to es->str
diff --git a/src/backend/optimizer/path/allpaths.c b/src/backend/optimizer/path/allpaths.c
index d84f66a81b..417a16a97e 100644
--- a/src/backend/optimizer/path/allpaths.c
+++ b/src/backend/optimizer/path/allpaths.c
@@ -3237,6 +3237,9 @@ make_rel_from_joinlist(PlannerInfo *root, List *joinlist)
if (levels_needed <= 0)
return NULL; /* nothing to do? */
+ if (root->max_joinnodes < levels_needed)
+ root->max_joinnodes = levels_needed;
+
/*
* Construct a list of rels corresponding to the child joinlist nodes.
* This may contain both base rels and rels constructed according to
@@ -3290,7 +3293,12 @@ make_rel_from_joinlist(PlannerInfo *root, List *joinlist)
if (join_search_hook)
return (*join_search_hook) (root, levels_needed, initial_rels);
else if (enable_geqo && levels_needed >= geqo_threshold)
+ {
+ elog(DEBUG1, "the number of join nodes %d is larger than geqo_threshold %d",
+ levels_needed, geqo_threshold);
+ root->geqo_used = true;
return geqo(root, levels_needed, initial_rels);
+ }
else
return standard_join_search(root, levels_needed, initial_rels);
}
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index 9a4accb4d9..3c061e52d6 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -532,6 +532,15 @@ standard_planner(Query *parse, const char *query_string, int cursorOptions,
result->stmt_location = parse->stmt_location;
result->stmt_len = parse->stmt_len;
+ result->geqoFlag = false;
+ result->max_nodes_in_join_search = 0;
+ if (enable_geqo)
+ {
+ result->geqoFlag = root->geqo_used;
+ result->max_nodes_in_join_search = root->max_joinnodes;
+ }
+
+
result->jitFlags = PGJIT_NONE;
if (jit_enabled && jit_above_cost >= 0 &&
top_plan->total_cost > jit_above_cost)
@@ -641,6 +650,8 @@ subquery_planner(PlannerGlobal *glob, Query *parse,
root->wt_param_id = -1;
root->non_recursive_path = NULL;
root->partColsUpdated = false;
+ root->geqo_used = false;
+ root->max_joinnodes = 0;
/*
* If there is a WITH list, process each WITH query and either convert it
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 666977fb1f..f3e4ec95ee 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -46,6 +46,7 @@ typedef struct ExplainState
bool timing; /* print detailed node timing */
bool summary; /* print total planning and execution timing */
bool settings; /* print modified settings */
+ bool geqo; /* print geqo details */
ExplainFormat format; /* output format */
/* state for output formatting --- not reset for each new plan tree */
int indent; /* current indentation level */
diff --git a/src/include/nodes/pathnodes.h b/src/include/nodes/pathnodes.h
index 244d1e1197..6ecf3954c5 100644
--- a/src/include/nodes/pathnodes.h
+++ b/src/include/nodes/pathnodes.h
@@ -378,6 +378,10 @@ struct PlannerInfo
/* Does this query modify any partition key columns? */
bool partColsUpdated;
+
+ /* Information about geqo */
+ bool geqo_used;
+ int max_joinnodes;
};
diff --git a/src/include/nodes/plannodes.h b/src/include/nodes/plannodes.h
index e43e360d9b..89fd51d931 100644
--- a/src/include/nodes/plannodes.h
+++ b/src/include/nodes/plannodes.h
@@ -89,6 +89,9 @@ typedef struct PlannedStmt
/* statement location in source string (copied from Query) */
int stmt_location; /* start location, or -1 if unknown */
int stmt_len; /* length in bytes; 0 means "rest of string" */
+
+ bool geqoFlag; /* if true, geqo is used */
+ int max_nodes_in_join_search; /* the number of join nodes when geqo is used */
} PlannedStmt;
/* macro for fetching the Plan associated with a SubPlan node */
On Wed, Jun 1, 2022 at 11:09 PM KAWAMOTO Masaya <kawamoto@sraoss.co.jp> wrote:
That sounds a nice idea. But I don't think that postgres shows in the
EXPLAIN output why the plan is selected. Would it be appropriate to
show that GEQO is used in EXPLAIN output?
I'm reminded of Greenplum's "Optimizer" line in its EXPLAIN output
[1]: https://docs.vmware.com/en/VMware-Tanzu-Greenplum/6/greenplum-database/GUID-ref_guide-sql_commands-EXPLAIN.html#examples-4
As a test, I created a patch that add information about GEQO to
EXPLAIN output by the GEQO option. The output example is as follows.
What do you think about the location and content of information about GEQO?
I am a little surprised to see GeqoDetails being printed for a plan
that didn't use GEQO, but again that's probably because I'm used to
GPDB's Optimizer output. And I don't have a lot of personal experience
using alternative optimizers.
One way to think about it might be, if we had ten alternatives, would
we want a line for each showing why it wasn't selected, or just one
line showing the optimizer that was selected? The latter is more
compact but doesn't help you debug why something else wasn't chosen, I
suppose...
--Jacob
On Fri, Jul 22, 2022 at 1:20 PM Jacob Champion <jchampion@timescale.com>
wrote:
On Wed, Jun 1, 2022 at 11:09 PM KAWAMOTO Masaya <kawamoto@sraoss.co.jp>
wrote:That sounds a nice idea. But I don't think that postgres shows in the
EXPLAIN output why the plan is selected. Would it be appropriate to
show that GEQO is used in EXPLAIN output?I'm reminded of Greenplum's "Optimizer" line in its EXPLAIN output
[1], so from that perspective I think it's intuitive.As a test, I created a patch that add information about GEQO to
EXPLAIN output by the GEQO option. The output example is as follows.
What do you think about the location and content of information aboutGEQO?
I am a little surprised to see GeqoDetails being printed for a plan
that didn't use GEQO, but again that's probably because I'm used to
GPDB's Optimizer output. And I don't have a lot of personal experience
using alternative optimizers.
I agree this should be part of explain output.
I would not print the current value of geqo_threshold and leave setting
display the exclusive purview of the settings option.
The presentation of only a single geqo result seems incorrect given that
multiple trees can exist. In the first example below the full outer join
causes 3 relations to be seen as a single relation at the top level (hence
max join nodes = 4) while in the inner join case we see all 6 join nodes.
There should be two outputs of GEQO in the first explain, one with join
nodes of 3 and the existing one with 4.
I also don't see the point of labelling them "max"; "join nodes" seems
sufficient.
While it can probably be figured out from the rest of the plan, listing the
names of the join nodes may be useful (and give join nodes some company).
David J.
postgres=# explain (verbose, geqo) with gs2 (v2) as materialized ( select *
from generate_series(1,1) ) select * from gs2 as gs4 full outer join
(select gs2a.v2 from gs2 as gs2a, gs2 as gs2b) as gs5 using (v2),
generate_series(1, 1) as gs (v1) cross join gs2 as gs3 where v1 IN (select
v2 from gs2);
QUERY PLAN
----------------------------------------------------------------------------------------------------
Nested Loop (cost=0.07..0.21 rows=1 width=12)
Output: COALESCE(gs4.v2, gs2a.v2), gs.v1, gs3.v2
CTE gs2
-> Function Scan on pg_catalog.generate_series (cost=0.00..0.01
rows=1 width=4)
Output: generate_series.generate_series
Function Call: generate_series(1, 1)
-> Nested Loop (cost=0.06..0.16 rows=1 width=12)
Output: gs.v1, gs4.v2, gs2a.v2
-> Nested Loop (cost=0.02..0.06 rows=1 width=4)
Output: gs.v1
Join Filter: (gs.v1 = gs2.v2)
-> Function Scan on pg_catalog.generate_series gs
(cost=0.00..0.01 rows=1 width=4)
Output: gs.v1
Function Call: generate_series(1, 1)
-> HashAggregate (cost=0.02..0.03 rows=1 width=4)
Output: gs2.v2
Group Key: gs2.v2
-> CTE Scan on gs2 (cost=0.00..0.02 rows=1 width=4)
Output: gs2.v2
-> Hash Full Join (cost=0.03..0.10 rows=1 width=8)
Output: gs4.v2, gs2a.v2
Hash Cond: (gs2a.v2 = gs4.v2)
-> Nested Loop (cost=0.00..0.05 rows=1 width=4)
Output: gs2a.v2
-> CTE Scan on gs2 gs2b (cost=0.00..0.02 rows=1
width=0)
Output: gs2b.v2
-> CTE Scan on gs2 gs2a (cost=0.00..0.02 rows=1
width=4)
Output: gs2a.v2
-> Hash (cost=0.02..0.02 rows=1 width=4)
Output: gs4.v2
-> CTE Scan on gs2 gs4 (cost=0.00..0.02 rows=1
width=4)
Output: gs4.v2
-> CTE Scan on gs2 gs3 (cost=0.00..0.02 rows=1 width=4)
Output: gs3.v2
GeqoDetails: GEQO: used, geqo_threshold: 2, Max join nodes: 4
(35 rows)
postgres=# explain (verbose, geqo) with gs2 (v2) as materialized ( select *
from generate_series(1,1) ) select * from gs2 as gs4 join (select gs2a.v2
from gs2 as gs2a, gs2 as gs2b) as gs5 using (v2), generate_series(1, 1) as
gs (v1) cross join gs2 as gs3 where v1 IN (select v2 from gs2);
QUERY PLAN
----------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.02..0.18 rows=1 width=12)
Output: gs4.v2, gs.v1, gs3.v2
CTE gs2
-> Function Scan on pg_catalog.generate_series (cost=0.00..0.01
rows=1 width=4)
Output: generate_series.generate_series
Function Call: generate_series(1, 1)
-> Nested Loop (cost=0.00..0.14 rows=1 width=12)
Output: gs.v1, gs4.v2, gs3.v2
-> Nested Loop (cost=0.00..0.11 rows=1 width=8)
Output: gs.v1, gs4.v2
-> Nested Loop Semi Join (cost=0.00..0.04 rows=1 width=4)
Output: gs.v1
Join Filter: (gs.v1 = gs2.v2)
-> Function Scan on pg_catalog.generate_series gs
(cost=0.00..0.01 rows=1 width=4)
Output: gs.v1
Function Call: generate_series(1, 1)
-> CTE Scan on gs2 (cost=0.00..0.02 rows=1 width=4)
Output: gs2.v2
-> Nested Loop (cost=0.00..0.05 rows=1 width=4)
Output: gs4.v2
Join Filter: (gs2a.v2 = gs4.v2)
-> CTE Scan on gs2 gs2a (cost=0.00..0.02 rows=1
width=4)
Output: gs2a.v2
-> CTE Scan on gs2 gs4 (cost=0.00..0.02 rows=1
width=4)
Output: gs4.v2
-> CTE Scan on gs2 gs3 (cost=0.00..0.02 rows=1 width=4)
Output: gs3.v2
-> CTE Scan on gs2 gs2b (cost=0.00..0.02 rows=1 width=0)
Output: gs2b.v2
GeqoDetails: GEQO: used, geqo_threshold: 2, Max join nodes: 6
(30 rows)