Add planning and execution times to babelfish_statistics profile (bab…

…elfish-for-postgresql#717) This commit changes babelfish_statistics profile in two ways. First it enables the summary and timing gucs by default to match postgres. Second it implements the summary timings. This is done through adding variables in estate that are set when the appropriate hook functions are called. For planning, a new hook was introduced as many babelfish code paths will invoke the planner from a SPI_exec function. This makes mirroring postgres which during its explain analyze flow only calls through to the pg_plan_query function. By adding this hook, we are able to time standard_planner which is the majority of the work done in pg_plan_query. For execution time, we can simply time the existing executor hooks. The closing calculation is located in append_explain_info as to match postgres, we must only stop the timer after we have written out the rest of the metrics. Task: BABEL-3338 Signed-off-by: Justin Jossick jusjosj@amazon.com
Bit-Quill · Oct 31, 2022 · d4c1860 · d4c1860
1 parent a84ecc1
commit d4c1860
Show file tree

Hide file tree

Showing 9 changed files with 134 additions and 7 deletions.
diff --git a/contrib/babelfishpg_tsql/src/guc.c b/contrib/babelfishpg_tsql/src/guc.c
@@ -980,7 +980,7 @@ define_custom_variables(void)
 				 gettext_noop("Include actual startup time and time spent in each node in the output"),
 				 NULL,
 				 &pltsql_explain_timing,
-				 false,
+				 true,
 				 PGC_USERSET,
 				 GUC_NOT_IN_SAMPLE | GUC_DISALLOW_IN_FILE | GUC_DISALLOW_IN_AUTO_FILE,
 				 NULL, NULL, NULL);
@@ -989,7 +989,7 @@ define_custom_variables(void)
 				 gettext_noop("Include summary information (e.g., totaled timing information) after the query plan"),
 				 NULL,
 				 &pltsql_explain_summary,
-				 false,
+				 true,
 				 PGC_USERSET,
 				 GUC_NOT_IN_SAMPLE | GUC_DISALLOW_IN_FILE | GUC_DISALLOW_IN_AUTO_FILE,
 				 NULL, NULL, NULL);

diff --git a/contrib/babelfishpg_tsql/src/hooks.c b/contrib/babelfishpg_tsql/src/hooks.c
@@ -26,6 +26,7 @@
 #include "nodes/nodeFuncs.h"
 #include "optimizer/clauses.h"
 #include "optimizer/optimizer.h"
+#include "optimizer/planner.h"
 #include "parser/analyze.h"
 #include "parser/parse_clause.h"
 #include "parser/parse_coerce.h"
@@ -111,6 +112,7 @@ static void pltsql_drop_func_default_positions(Oid objectId);
  *****************************************/
 static void pltsql_report_proc_not_found_error(List *names, List *argnames, int nargs, ParseState *pstate, int location, bool proc_call);
 extern PLtsql_execstate *get_outermost_tsql_estate(int *nestlevel);
+extern PLtsql_execstate *get_current_tsql_estate();
 static void pltsql_store_view_definition(const char *queryString, ObjectAddress address);
 static void pltsql_drop_view_definition(Oid objectId);
 static void preserve_view_constraints_from_base_table(ColumnDef  *col, Oid tableOid, AttrNumber colId);
@@ -146,6 +148,11 @@ static void bbf_object_access_hook(ObjectAccessType access, Oid classId, Oid obj
 static void revoke_func_permission_from_public(Oid objectId);
 static char *gen_func_arg_list(Oid objectId);
 
+/*****************************************
+ * 			Planner Hook
+ *****************************************/
+static PlannedStmt * pltsql_planner_hook(Query *parse, const char *query_string, int cursorOptions, ParamListInfo boundParams);
+
 /* Save hook values in case of unload */
 static core_yylex_hook_type prev_core_yylex_hook = NULL;
 static pre_transform_returning_hook_type prev_pre_transform_returning_hook = NULL;
@@ -175,6 +182,7 @@ static detect_numeric_overflow_hook_type prev_detect_numeric_overflow_hook = NUL
 static match_pltsql_func_call_hook_type prev_match_pltsql_func_call_hook = NULL;
 static insert_pltsql_function_defaults_hook_type prev_insert_pltsql_function_defaults_hook = NULL;
 static print_pltsql_function_arguments_hook_type prev_print_pltsql_function_arguments_hook = NULL;
+static planner_hook_type prev_planner_hook = NULL;
 /*****************************************
  * 			Install / Uninstall
  *****************************************/
@@ -278,6 +286,9 @@ InstallExtendedHooks(void)
 
 	prev_print_pltsql_function_arguments_hook = print_pltsql_function_arguments_hook;
 	print_pltsql_function_arguments_hook = print_pltsql_function_arguments;
+
+	prev_planner_hook = planner_hook;
+	planner_hook = pltsql_planner_hook;
 }
 
 void
@@ -319,6 +330,7 @@ UninstallExtendedHooks(void)
 	match_pltsql_func_call_hook = prev_match_pltsql_func_call_hook;
 	insert_pltsql_function_defaults_hook = prev_insert_pltsql_function_defaults_hook;
 	print_pltsql_function_arguments_hook = prev_print_pltsql_function_arguments_hook;
+	planner_hook = prev_planner_hook;
 }
 
 /*****************************************
@@ -345,6 +357,12 @@ pltsql_GetNewObjectId(VariableCache variableCache)
 static void
 pltsql_ExecutorStart(QueryDesc *queryDesc, int eflags)
 {
+	if (pltsql_explain_analyze)
+	{
+		PLtsql_execstate *estate = get_current_tsql_estate();
+		Assert(estate != NULL);
+		INSTR_TIME_SET_CURRENT(estate->execution_start);
+	}
 	int ef = pltsql_explain_only ? EXEC_FLAG_EXPLAIN_ONLY : eflags;
 	if (is_explain_analyze_mode())
 	{
@@ -2944,3 +2962,28 @@ pltsql_pg_attribute_aclchk_all(Oid table_oid, Oid roleid, AclMode mode,
 	if (prev_pg_attribute_aclchk_all_hook)
 		prev_pg_attribute_aclchk_all_hook(table_oid, roleid, mode, how, has_access);
 }
+
+static PlannedStmt *
+pltsql_planner_hook(Query *parse, const char *query_string, int cursorOptions, ParamListInfo boundParams)
+{
+	PlannedStmt * plan;
+	PLtsql_execstate *estate;
+
+	if (pltsql_explain_analyze)
+	{
+		estate = get_current_tsql_estate();
+		Assert(estate != NULL);
+		INSTR_TIME_SET_CURRENT(estate->planning_start);
+	}
+	if (prev_planner_hook)
+		plan = prev_planner_hook(parse, query_string, cursorOptions, boundParams);
+	else
+		plan = standard_planner(parse, query_string, cursorOptions, boundParams);
+	if (pltsql_explain_analyze)
+	{
+		INSTR_TIME_SET_CURRENT(estate->planning_end);
+		INSTR_TIME_SUBTRACT(estate->planning_end, estate->planning_start);
+	}
+
+	return plan;
+}
diff --git a/contrib/babelfishpg_tsql/src/pl_exec.c b/contrib/babelfishpg_tsql/src/pl_exec.c
@@ -7232,9 +7232,7 @@ exec_run_select(PLtsql_execstate *estate,
 	 * can't support.
 	 */
 	if (expr->plan == NULL)
-		exec_prepare_plan(estate, expr,
-						  portalP == NULL ? CURSOR_OPT_PARALLEL_OK : 0, true);
-
+		exec_prepare_plan(estate, expr, portalP == NULL ? CURSOR_OPT_PARALLEL_OK : 0, true);
 	/*
 	 * If we started an implicit_transaction for this statement but
 	 * the statement has a simple expression associated with them,

diff --git a/contrib/babelfishpg_tsql/src/pl_explain.c b/contrib/babelfishpg_tsql/src/pl_explain.c
@@ -7,7 +7,7 @@
 
 
 extern PLtsql_execstate *get_outermost_tsql_estate(int *nestlevel);
-
+extern PLtsql_execstate *get_current_tsql_estate();
 bool pltsql_explain_only = false;
 bool pltsql_explain_analyze = false;
 bool pltsql_explain_verbose = false;
@@ -16,7 +16,7 @@ bool pltsql_explain_settings = false;
 bool pltsql_explain_buffers = false;
 bool pltsql_explain_wal = false;
 bool pltsql_explain_timing = true;
-bool pltsql_explain_summary = false;
+bool pltsql_explain_summary = true;
 int pltsql_explain_format = EXPLAIN_FORMAT_TEXT;
 
 static ExplainInfo *get_last_explain_info();
@@ -144,6 +144,14 @@ void append_explain_info(QueryDesc *queryDesc, const char *queryString)
 			ExplainPrintTriggers(es, queryDesc);
 		if (es->costs)
 			ExplainPrintJITSummary(es, queryDesc);
+		if (es->summary) {
+			PLtsql_execstate *time_state = get_current_tsql_estate();
+			ExplainPropertyFloat("Planning Time", "ms", 1000.0 * INSTR_TIME_GET_DOUBLE(time_state->planning_end), 3, es);
+			INSTR_TIME_SET_CURRENT(time_state->execution_end);
+			INSTR_TIME_SUBTRACT(time_state->execution_end, time_state->execution_start);
+			ExplainPropertyFloat("Execution Time", "ms", 1000.0 * INSTR_TIME_GET_DOUBLE(time_state->execution_end), 3, es);
+		}
+
 	}
 	else if (queryString)
 	{

diff --git a/contrib/babelfishpg_tsql/src/pltsql.h b/contrib/babelfishpg_tsql/src/pltsql.h
@@ -1400,6 +1400,10 @@ typedef struct PLtsql_execstate
 	List 		*explain_infos;
 	char		*schema_name;
 	const char		*db_name;
+	instr_time	planning_start;
+	instr_time	planning_end;
+	instr_time execution_start;
+	instr_time execution_end;
 } PLtsql_execstate;
 
 /*

diff --git a/test/JDBC/expected/BABEL-2843.out b/test/JDBC/expected/BABEL-2843.out
@@ -1,5 +1,19 @@
 use master;
 go
+select set_config('babelfishpg_tsql.explain_timing', 'off', false);
+go
+~~START~~
+text
+off
+~~END~~
+
+select set_config('babelfishpg_tsql.explain_summary', 'off', false);
+go
+~~START~~
+text
+off
+~~END~~
+
 
 set babelfish_statistics profile On;
 go
@@ -364,3 +378,18 @@ drop table babel_2843_t2;
 go
 set babelfish_statistics profile oFf;
 go
+
+select set_config('babelfishpg_tsql.explain_timing', 'on', false);
+go
+~~START~~
+text
+on
+~~END~~
+
+select set_config('babelfishpg_tsql.explain_summary', 'on', false);
+go
+~~START~~
+text
+on
+~~END~~
+
diff --git a/test/JDBC/expected/BABEL-3248.out b/test/JDBC/expected/BABEL-3248.out
@@ -5,6 +5,20 @@ text
 off
 ~~END~~
 
+select set_config('babelfishpg_tsql.explain_timing', 'off', false);
+go
+~~START~~
+text
+off
+~~END~~
+
+select set_config('babelfishpg_tsql.explain_summary', 'off', false);
+go
+~~START~~
+text
+off
+~~END~~
+
 select current_setting('babelfishpg_tsql.escape_hatch_showplan_all');
 go
 ~~START~~
@@ -82,3 +96,17 @@ text
 on
 ~~END~~
 
+select set_config('babelfishpg_tsql.explain_timing', 'on', false);
+go
+~~START~~
+text
+on
+~~END~~
+
+select set_config('babelfishpg_tsql.explain_summary', 'on', false);
+go
+~~START~~
+text
+on
+~~END~~
+
diff --git a/test/JDBC/input/BABEL-2843.sql b/test/JDBC/input/BABEL-2843.sql
@@ -1,5 +1,9 @@
 use master;
 go
+select set_config('babelfishpg_tsql.explain_timing', 'off', false);
+go
+select set_config('babelfishpg_tsql.explain_summary', 'off', false);
+go
 
 set babelfish_statistics profile On;
 go
@@ -106,3 +110,8 @@ drop table babel_2843_t2;
 go
 set babelfish_statistics profile oFf;
 go
+
+select set_config('babelfishpg_tsql.explain_timing', 'on', false);
+go
+select set_config('babelfishpg_tsql.explain_summary', 'on', false);
+go
diff --git a/test/JDBC/input/BABEL-3248.sql b/test/JDBC/input/BABEL-3248.sql
@@ -1,5 +1,9 @@
 select set_config('babelfishpg_tsql.explain_costs', 'off', false);
 go
+select set_config('babelfishpg_tsql.explain_timing', 'off', false);
+go
+select set_config('babelfishpg_tsql.explain_summary', 'off', false);
+go
 select current_setting('babelfishpg_tsql.escape_hatch_showplan_all');
 go
 
@@ -40,3 +44,7 @@ go
 
 select set_config('babelfishpg_tsql.explain_costs', 'on', false);
 go
+select set_config('babelfishpg_tsql.explain_timing', 'on', false);
+go
+select set_config('babelfishpg_tsql.explain_summary', 'on', false);
+go