Hi all,
This is patch for TODO item: /Improve ability to display optimizer
analysis using OPTIMIZER_DEBUG
/
As per as suggestion in the mailing list which is to replace current
mechanism of getting optimizer log via OPTIMIZER_DEBUG macro
to something more configurable (which doesn't require rebuilding
postgres from source code). This patch replaces /OPTIMIZER_DEBUG
/
by introducing a//GUC /show_optimizer_log /which can be configured on
and off to//display (or hide)//previously generated log from stdout to
postmaster's log.
Please check attached patch, any feedback is appreciated.
--
Regards,
Ankit Kumar Pandey
From 420f0ed81d233bf63a10104d1164726b138bce83 Mon Sep 17 00:00:00 2001
From: Ankit Kumar Pandey <itsanki...@gmail.com>
Date: Sun, 25 Dec 2022 21:26:32 +0530
Subject: [PATCH] Improve ability to display optimizer analysis using
OPTIMIZER_DEBUG
Currently optimizer logs are enabled as build flag. This patch adds a
GUC variable to enable or disable optimizer logs and thus does away with
build requirements.
---
src/backend/nodes/print.c | 107 ++++++++++++++
src/backend/optimizer/path/allpaths.c | 134 ++++++++++--------
src/backend/optimizer/plan/planner.c | 11 +-
src/backend/utils/misc/guc_tables.c | 11 ++
src/backend/utils/misc/postgresql.conf.sample | 1 +
src/include/nodes/print.h | 1 +
src/include/optimizer/optimizer.h | 1 +
src/include/optimizer/paths.h | 2 -
8 files changed, 200 insertions(+), 68 deletions(-)
diff --git a/src/backend/nodes/print.c b/src/backend/nodes/print.c
index a5c44adc6c..c33db27142 100644
--- a/src/backend/nodes/print.c
+++ b/src/backend/nodes/print.c
@@ -418,6 +418,113 @@ print_expr(const Node *expr, const List *rtable)
printf("unknown expr");
}
+
+
+/*
+ * format_expr
+ * stores an expression to given string for logging
+ */
+void
+format_expr(const Node *expr, const List *rtable, StringInfoData *str)
+{
+ if (expr == NULL)
+ {
+ appendStringInfo(str, "<>");
+ return;
+ }
+
+ if (IsA(expr, Var))
+ {
+ const Var *var = (const Var *) expr;
+ char *relname,
+ *attname;
+
+ switch (var->varno)
+ {
+ case INNER_VAR:
+ relname = "INNER";
+ attname = "?";
+ break;
+ case OUTER_VAR:
+ relname = "OUTER";
+ attname = "?";
+ break;
+ case INDEX_VAR:
+ relname = "INDEX";
+ attname = "?";
+ break;
+ default:
+ {
+ RangeTblEntry *rte;
+
+ Assert(var->varno > 0 &&
+ (int) var->varno <= list_length(rtable));
+ rte = rt_fetch(var->varno, rtable);
+ relname = rte->eref->aliasname;
+ attname = get_rte_attribute_name(rte, var->varattno);
+ }
+ break;
+ }
+ appendStringInfo(str, "%s.%s", relname, attname);
+ }
+ else if (IsA(expr, Const))
+ {
+ const Const *c = (const Const *) expr;
+ Oid typoutput;
+ bool typIsVarlena;
+ char *outputstr;
+
+ if (c->constisnull)
+ {
+ appendStringInfo(str, "NULL");
+ return;
+ }
+
+ getTypeOutputInfo(c->consttype,
+ &typoutput, &typIsVarlena);
+
+ outputstr = OidOutputFunctionCall(typoutput, c->constvalue);
+ appendStringInfo(str, "%s", outputstr);
+ pfree(outputstr);
+ }
+ else if (IsA(expr, OpExpr))
+ {
+ const OpExpr *e = (const OpExpr *) expr;
+ char *opname;
+
+ opname = get_opname(e->opno);
+ if (list_length(e->args) > 1)
+ {
+ print_expr(get_leftop((const Expr *) e), rtable);
+ appendStringInfo(str, " %s ", ((opname != NULL) ? opname : "(invalid operator)"));
+ print_expr(get_rightop((const Expr *) e), rtable);
+ }
+ else
+ {
+ appendStringInfo(str, "%s ", ((opname != NULL) ? opname : "(invalid operator)"));
+ print_expr(get_leftop((const Expr *) e), rtable);
+ }
+ }
+ else if (IsA(expr, FuncExpr))
+ {
+ const FuncExpr *e = (const FuncExpr *) expr;
+ char *funcname;
+ ListCell *l;
+
+ funcname = get_func_name(e->funcid);
+ appendStringInfo(str, "%s(", ((funcname != NULL) ? funcname : "(invalid function)"));
+ foreach(l, e->args)
+ {
+ print_expr(lfirst(l), rtable);
+ if (lnext(e->args, l))
+ appendStringInfo(str, ",");
+ }
+ appendStringInfo(str, ")");
+ }
+ else
+ appendStringInfo(str, "unknown expr");
+}
+
/*
* print_pathkeys -
* pathkeys list of PathKeys
diff --git a/src/backend/optimizer/path/allpaths.c b/src/backend/optimizer/path/allpaths.c
index 0cfa3a1d6c..38cbc365b3 100644
--- a/src/backend/optimizer/path/allpaths.c
+++ b/src/backend/optimizer/path/allpaths.c
@@ -28,9 +28,7 @@
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
#include "nodes/supportnodes.h"
-#ifdef OPTIMIZER_DEBUG
#include "nodes/print.h"
-#endif
#include "optimizer/appendinfo.h"
#include "optimizer/clauses.h"
#include "optimizer/cost.h"
@@ -65,6 +63,7 @@ bool enable_geqo = false; /* just in case GUC doesn't set it */
int geqo_threshold;
int min_parallel_table_scan_size;
int min_parallel_index_scan_size;
+bool show_optimizer_log = false;
/* Hook for plugins to get control in set_rel_pathlist() */
set_rel_pathlist_hook_type set_rel_pathlist_hook = NULL;
@@ -564,9 +563,12 @@ set_rel_pathlist(PlannerInfo *root, RelOptInfo *rel,
/* Now find the cheapest of the paths for this rel */
set_cheapest(rel);
-#ifdef OPTIMIZER_DEBUG
- debug_print_rel(root, rel);
-#endif
+ if (show_optimizer_log)
+ {
+ debug_print_rel(root, rel);
+ }
+
+
}
/*
@@ -3435,9 +3437,10 @@ standard_join_search(PlannerInfo *root, int levels_needed, List *initial_rels)
/* Find and save the cheapest paths for this rel */
set_cheapest(rel);
-#ifdef OPTIMIZER_DEBUG
- debug_print_rel(root, rel);
-#endif
+ if (show_optimizer_log)
+ {
+ debug_print_rel(root, rel);
+ }
}
}
@@ -4288,9 +4291,10 @@ generate_partitionwise_join_paths(PlannerInfo *root, RelOptInfo *rel)
if (IS_DUMMY_REL(child_rel))
continue;
-#ifdef OPTIMIZER_DEBUG
- debug_print_rel(root, child_rel);
-#endif
+ if (show_optimizer_log)
+ {
+ debug_print_rel(root, child_rel);
+ }
live_children = lappend(live_children, child_rel);
}
@@ -4312,10 +4316,9 @@ generate_partitionwise_join_paths(PlannerInfo *root, RelOptInfo *rel)
* DEBUG SUPPORT
*****************************************************************************/
-#ifdef OPTIMIZER_DEBUG
static void
-print_relids(PlannerInfo *root, Relids relids)
+print_relids(PlannerInfo *root, Relids relids, StringInfoData *str)
{
int x;
bool first = true;
@@ -4324,18 +4327,18 @@ print_relids(PlannerInfo *root, Relids relids)
while ((x = bms_next_member(relids, x)) >= 0)
{
if (!first)
- printf(" ");
+ appendStringInfo(str, " ");
if (x < root->simple_rel_array_size &&
root->simple_rte_array[x])
- printf("%s", root->simple_rte_array[x]->eref->aliasname);
+ appendStringInfo(str, "%s", root->simple_rte_array[x]->eref->aliasname);
else
- printf("%d", x);
+ appendStringInfo(str, "%d", x);
first = false;
}
}
static void
-print_restrictclauses(PlannerInfo *root, List *clauses)
+print_restrictclauses(PlannerInfo *root, List *clauses, StringInfoData *str)
{
ListCell *l;
@@ -4343,14 +4346,14 @@ print_restrictclauses(PlannerInfo *root, List *clauses)
{
RestrictInfo *c = lfirst(l);
- print_expr((Node *) c->clause, root->parse->rtable);
+ format_expr((Node *) c->clause, root->parse->rtable, str);
if (lnext(clauses, l))
- printf(", ");
+ appendStringInfoString(str, ", ");
}
}
static void
-print_path(PlannerInfo *root, Path *path, int indent)
+print_path(PlannerInfo *root, Path *path, int indent, StringInfoData *str)
{
const char *ptype;
bool join = false;
@@ -4522,29 +4525,29 @@ print_path(PlannerInfo *root, Path *path, int indent)
}
for (i = 0; i < indent; i++)
- printf("\t");
- printf("%s", ptype);
+ appendStringInfoString(str, "\t");
+ appendStringInfoString(str, ptype);
if (path->parent)
{
- printf("(");
- print_relids(root, path->parent->relids);
- printf(")");
+ appendStringInfoString(str, "(");
+ print_relids(root, path->parent->relids, str);
+ appendStringInfoString(str, ")");
}
if (path->param_info)
{
- printf(" required_outer (");
- print_relids(root, path->param_info->ppi_req_outer);
- printf(")");
+ appendStringInfoString(str, " required_outer (");
+ print_relids(root, path->param_info->ppi_req_outer, str);
+ appendStringInfoString(str, ")");
}
- printf(" rows=%.0f cost=%.2f..%.2f\n",
+ appendStringInfo(str, " rows=%.0f cost=%.2f..%.2f\n",
path->rows, path->startup_cost, path->total_cost);
if (path->pathkeys)
{
for (i = 0; i < indent; i++)
- printf("\t");
- printf(" pathkeys: ");
+ appendStringInfoString(str, "\t");
+ appendStringInfoString(str, " pathkeys: ");
print_pathkeys(path->pathkeys, root->parse->rtable);
}
@@ -4553,75 +4556,86 @@ print_path(PlannerInfo *root, Path *path, int indent)
JoinPath *jp = (JoinPath *) path;
for (i = 0; i < indent; i++)
- printf("\t");
- printf(" clauses: ");
- print_restrictclauses(root, jp->joinrestrictinfo);
- printf("\n");
+ appendStringInfoString(str, "\t");
+ appendStringInfoString(str, " clauses: ");
+ print_restrictclauses(root, jp->joinrestrictinfo, str);
+ appendStringInfoString(str, "\n");
if (IsA(path, MergePath))
{
MergePath *mp = (MergePath *) path;
for (i = 0; i < indent; i++)
- printf("\t");
- printf(" sortouter=%d sortinner=%d materializeinner=%d\n",
+ appendStringInfoString(str, "\t");
+ appendStringInfo(str, " sortouter=%d sortinner=%d materializeinner=%d\n",
((mp->outersortkeys) ? 1 : 0),
((mp->innersortkeys) ? 1 : 0),
((mp->materialize_inner) ? 1 : 0));
}
- print_path(root, jp->outerjoinpath, indent + 1);
- print_path(root, jp->innerjoinpath, indent + 1);
+ print_path(root, jp->outerjoinpath, indent + 1, str);
+ print_path(root, jp->innerjoinpath, indent + 1, str);
}
if (subpath)
- print_path(root, subpath, indent + 1);
+ print_path(root, subpath, indent + 1, str);
+
}
void
debug_print_rel(PlannerInfo *root, RelOptInfo *rel)
{
ListCell *l;
+ StringInfoData str;
+ initStringInfo(&str);
- printf("RELOPTINFO (");
- print_relids(root, rel->relids);
- printf("): rows=%.0f width=%d\n", rel->rows, rel->reltarget->width);
+ appendStringInfo(&str, "RELOPTINFO (");
+ print_relids(root, rel->relids, &str);
+ appendStringInfo(&str, "): rows=%.0f width=%d\n", rel->rows, rel->reltarget->width);
if (rel->baserestrictinfo)
{
- printf("\tbaserestrictinfo: ");
- print_restrictclauses(root, rel->baserestrictinfo);
- printf("\n");
+ appendStringInfo(&str, "\tbaserestrictinfo: ");
+ print_restrictclauses(root, rel->baserestrictinfo, &str);
+ appendStringInfo(&str, "\n");
}
if (rel->joininfo)
{
- printf("\tjoininfo: ");
- print_restrictclauses(root, rel->joininfo);
- printf("\n");
+ appendStringInfo(&str, "\tjoininfo: ");
+ print_restrictclauses(root, rel->joininfo, &str);
+ appendStringInfo(&str, "\n");
}
- printf("\tpath list:\n");
+ appendStringInfo(&str, "\tpath list:\n");
foreach(l, rel->pathlist)
- print_path(root, lfirst(l), 1);
+ print_path(root, lfirst(l), 1, &str);
if (rel->cheapest_parameterized_paths)
{
- printf("\n\tcheapest parameterized paths:\n");
+ appendStringInfo(&str, "\n\tcheapest parameterized paths:\n");
foreach(l, rel->cheapest_parameterized_paths)
- print_path(root, lfirst(l), 1);
+ print_path(root, lfirst(l), 1, &str);
}
if (rel->cheapest_startup_path)
{
- printf("\n\tcheapest startup path:\n");
- print_path(root, rel->cheapest_startup_path, 1);
+ appendStringInfo(&str, "\n\tcheapest startup path:\n");
+ print_path(root, rel->cheapest_startup_path, 1, &str);
}
if (rel->cheapest_total_path)
{
- printf("\n\tcheapest total path:\n");
- print_path(root, rel->cheapest_total_path, 1);
+ appendStringInfo(&str, "\n\tcheapest total path:\n");
+ print_path(root, rel->cheapest_total_path, 1, &str);
}
- printf("\n");
- fflush(stdout);
+
+ /* remove trailing newline */
+ if (str.data[str.len - 1] == '\n')
+ str.data[--str.len] = '\0';
+
+ ereport(LOG,
+ (errmsg_internal("Optimizer statistics"),
+ errdetail_internal("%s", str.data)));
+
+ pfree(str.data);
}
-#endif /* OPTIMIZER_DEBUG */
+ /* OPTIMIZER_DEBUG */
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index 8a41e1e6d3..e8e897ea8f 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -38,9 +38,7 @@
#include "miscadmin.h"
#include "nodes/makefuncs.h"
#include "nodes/nodeFuncs.h"
-#ifdef OPTIMIZER_DEBUG
#include "nodes/print.h"
-#endif
#include "nodes/supportnodes.h"
#include "optimizer/appendinfo.h"
#include "optimizer/clauses.h"
@@ -1143,10 +1141,11 @@ preprocess_expression(PlannerInfo *root, Node *expr, int kind)
{
expr = (Node *) canonicalize_qual((Expr *) expr, false);
-#ifdef OPTIMIZER_DEBUG
- printf("After canonicalize_qual()\n");
- pprint(expr);
-#endif
+ if (show_optimizer_log)
+ {
+ elog_node_display(LOG, "Result after canonicalize_qual", expr, true);
+ }
+
}
/*
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index 436afe1d21..724e457acb 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -1007,6 +1007,17 @@ struct config_bool ConfigureNamesBool[] =
true,
NULL, NULL, NULL
},
+
+ {
+ {"show_optimizer_log", PGC_USERSET, QUERY_TUNING_OTHER,
+ gettext_noop("Shows debugging logs from optimizer"),
+ NULL,
+ GUC_EXPLAIN
+ },
+ &show_optimizer_log,
+ false,
+ NULL, NULL, NULL
+ },
{
/* Not for general use --- used by SET SESSION AUTHORIZATION */
{"is_superuser", PGC_INTERNAL, UNGROUPED,
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 5afdeb04de..eb3fbfd462 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -433,6 +433,7 @@
#plan_cache_mode = auto # auto, force_generic_plan or
# force_custom_plan
#recursive_worktable_factor = 10.0 # range 0.001-1000000
+#show_optimizer_log = off # on to show debug info from optimizer
#------------------------------------------------------------------------------
diff --git a/src/include/nodes/print.h b/src/include/nodes/print.h
index be5e2287f3..5d7bb97f44 100644
--- a/src/include/nodes/print.h
+++ b/src/include/nodes/print.h
@@ -27,6 +27,7 @@ extern char *format_node_dump(const char *dump);
extern char *pretty_format_node_dump(const char *dump);
extern void print_rt(const List *rtable);
extern void print_expr(const Node *expr, const List *rtable);
+extern void format_expr(const Node *expr, const List *rtable, StringInfoData *str);
extern void print_pathkeys(const List *pathkeys, const List *rtable);
extern void print_tl(const List *tlist, const List *rtable);
extern void print_slot(TupleTableSlot *slot);
diff --git a/src/include/optimizer/optimizer.h b/src/include/optimizer/optimizer.h
index 409005bae9..a2cf9eb22e 100644
--- a/src/include/optimizer/optimizer.h
+++ b/src/include/optimizer/optimizer.h
@@ -88,6 +88,7 @@ extern PGDLLIMPORT double parallel_tuple_cost;
extern PGDLLIMPORT double parallel_setup_cost;
extern PGDLLIMPORT double recursive_worktable_factor;
extern PGDLLIMPORT int effective_cache_size;
+extern PGDLLIMPORT bool show_optimizer_log;
extern double clamp_row_est(double nrows);
extern long clamp_cardinality_to_long(Cardinality x);
diff --git a/src/include/optimizer/paths.h b/src/include/optimizer/paths.h
index 41f765d342..7802f00a5b 100644
--- a/src/include/optimizer/paths.h
+++ b/src/include/optimizer/paths.h
@@ -63,9 +63,7 @@ extern void create_partial_bitmap_paths(PlannerInfo *root, RelOptInfo *rel,
extern void generate_partitionwise_join_paths(PlannerInfo *root,
RelOptInfo *rel);
-#ifdef OPTIMIZER_DEBUG
extern void debug_print_rel(PlannerInfo *root, RelOptInfo *rel);
-#endif
/*
* indxpath.c
--
2.37.2
