From ce77abe63cfc85fb0bc236deb2cc34ae35cb5324 Mon Sep 17 00:00:00 2001 From: Fujii Masao Date: Sat, 4 Apr 2020 03:13:17 +0900 Subject: [PATCH] Include information on buffer usage during planning phase, in EXPLAIN output, take two. 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. This commit revives the original commit ed7a509571 that was reverted by commit 19db23bcbd. The original commit had to be reverted because it caused the regression test failure on the buildfarm members prion and dory. But since commit c0885c4c30 got rid of the caues of the test failure, the original commit can be safely introduced again. Author: Julien Rouhaud, slightly revised by Fujii Masao Reviewed-by: Justin Pryzby Discussion: https://postgr.es/m/16109-26a1a88651e90608@postgresql.org --- src/backend/commands/explain.c | 32 +++++++++++++++- src/backend/commands/prepare.c | 13 ++++++- src/include/commands/explain.h | 3 +- src/test/regress/expected/explain.out | 55 +++++++++++++++++++++++++-- 4 files changed, 95 insertions(+), 8 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index ee0e638f33d..81a18abbeb3 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -372,7 +372,11 @@ ExplainOneQuery(Query *query, int cursorOptions, PlannedStmt *plan; instr_time planstart, planduration; + BufferUsage bufusage_start, + bufusage; + if (es->buffers) + bufusage_start = pgBufferUsage; INSTR_TIME_SET_CURRENT(planstart); /* plan the query */ @@ -381,9 +385,16 @@ ExplainOneQuery(Query *query, int cursorOptions, INSTR_TIME_SET_CURRENT(planduration); 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 */ 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 ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, const char *queryString, ParamListInfo params, - QueryEnvironment *queryEnv, const instr_time *planduration) + QueryEnvironment *queryEnv, const instr_time *planduration, + const BufferUsage *bufusage) { DestReceiver *dest; QueryDesc *queryDesc; @@ -560,6 +572,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* Create textual dump of plan tree */ ExplainPrintPlan(es, queryDesc); + if (es->summary && (planduration || bufusage)) + ExplainOpenGroup("Planning", "Planning", true, es); + if (es->summary && 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); } + /* 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 */ if (es->analyze) ExplainPrintTriggers(es, queryDesc); diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index 284a5bfbec7..80d6df8ac1e 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -616,7 +616,11 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, EState *estate = NULL; instr_time planstart; instr_time planduration; + BufferUsage bufusage_start, + bufusage; + if (es->buffers) + bufusage_start = pgBufferUsage; INSTR_TIME_SET_CURRENT(planstart); /* 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_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; /* Explain each query */ @@ -663,7 +674,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, if (pstmt->commandType != CMD_UTILITY) ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv, - &planduration); + &planduration, (es->buffers ? &bufusage : NULL)); else ExplainOneUtility(pstmt->utilityStmt, into, es, query_string, paramLI, queryEnv); diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 54f6240e5e5..739c1d0b423 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -89,7 +89,8 @@ extern void ExplainOneUtility(Node *utilityStmt, IntoClause *into, extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, const char *queryString, ParamListInfo params, QueryEnvironment *queryEnv, - const instr_time *planduration); + const instr_time *planduration, + const BufferUsage *bufusage); extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc); extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc); diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out index 3ec66ceda3c..96baba038c2 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -105,7 +105,19 @@ select explain_filter('explain (analyze, buffers, format json) select * from int "Temp Read 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": [ + ], + "Execution Time": N.N + @@ -142,7 +154,19 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8 N + N + + - N.N + + + + N.N + + N + + N + + N+ + N+ + N + + N + + N + + N + + N + + N + + + + + N.N + @@ -176,7 +200,18 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int Local Written Blocks: N + Temp Read 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: + Execution Time: N.N (1 row) @@ -366,9 +401,21 @@ select jsonb_pretty( "Shared Dirtied 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": [ + ], + - "Planning Time": 0.0, + "Execution Time": 0.0 + } + ]