Skip to content

Commit

Permalink
Use ExplainOneQuery hook to show query info and suggestions
Browse files Browse the repository at this point in the history
  • Loading branch information
@yamatattsu
yamatattsu committed May 4, 2024
1 parent e47d6f2 commit fc0762a
Showing 1 changed file with 169 additions and 70 deletions.
239 changes: 169 additions & 70 deletions pg_plan_advsr.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -115,13 +115,21 @@ static double max_diff_ratio_scan;
static int scan_cnt;
static int join_cnt;
static int rows_cnt;
static int initplan_cnt;
static int subplan_cnt;

/* application name */
static char *aplname;

/* This is made by generate_normalized_query in post_parse_analyze_hook */
char *normalized_query;

/* Current nesting depth of ExecutorRun+ProcessUtility calls */
static int nested_level = 0;

#define run_pg_plan_advsr() \
(isExplain == true && nested_level == 0 && pg_plan_advsr_is_enabled)

/* GUC variables */
/* enable / disabe pg_plan_advsr */
static bool pg_plan_advsr_is_enabled;
Expand All @@ -138,6 +146,7 @@ static bool pg_plan_advsr_widely;
/* Saved hook values in case of unload */
static post_parse_analyze_hook_type prev_post_parse_analyze_hook = NULL;
static ProcessUtility_hook_type prev_ProcessUtility_hook = NULL;
static ExplainOneQuery_hook_type prev_ExplainOneQuery_hook = NULL;
static ExecutorStart_hook_type prev_ExecutorStart_hook = NULL;
static ExecutorRun_hook_type prev_ExecutorRun_hook = NULL;
static ExecutorFinish_hook_type prev_ExecutorFinish_hook = NULL;
Expand Down Expand Up @@ -174,6 +183,13 @@ static void pg_plan_advsr_ProcessUtility_hook(PlannedStmt *pstmt,
QueryCompletion *qc);
#endif /* PG_VERSION_NUM */

static void pg_plan_advsr_ExplainOneQuery_hook(Query *query,
int cursorOptions,
IntoClause *into,
ExplainState *es,
const char *queryString,
ParamListInfo params,
QueryEnvironment *queryEnv);
static void pg_plan_advsr_ExecutorStart_hook(QueryDesc *queryDesc, int eflags);
static void pg_plan_advsr_ExecutorRun_hook(QueryDesc *queryDesc, ScanDirection direction,
uint64 count, bool execute_once);
Expand All @@ -189,8 +205,6 @@ static bool pg_plan_advsr_query_walker(Node *parsetree);
static const char *get_query_string(ParseState *pstate, Query *query, Query **jumblequery);
#endif /* PG_VERSION_NUM */

ExplainState *pg_plan_advsr_NewExplainState(void);

/* entry point of pg_plan_advsr */
void pg_plan_advsr_ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);

Expand Down Expand Up @@ -704,6 +718,9 @@ _PG_init(void)
prev_ProcessUtility_hook = ProcessUtility_hook;
ProcessUtility_hook = pg_plan_advsr_ProcessUtility_hook;

prev_ExplainOneQuery_hook = ExplainOneQuery_hook;
ExplainOneQuery_hook = pg_plan_advsr_ExplainOneQuery_hook;

prev_ExecutorStart_hook = ExecutorStart_hook;
ExecutorStart_hook = pg_plan_advsr_ExecutorStart_hook;

Expand Down Expand Up @@ -971,6 +988,130 @@ pg_plan_advsr_ProcessUtility_hook(PlannedStmt *pstmt,
#endif /* PG_VERSION_NUM */
}


static void pg_plan_advsr_ExplainOneQuery_hook(Query *query,
int cursorOptions,
IntoClause *into,
ExplainState *es,
const char *queryString,
ParamListInfo params,
QueryEnvironment *queryEnv)
{
PlannedStmt *plan;
instr_time planstart,
planduration;
#if PG_VERSION_NUM > 130000
BufferUsage bufusage_start,
bufusage;
#endif /* PG_VERSION_NUM */

if (prev_ExplainOneQuery_hook)
prev_ExplainOneQuery_hook(query,
cursorOptions,
into,
es,
queryString,
params,
queryEnv);

if (run_pg_plan_advsr())
{
elog(DEBUG1, "##pg_plan_advsr_ExplainOneQuery_hook start ##");

#if PG_VERSION_NUM > 130000
if (es->buffers)
bufusage_start = pgBufferUsage;
#endif /* PG_VERSION_NUM */

INSTR_TIME_SET_CURRENT(planstart);

/* plan the query */
plan = pg_plan_query(query,
#if PG_VERSION_NUM < 130000
cursorOptions, params);
#else
queryString, cursorOptions, params);
#endif /* PG_VERSION_NUM */

INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);

#if PG_VERSION_NUM > 130000
/* calc differences of buffer counters. */
if (es->buffers)
{
memset(&bufusage, 0, sizeof(BufferUsage));
BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
}
#endif /* PG_VERSION_NUM */


/* run it (if needed) and produce output */
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
#if PG_VERSION_NUM < 130000
&planduration);
#else
&planduration, (es->buffers ? &bufusage : NULL));
#endif /* PG_VERSION_NUM */

if (es->format == EXPLAIN_FORMAT_TEXT && !pg_plan_advsr_is_quieted)
{
appendStringInfo(es->str, "\nDESCRIBE\n");
appendStringInfo(es->str, "------------------------\n");
appendStringInfo(es->str, "application: %s\n", aplname);
appendStringInfo(es->str, "pgsp_queryid: %lu\n", pgsp_queryid);
appendStringInfo(es->str, "pgsp_planid: %u\n", pgsp_planid);
appendStringInfo(es->str, "join_cnt: %d\n", join_cnt);
appendStringInfo(es->str, "join_rows_err: %0.f\n", total_diff_rows_join);
appendStringInfo(es->str, "join_err_ratio: %0.f\n", max_diff_ratio_join);
appendStringInfo(es->str, "scan_cnt: %d\n", scan_cnt);
appendStringInfo(es->str, "scan_rows_err: %0.f\n", total_diff_rows_scan);
appendStringInfo(es->str, "scan_err_ratio: %0.f\n", max_diff_ratio_scan);

appendStringInfo(es->str, "lead hint: %s\n", leadcxt->lead_str->data);
replaceAll(join_str->data, "\n", "");
appendStringInfo(es->str, "join hint: %s\n", join_str->data);

appendStringInfo(es->str, "scan hint: %s\n", scan_str->data);

replaceAll(rows_str->data, "\n", "");
appendStringInfo(es->str, "rows hint: %s\n", rows_str->data);

appendStringInfo(es->str, "\nSUGGESTIONS\n");
appendStringInfo(es->str, "------------------------\n");
appendStringInfo(es->str, "ext stats: TBA\n");
}

/* post processing */
isExplain = false;
normalized_query = NULL;
pgsp_queryid = 0;
pgsp_planid = 0;
pfree(leadcxt);

elog(DEBUG1, "##pg_plan_advsr_ExplainOneQuery_hook end ##");
}
else
{
PlannedStmt *plan;
instr_time planstart,
planduration;

INSTR_TIME_SET_CURRENT(planstart);

/* plan the query */
plan = pg_plan_query(query, cursorOptions, params);

INSTR_TIME_SET_CURRENT(planduration);
INSTR_TIME_SUBTRACT(planduration, planstart);

/* run it (if needed) and produce output */
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
&planduration);
}
}


/* ExecutorStart, Run and Finish are came from pg_store_plans.c */
/*
* ExecutorStart hook: start up tracking if needed
Expand Down Expand Up @@ -1056,6 +1197,7 @@ static void
pg_plan_advsr_ExecutorEnd_hook(QueryDesc *queryDesc)
{
ExplainState *hs;
MemoryContext oldcxt;

if (queryDesc->totaltime)
InstrEndLoop(queryDesc->totaltime);
Expand All @@ -1067,20 +1209,41 @@ pg_plan_advsr_ExecutorEnd_hook(QueryDesc *queryDesc)
elog(DEBUG1, "## pg_plan_advsr_ExecutorEnd start ##");

/* Create Hints using HintState like a ExplainState */
hs = pg_plan_advsr_NewExplainState();
hs = NewExplainState();
hs->analyze = true;
hs->verbose = true;
hs->buffers = false;
hs->timing = false;
hs->summary = hs->analyze;
hs->format = EXPLAIN_FORMAT_JSON;

/* Initialize */
oldcxt = MemoryContextSwitchTo(TopMemoryContext);
leadcxt = (LeadingContext *) palloc0(sizeof(LeadingContext));
leadcxt->lead_str = makeStringInfo();
MemoryContextSwitchTo(oldcxt);

scan_str = makeStringInfo();
join_str = makeStringInfo();
rows_str = makeStringInfo();
est_rows = 0;
act_rows = 0;
diff_rows_join = 0;
diff_ratio_join = 0;
diff_rows_scan = 0;
diff_ratio_scan = 0;
scan_cnt = 0;
join_cnt = 0;
rows_cnt = 0;
initplan_cnt = 0;
subplan_cnt = 0;

pg_plan_advsr_ExplainPrintPlan(hs, queryDesc);

elog(DEBUG1, "## pg_plan_advsr_ExecutorEnd end ##");

/* initialize */
isExplain = false;
/* isExplain = false; */
}

if (prev_ExecutorEnd_hook)
Expand Down Expand Up @@ -1116,10 +1279,6 @@ create_pgsp_planid(QueryDesc *queryDesc)
if (strcmp(GetConfigOptionByName("pg_store_plans.log_triggers", NULL, false), "on") == 0)
log_triggers = true;

/*
* elog(INFO, "pg_store_plans.log_analyze: %s",
* GetConfigOptionByName("pg_store_plans.log_analyze", NULL, false));
*/
elog(DEBUG1, "pg_store_plans.log_verbose : %s", log_verbose ? "on" : "off");
elog(DEBUG1, "pg_store_plans.log_buffers : %s", log_buffers ? "on" : "off");
elog(DEBUG1, "pg_store_plans.log_timing : %s", log_timing ? "on" : "off");
Expand Down Expand Up @@ -1434,7 +1593,7 @@ ExplainPreScanNode(PlanState *planstate, Bitmapset **rels_used)

/* For creating Leading hint */
bool
CreateLeadingHint(PlanState *planstate, LeadingContext * lead)
CreateLeadingHint(PlanState *planstate, LeadingContext *lead)
{
Plan *plan = planstate->plan;

Expand Down Expand Up @@ -1539,8 +1698,6 @@ pg_plan_advsr_ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
CreateScanJoinRowsHints(ps, NIL, NULL, NULL, es);

/* Create leading_str */
leadcxt = (LeadingContext *) palloc0(sizeof(LeadingContext));
leadcxt->lead_str = makeStringInfo();
leadcxt->es = es;

appendStringInfo(leadcxt->lead_str, "LEADING( ");
Expand All @@ -1559,22 +1716,7 @@ pg_plan_advsr_ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
pgsp_planid = create_pgsp_planid(queryDesc);
totaltime = queryDesc->totaltime ? queryDesc->totaltime->total * 1000.0 : 0;

if (!pg_plan_advsr_is_quieted)
{
elog(INFO, "---- pgsp_queryid ----------------\n\t\t%ld", pgsp_queryid);
elog(INFO, "---- pgsp_planid -----------------\n\t\t%d", pgsp_planid);
elog(INFO, "---- Execution Time --------------\n\t\t%0.3f ms", totaltime);
elog(DEBUG3, "---- Query text -------------------\n%s\n", queryDesc->sourceText);
/* normalized_query is made by post_parse_analyze_hook function */
elog(DEBUG3, "---- Normalized query text --------\n%s\n", normalized_query);
elog(INFO, "---- Hints for current plan ------\n%s\n%s\n%s", scan_str->data, join_str->data, leadcxt->lead_str->data);
elog(INFO, "---- Rows hint (feedback info)----\n%s", rows_str->data);
elog(INFO, "---- Join count ------------------\n\t\t%d", join_cnt);
elog(INFO, "---- Total diff rows of joins ----\n\t\t%.0f", total_diff_rows_join);
elog(INFO, "---- Maximum diff ratio of joins -\n\t\t%.3f", max_diff_ratio_join);
elog(INFO, "---- Total diff rows of scans ----\n\t\t%.0f", total_diff_rows_scan);
elog(INFO, "---- Maximum diff ratio of scans -\n\t\t%.3f", max_diff_ratio_scan);
}
aplname = GetConfigOptionByName("application_name", NULL, false);

/* store above data to tables */
/*----
Expand All @@ -1586,11 +1728,6 @@ pg_plan_advsr_ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
*/
store_info_to_tables(totaltime, queryDesc->sourceText);

/* initialize */
normalized_query = NULL;
pgsp_queryid = 0;
pgsp_planid = 0;
pfree(leadcxt);
}

/*
Expand All @@ -1605,7 +1742,6 @@ store_info_to_tables(double totaltime, const char *sourcetext)
const char *errstr = NULL;
#endif /* PG_VERSION_NUM */

char *aplname;
StringInfo prev_rows_hint;
StringInfo new_hint;

Expand All @@ -1628,11 +1764,6 @@ store_info_to_tables(double totaltime, const char *sourcetext)
errmsg("pg_md5_hash: out of memory")));
}

/* get application_name */
aplname = GetConfigOptionByName("application_name", NULL, false);
if (!pg_plan_advsr_is_quieted)
elog(INFO, "---- Application name-------------\n\t\t%s", aplname);

/* insert totaltime and hints to plan_repo.plan_history */
if (insertPlanHistory(md5, pgsp_queryid, pgsp_planid, totaltime,
rows_str->data, scan_str->data, join_str->data,
Expand Down Expand Up @@ -1944,38 +2075,6 @@ CreateScanJoinRowsHints(PlanState *planstate, List *ancestors,
}
}


/*
* Create a new ExplainState struct initialized with default options.
*/
ExplainState *
pg_plan_advsr_NewExplainState(void)
{
ExplainState *es = (ExplainState *) palloc0(sizeof(ExplainState));

elog(DEBUG1, "### pg_plan_advsr_NewExplainState ###");

/* Set default options (most fields can be left as zeroes). */
es->costs = true;
/* Prepare output buffer. */
es->str = makeStringInfo();

scan_str = makeStringInfo();
join_str = makeStringInfo();
rows_str = makeStringInfo();
est_rows = 0;
act_rows = 0;
diff_rows_join = 0;
diff_ratio_join = 0;
diff_rows_scan = 0;
diff_ratio_scan = 0;
scan_cnt = 0;
join_cnt = 0;
rows_cnt = 0;

return es;
}

/*
* Show the target of a Scan node
*/
Expand Down

0 comments on commit fc0762a

Please sign in to comment.