Include information on buffer usage during planning phase, in EXPLAIN output.
When BUFFERS option is enabled, EXPLAIN command includes the information on buffer usage during each plan node, in its output. In addition to that, this commit makes EXPLAIN command include also the information on buffer usage during planning phase, in its output. This feature makes it easier to discern the cases where lots of buffer access happen during planning. Author: Julien Rouhaud, slightly revised by Fujii Masao Reviewed-by: Justin Pryzby Discussion: https://postgr.es/m/16109-26a1a88651e90608@postgresql.org
This commit is contained in:
parent
ac44367efb
commit
ed7a509571
|
@ -372,7 +372,11 @@ ExplainOneQuery(Query *query, int cursorOptions,
|
||||||
PlannedStmt *plan;
|
PlannedStmt *plan;
|
||||||
instr_time planstart,
|
instr_time planstart,
|
||||||
planduration;
|
planduration;
|
||||||
|
BufferUsage bufusage_start,
|
||||||
|
bufusage;
|
||||||
|
|
||||||
|
if (es->buffers)
|
||||||
|
bufusage_start = pgBufferUsage;
|
||||||
INSTR_TIME_SET_CURRENT(planstart);
|
INSTR_TIME_SET_CURRENT(planstart);
|
||||||
|
|
||||||
/* plan the query */
|
/* plan the query */
|
||||||
|
@ -381,9 +385,16 @@ ExplainOneQuery(Query *query, int cursorOptions,
|
||||||
INSTR_TIME_SET_CURRENT(planduration);
|
INSTR_TIME_SET_CURRENT(planduration);
|
||||||
INSTR_TIME_SUBTRACT(planduration, planstart);
|
INSTR_TIME_SUBTRACT(planduration, planstart);
|
||||||
|
|
||||||
|
/* calc differences of buffer counters. */
|
||||||
|
if (es->buffers)
|
||||||
|
{
|
||||||
|
memset(&bufusage, 0, sizeof(BufferUsage));
|
||||||
|
BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
|
||||||
|
}
|
||||||
|
|
||||||
/* run it (if needed) and produce output */
|
/* run it (if needed) and produce output */
|
||||||
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
|
ExplainOnePlan(plan, into, es, queryString, params, queryEnv,
|
||||||
&planduration);
|
&planduration, (es->buffers ? &bufusage : NULL));
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@ -476,7 +487,8 @@ ExplainOneUtility(Node *utilityStmt, IntoClause *into, ExplainState *es,
|
||||||
void
|
void
|
||||||
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
|
ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
|
||||||
const char *queryString, ParamListInfo params,
|
const char *queryString, ParamListInfo params,
|
||||||
QueryEnvironment *queryEnv, const instr_time *planduration)
|
QueryEnvironment *queryEnv, const instr_time *planduration,
|
||||||
|
const BufferUsage *bufusage)
|
||||||
{
|
{
|
||||||
DestReceiver *dest;
|
DestReceiver *dest;
|
||||||
QueryDesc *queryDesc;
|
QueryDesc *queryDesc;
|
||||||
|
@ -560,6 +572,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
|
||||||
/* Create textual dump of plan tree */
|
/* Create textual dump of plan tree */
|
||||||
ExplainPrintPlan(es, queryDesc);
|
ExplainPrintPlan(es, queryDesc);
|
||||||
|
|
||||||
|
if (es->summary && (planduration || bufusage))
|
||||||
|
ExplainOpenGroup("Planning", "Planning", true, es);
|
||||||
|
|
||||||
if (es->summary && planduration)
|
if (es->summary && planduration)
|
||||||
{
|
{
|
||||||
double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
|
double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
|
||||||
|
@ -567,6 +582,19 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
|
||||||
ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
|
ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/* Show buffer usage */
|
||||||
|
if (es->summary && bufusage)
|
||||||
|
{
|
||||||
|
if (es->format == EXPLAIN_FORMAT_TEXT)
|
||||||
|
es->indent++;
|
||||||
|
show_buffer_usage(es, bufusage);
|
||||||
|
if (es->format == EXPLAIN_FORMAT_TEXT)
|
||||||
|
es->indent--;
|
||||||
|
}
|
||||||
|
|
||||||
|
if (es->summary && (planduration || bufusage))
|
||||||
|
ExplainCloseGroup("Planning", "Planning", true, es);
|
||||||
|
|
||||||
/* Print info about runtime of triggers */
|
/* Print info about runtime of triggers */
|
||||||
if (es->analyze)
|
if (es->analyze)
|
||||||
ExplainPrintTriggers(es, queryDesc);
|
ExplainPrintTriggers(es, queryDesc);
|
||||||
|
|
|
@ -616,7 +616,11 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
|
||||||
EState *estate = NULL;
|
EState *estate = NULL;
|
||||||
instr_time planstart;
|
instr_time planstart;
|
||||||
instr_time planduration;
|
instr_time planduration;
|
||||||
|
BufferUsage bufusage_start,
|
||||||
|
bufusage;
|
||||||
|
|
||||||
|
if (es->buffers)
|
||||||
|
bufusage_start = pgBufferUsage;
|
||||||
INSTR_TIME_SET_CURRENT(planstart);
|
INSTR_TIME_SET_CURRENT(planstart);
|
||||||
|
|
||||||
/* Look it up in the hash table */
|
/* Look it up in the hash table */
|
||||||
|
@ -654,6 +658,13 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
|
||||||
INSTR_TIME_SET_CURRENT(planduration);
|
INSTR_TIME_SET_CURRENT(planduration);
|
||||||
INSTR_TIME_SUBTRACT(planduration, planstart);
|
INSTR_TIME_SUBTRACT(planduration, planstart);
|
||||||
|
|
||||||
|
/* calc differences of buffer counters. */
|
||||||
|
if (es->buffers)
|
||||||
|
{
|
||||||
|
memset(&bufusage, 0, sizeof(BufferUsage));
|
||||||
|
BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start);
|
||||||
|
}
|
||||||
|
|
||||||
plan_list = cplan->stmt_list;
|
plan_list = cplan->stmt_list;
|
||||||
|
|
||||||
/* Explain each query */
|
/* Explain each query */
|
||||||
|
@ -663,7 +674,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es,
|
||||||
|
|
||||||
if (pstmt->commandType != CMD_UTILITY)
|
if (pstmt->commandType != CMD_UTILITY)
|
||||||
ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
|
ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv,
|
||||||
&planduration);
|
&planduration, (es->buffers ? &bufusage : NULL));
|
||||||
else
|
else
|
||||||
ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
|
ExplainOneUtility(pstmt->utilityStmt, into, es, query_string,
|
||||||
paramLI, queryEnv);
|
paramLI, queryEnv);
|
||||||
|
|
|
@ -89,7 +89,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause *into,
|
||||||
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
|
extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
|
||||||
ExplainState *es, const char *queryString,
|
ExplainState *es, const char *queryString,
|
||||||
ParamListInfo params, QueryEnvironment *queryEnv,
|
ParamListInfo params, QueryEnvironment *queryEnv,
|
||||||
const instr_time *planduration);
|
const instr_time *planduration,
|
||||||
|
const BufferUsage *bufusage);
|
||||||
|
|
||||||
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
|
extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
|
||||||
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
|
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
|
||||||
|
|
|
@ -105,7 +105,19 @@ select explain_filter('explain (analyze, buffers, format json) select * from int
|
||||||
"Temp Read Blocks": N, +
|
"Temp Read Blocks": N, +
|
||||||
"Temp Written Blocks": N +
|
"Temp Written Blocks": N +
|
||||||
}, +
|
}, +
|
||||||
"Planning Time": N.N, +
|
"Planning": { +
|
||||||
|
"Planning Time": N.N, +
|
||||||
|
"Shared Hit Blocks": N, +
|
||||||
|
"Shared Read Blocks": N, +
|
||||||
|
"Shared Dirtied Blocks": N, +
|
||||||
|
"Shared Written Blocks": N, +
|
||||||
|
"Local Hit Blocks": N, +
|
||||||
|
"Local Read Blocks": N, +
|
||||||
|
"Local Dirtied Blocks": N, +
|
||||||
|
"Local Written Blocks": N, +
|
||||||
|
"Temp Read Blocks": N, +
|
||||||
|
"Temp Written Blocks": N +
|
||||||
|
}, +
|
||||||
"Triggers": [ +
|
"Triggers": [ +
|
||||||
], +
|
], +
|
||||||
"Execution Time": N.N +
|
"Execution Time": N.N +
|
||||||
|
@ -142,7 +154,19 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
|
||||||
<Temp-Read-Blocks>N</Temp-Read-Blocks> +
|
<Temp-Read-Blocks>N</Temp-Read-Blocks> +
|
||||||
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
|
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
|
||||||
</Plan> +
|
</Plan> +
|
||||||
<Planning-Time>N.N</Planning-Time> +
|
<Planning> +
|
||||||
|
<Planning-Time>N.N</Planning-Time> +
|
||||||
|
<Shared-Hit-Blocks>N</Shared-Hit-Blocks> +
|
||||||
|
<Shared-Read-Blocks>N</Shared-Read-Blocks> +
|
||||||
|
<Shared-Dirtied-Blocks>N</Shared-Dirtied-Blocks>+
|
||||||
|
<Shared-Written-Blocks>N</Shared-Written-Blocks>+
|
||||||
|
<Local-Hit-Blocks>N</Local-Hit-Blocks> +
|
||||||
|
<Local-Read-Blocks>N</Local-Read-Blocks> +
|
||||||
|
<Local-Dirtied-Blocks>N</Local-Dirtied-Blocks> +
|
||||||
|
<Local-Written-Blocks>N</Local-Written-Blocks> +
|
||||||
|
<Temp-Read-Blocks>N</Temp-Read-Blocks> +
|
||||||
|
<Temp-Written-Blocks>N</Temp-Written-Blocks> +
|
||||||
|
</Planning> +
|
||||||
<Triggers> +
|
<Triggers> +
|
||||||
</Triggers> +
|
</Triggers> +
|
||||||
<Execution-Time>N.N</Execution-Time> +
|
<Execution-Time>N.N</Execution-Time> +
|
||||||
|
@ -176,7 +200,18 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
|
||||||
Local Written Blocks: N +
|
Local Written Blocks: N +
|
||||||
Temp Read Blocks: N +
|
Temp Read Blocks: N +
|
||||||
Temp Written Blocks: N +
|
Temp Written Blocks: N +
|
||||||
Planning Time: N.N +
|
Planning: +
|
||||||
|
Planning Time: N.N +
|
||||||
|
Shared Hit Blocks: N +
|
||||||
|
Shared Read Blocks: N +
|
||||||
|
Shared Dirtied Blocks: N +
|
||||||
|
Shared Written Blocks: N +
|
||||||
|
Local Hit Blocks: N +
|
||||||
|
Local Read Blocks: N +
|
||||||
|
Local Dirtied Blocks: N +
|
||||||
|
Local Written Blocks: N +
|
||||||
|
Temp Read Blocks: N +
|
||||||
|
Temp Written Blocks: N +
|
||||||
Triggers: +
|
Triggers: +
|
||||||
Execution Time: N.N
|
Execution Time: N.N
|
||||||
(1 row)
|
(1 row)
|
||||||
|
@ -366,9 +401,21 @@ select jsonb_pretty(
|
||||||
"Shared Dirtied Blocks": 0, +
|
"Shared Dirtied Blocks": 0, +
|
||||||
"Shared Written Blocks": 0 +
|
"Shared Written Blocks": 0 +
|
||||||
}, +
|
}, +
|
||||||
|
"Planning": { +
|
||||||
|
"Planning Time": 0.0, +
|
||||||
|
"Local Hit Blocks": 0, +
|
||||||
|
"Temp Read Blocks": 0, +
|
||||||
|
"Local Read Blocks": 0, +
|
||||||
|
"Shared Hit Blocks": 0, +
|
||||||
|
"Shared Read Blocks": 0, +
|
||||||
|
"Temp Written Blocks": 0, +
|
||||||
|
"Local Dirtied Blocks": 0, +
|
||||||
|
"Local Written Blocks": 0, +
|
||||||
|
"Shared Dirtied Blocks": 0, +
|
||||||
|
"Shared Written Blocks": 0 +
|
||||||
|
}, +
|
||||||
"Triggers": [ +
|
"Triggers": [ +
|
||||||
], +
|
], +
|
||||||
"Planning Time": 0.0, +
|
|
||||||
"Execution Time": 0.0 +
|
"Execution Time": 0.0 +
|
||||||
} +
|
} +
|
||||||
]
|
]
|
||||||
|
|
Loading…
Reference in New Issue