diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 6f82a671ee..3397ea17a0 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -1021,30 +1021,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, rows = 0; /* calc differences of buffer counters. */ - bufusage.shared_blks_hit = - pgBufferUsage.shared_blks_hit - bufusage_start.shared_blks_hit; - bufusage.shared_blks_read = - pgBufferUsage.shared_blks_read - bufusage_start.shared_blks_read; - bufusage.shared_blks_dirtied = - pgBufferUsage.shared_blks_dirtied - bufusage_start.shared_blks_dirtied; - bufusage.shared_blks_written = - pgBufferUsage.shared_blks_written - bufusage_start.shared_blks_written; - bufusage.local_blks_hit = - pgBufferUsage.local_blks_hit - bufusage_start.local_blks_hit; - bufusage.local_blks_read = - pgBufferUsage.local_blks_read - bufusage_start.local_blks_read; - bufusage.local_blks_dirtied = - pgBufferUsage.local_blks_dirtied - bufusage_start.local_blks_dirtied; - bufusage.local_blks_written = - pgBufferUsage.local_blks_written - bufusage_start.local_blks_written; - bufusage.temp_blks_read = - pgBufferUsage.temp_blks_read - bufusage_start.temp_blks_read; - bufusage.temp_blks_written = - pgBufferUsage.temp_blks_written - bufusage_start.temp_blks_written; - bufusage.blk_read_time = pgBufferUsage.blk_read_time; - INSTR_TIME_SUBTRACT(bufusage.blk_read_time, bufusage_start.blk_read_time); - bufusage.blk_write_time = pgBufferUsage.blk_write_time; - INSTR_TIME_SUBTRACT(bufusage.blk_write_time, bufusage_start.blk_write_time); + bufusage = ComputeBufferCounters(&bufusage_start, &pgBufferUsage); pgss_store(queryString, 0, /* signal that it's a utility stmt */ diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index c367c750b1..492feca90f 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -370,7 +370,10 @@ ExplainOneQuery(Query *query, int cursorOptions, PlannedStmt *plan; instr_time planstart, planduration; + BufferUsage bufusage_start, + bufusage; + bufusage_start = pgBufferUsage; INSTR_TIME_SET_CURRENT(planstart); /* plan the query */ @@ -379,9 +382,12 @@ ExplainOneQuery(Query *query, int cursorOptions, INSTR_TIME_SET_CURRENT(planduration); INSTR_TIME_SUBTRACT(planduration, planstart); + /* calc differences of buffer counters. */ + bufusage = ComputeBufferCounters(&bufusage_start, &pgBufferUsage); + /* run it (if needed) and produce output */ ExplainOnePlan(plan, into, es, queryString, params, queryEnv, - &planduration); + &planduration, &bufusage); } } @@ -474,7 +480,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; @@ -558,6 +565,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, /* Create textual dump of plan tree */ ExplainPrintPlan(es, queryDesc); + if (es->summary && (planduration || es->buffers)) + ExplainOpenGroup("Planning", "Planning", true, es); + if (es->summary && planduration) { double plantime = INSTR_TIME_GET_DOUBLE(*planduration); @@ -565,6 +575,16 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es); } + if (es->summary && es->buffers) + { + es->indent += 1; + show_buffer_usage(es, bufusage); + es->indent -= 1; + } + + if (es->summary && (planduration || es->buffers)) + 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 c4e4b6eaec..aa29a33aa6 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -616,7 +616,10 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, EState *estate = NULL; instr_time planstart; instr_time planduration; + BufferUsage bufusage_start, + bufusage; + bufusage_start = pgBufferUsage; INSTR_TIME_SET_CURRENT(planstart); /* Look it up in the hash table */ @@ -654,6 +657,9 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, INSTR_TIME_SET_CURRENT(planduration); INSTR_TIME_SUBTRACT(planduration, planstart); + /* calc differences of buffer counters. */ + bufusage = ComputeBufferCounters(&bufusage_start, &pgBufferUsage); + plan_list = cplan->stmt_list; /* Explain each query */ @@ -663,7 +669,7 @@ ExplainExecuteQuery(ExecuteStmt *execstmt, IntoClause *into, ExplainState *es, if (pstmt->commandType != CMD_UTILITY) ExplainOnePlan(pstmt, into, es, query_string, paramLI, queryEnv, - &planduration); + &planduration, &bufusage); else ExplainOneUtility(pstmt->utilityStmt, into, es, query_string, paramLI, queryEnv); diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index bc1d42bf64..2d8e435707 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -25,6 +25,33 @@ static void BufferUsageAccumDiff(BufferUsage *dst, const BufferUsage *add, const BufferUsage *sub); +/* Compute the difference between two BufferUsage */ +BufferUsage +ComputeBufferCounters(BufferUsage *start, BufferUsage *stop) +{ + BufferUsage result; + +#define CALC_BUFF_DIFF(x) result.x = stop->x - start->x; + CALC_BUFF_DIFF(shared_blks_hit); + CALC_BUFF_DIFF(shared_blks_read); + CALC_BUFF_DIFF(shared_blks_dirtied); + CALC_BUFF_DIFF(shared_blks_written); + CALC_BUFF_DIFF(local_blks_hit); + CALC_BUFF_DIFF(local_blks_read); + CALC_BUFF_DIFF(local_blks_dirtied); + CALC_BUFF_DIFF(local_blks_written); + CALC_BUFF_DIFF(temp_blks_read); + CALC_BUFF_DIFF(temp_blks_written); +#undef CALC_BUFF_DIFF + + result.blk_read_time = stop->blk_read_time; + INSTR_TIME_SUBTRACT(result.blk_read_time, start->blk_read_time); + result.blk_write_time = stop->blk_write_time; + INSTR_TIME_SUBTRACT(result.blk_write_time, start->blk_write_time); + + return result; +} + /* Allocate new instrumentation structure(s) */ Instrumentation * InstrAlloc(int n, int instrument_options) diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 54f6240e5e..739c1d0b42 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/include/executor/instrument.h b/src/include/executor/instrument.h index f48d46aede..2f112c051c 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -72,6 +72,7 @@ typedef struct WorkerInstrumentation extern PGDLLIMPORT BufferUsage pgBufferUsage; +extern BufferUsage ComputeBufferCounters(BufferUsage *start, BufferUsage *stop); extern Instrumentation *InstrAlloc(int n, int instrument_options); extern void InstrInit(Instrumentation *instr, int instrument_options); extern void InstrStartNode(Instrumentation *instr); diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out index 8f31c308c6..679a78b98c 100644 --- a/src/test/regress/expected/explain.out +++ b/src/test/regress/expected/explain.out @@ -77,107 +77,142 @@ select explain_filter('explain (analyze, buffers, format text) select * from int (4 rows) select explain_filter('explain (analyze, buffers, format json) select * from int8_tbl i8'); - explain_filter ------------------------------------- - [ + - { + - "Plan": { + - "Node Type": "Seq Scan", + - "Parallel Aware": false, + - "Relation Name": "int8_tbl",+ - "Alias": "i8", + - "Startup Cost": N.N, + - "Total Cost": N.N, + - "Plan Rows": N, + - "Plan Width": N, + - "Actual Startup Time": N.N, + - "Actual Total Time": N.N, + - "Actual Rows": N, + - "Actual Loops": 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 + - }, + - "Planning Time": N.N, + - "Triggers": [ + - ], + - "Execution Time": N.N + - } + + explain_filter +------------------------------------- + [ + + { + + "Plan": { + + "Node Type": "Seq Scan", + + "Parallel Aware": false, + + "Relation Name": "int8_tbl", + + "Alias": "i8", + + "Startup Cost": N.N, + + "Total Cost": N.N, + + "Plan Rows": N, + + "Plan Width": N, + + "Actual Startup Time": N.N, + + "Actual Total Time": N.N, + + "Actual Rows": N, + + "Actual Loops": 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 + + }, + + "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) select explain_filter('explain (analyze, buffers, format xml) select * from int8_tbl i8'); - explain_filter --------------------------------------------------------- - + - + - + - Seq Scan + - false + - int8_tbl + - i8 + - N.N + - N.N + - N + - N + - N.N + - N.N + - N + - N + - N + - N + - N+ - N+ - N + - N + - N + - N + - N + - N + - + - N.N + - + - + - N.N + - + + explain_filter +---------------------------------------------------------- + + + + + + + Seq Scan + + false + + int8_tbl + + i8 + + N.N + + N.N + + N + + N + + N.N + + N.N + + N + + N + + N + + N + + N + + N + + N + + N + + N + + N + + N + + N + + + + + + N.N + + N + + N + + N+ + N+ + N + + N + + N + + N + + N + + N + + + + + + + + N.N + + + (1 row) select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8'); - explain_filter -------------------------------- - - Plan: + - Node Type: "Seq Scan" + - Parallel Aware: false + - Relation Name: "int8_tbl"+ - Alias: "i8" + - Startup Cost: N.N + - Total Cost: N.N + - Plan Rows: N + - Plan Width: N + - Actual Startup Time: N.N + - Actual Total Time: N.N + - Actual Rows: N + - Actual Loops: 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 + - Planning Time: N.N + - Triggers: + + explain_filter +-------------------------------- + - Plan: + + Node Type: "Seq Scan" + + Parallel Aware: false + + Relation Name: "int8_tbl" + + Alias: "i8" + + Startup Cost: N.N + + Total Cost: N.N + + Plan Rows: N + + Plan Width: N + + Actual Startup Time: N.N + + Actual Total Time: N.N + + Actual Rows: N + + Actual Loops: 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 + + 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 + } + ]