From cddca5ec13d27017281422124cae0480cddfb663 Mon Sep 17 00:00:00 2001 From: Robert Haas Date: Tue, 15 Dec 2009 04:57:48 +0000 Subject: [PATCH] Add an EXPLAIN (BUFFERS) option to show buffer-usage statistics. This patch also removes buffer-usage statistics from the track_counts output, since this (or the global server statistics) is deemed to be a better interface to this information. Itagaki Takahiro, reviewed by Euler Taveira de Oliveira. --- contrib/auto_explain/auto_explain.c | 24 ++++- .../pg_stat_statements/pg_stat_statements.c | 4 +- doc/src/sgml/auto-explain.sgml | 21 +++- doc/src/sgml/ref/explain.sgml | 22 ++++- src/backend/commands/copy.c | 4 +- src/backend/commands/explain.c | 95 ++++++++++++++++++- src/backend/commands/tablecmds.c | 4 +- src/backend/executor/execMain.c | 12 +-- src/backend/executor/execProcnode.c | 4 +- src/backend/executor/functions.c | 4 +- src/backend/executor/instrument.c | 47 ++++++++- src/backend/executor/spi.c | 4 +- src/backend/storage/buffer/buf_init.c | 12 +-- src/backend/storage/buffer/bufmgr.c | 64 ++----------- src/backend/storage/buffer/localbuf.c | 5 +- src/backend/storage/file/buffile.c | 7 +- src/backend/tcop/postgres.c | 8 +- src/backend/tcop/pquery.c | 12 +-- src/include/commands/explain.h | 3 +- src/include/executor/execdesc.h | 6 +- src/include/executor/executor.h | 4 +- src/include/executor/instrument.h | 28 +++++- src/include/nodes/execnodes.h | 4 +- src/include/storage/buf_internals.h | 12 +-- src/include/storage/bufmgr.h | 4 +- 25 files changed, 274 insertions(+), 140 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 88d40c7188..47fde6d669 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -6,7 +6,7 @@ * Copyright (c) 2008-2009, PostgreSQL Global Development Group * * IDENTIFICATION - * $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.9 2009/12/12 00:35:33 rhaas Exp $ + * $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.10 2009/12/15 04:57:46 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -22,6 +22,7 @@ PG_MODULE_MAGIC; static int auto_explain_log_min_duration = -1; /* msec or -1 */ static bool auto_explain_log_analyze = false; static bool auto_explain_log_verbose = false; +static bool auto_explain_log_buffers = false; static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT; static bool auto_explain_log_nested_statements = false; @@ -93,6 +94,16 @@ _PG_init(void) NULL, NULL); + DefineCustomBoolVariable("auto_explain.log_buffers", + "Log buffers usage.", + NULL, + &auto_explain_log_buffers, + false, + PGC_SUSET, + 0, + NULL, + NULL); + DefineCustomEnumVariable("auto_explain.log_format", "EXPLAIN format to be used for plan logging.", NULL, @@ -147,7 +158,11 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) { /* Enable per-node instrumentation iff log_analyze is required. */ if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) - queryDesc->doInstrument = true; + { + queryDesc->instrument_options |= INSTRUMENT_TIMER; + if (auto_explain_log_buffers) + queryDesc->instrument_options |= INSTRUMENT_BUFFERS; + } } if (prev_ExecutorStart) @@ -167,7 +182,7 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) MemoryContext oldcxt; oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); - queryDesc->totaltime = InstrAlloc(1); + queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL); MemoryContextSwitchTo(oldcxt); } } @@ -219,8 +234,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc) ExplainState es; ExplainInitState(&es); - es.analyze = (queryDesc->doInstrument && auto_explain_log_analyze); + es.analyze = (queryDesc->instrument_options && auto_explain_log_analyze); es.verbose = auto_explain_log_verbose; + es.buffers = (es.analyze && auto_explain_log_buffers); es.format = auto_explain_log_format; ExplainBeginOutput(&es); diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index a877e63740..01e4b5e593 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -14,7 +14,7 @@ * Copyright (c) 2008-2009, PostgreSQL Global Development Group * * IDENTIFICATION - * $PostgreSQL: pgsql/contrib/pg_stat_statements/pg_stat_statements.c,v 1.7 2009/12/01 02:31:11 momjian Exp $ + * $PostgreSQL: pgsql/contrib/pg_stat_statements/pg_stat_statements.c,v 1.8 2009/12/15 04:57:46 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -495,7 +495,7 @@ pgss_ExecutorStart(QueryDesc *queryDesc, int eflags) MemoryContext oldcxt; oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); - queryDesc->totaltime = InstrAlloc(1); + queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL); MemoryContextSwitchTo(oldcxt); } } diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml index 39c7bc20f5..f332321ccb 100644 --- a/doc/src/sgml/auto-explain.sgml +++ b/doc/src/sgml/auto-explain.sgml @@ -1,4 +1,4 @@ - + auto_explain @@ -102,6 +102,25 @@ LOAD 'auto_explain'; + + + auto_explain.log_buffers (boolean) + + + auto_explain.log_buffers configuration parameter + + + + auto_explain.log_buffers causes EXPLAIN + (ANALYZE, BUFFERS) output, rather than just EXPLAIN + output, to be printed when an execution plan is logged. This parameter is + off by default. Only superusers can change this setting. This + parameter has no effect unless auto_explain.log_analyze + parameter is set. + + + + auto_explain.log_format (enum) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 4de5a4aba6..2f6aaf427a 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -1,5 +1,5 @@ @@ -31,7 +31,7 @@ PostgreSQL documentation -EXPLAIN [ ( { ANALYZE boolean | VERBOSE boolean | COSTS boolean | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] statement +EXPLAIN [ ( { ANALYZE boolean | VERBOSE boolean | COSTS boolean | BUFFERS boolean | FORMAT { TEXT | XML | JSON | YAML } } [, ...] ) ] statement EXPLAIN [ ANALYZE ] [ VERBOSE ] statement @@ -139,6 +139,24 @@ ROLLBACK; + + BUFFERS + + + Include information on buffer usage. Specifically, include the number of + shared blocks hits, reads, and writes, the number of local blocks hits, + reads, and writes, and the number of temp blocks reads and writes. + Shared blocks, local blocks, and temp blocks contain tables and indexes, + temporary tables and temporary indexes, and disk blocks used in sort and + materialized plans, respectively. The number of blocks shown for an + upper-level node includes those used by all its child nodes. In text + format, only non-zero values are printed. This parameter may only be + used with ANALYZE parameter. It defaults to + FALSE. + + + + FORMAT diff --git a/src/backend/commands/copy.c b/src/backend/commands/copy.c index 4ad49409c5..521f2828b8 100644 --- a/src/backend/commands/copy.c +++ b/src/backend/commands/copy.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.318 2009/11/20 20:38:10 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/commands/copy.c,v 1.319 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -1094,7 +1094,7 @@ DoCopy(const CopyStmt *stmt, const char *queryString) cstate->queryDesc = CreateQueryDesc(plan, queryString, GetActiveSnapshot(), InvalidSnapshot, - dest, NULL, false); + dest, NULL, 0); /* * Call ExecutorStart to prepare the plan for execution. diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index c34b5751e4..e63b8579d8 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -7,7 +7,7 @@ * Portions Copyright (c) 1994-5, Regents of the University of California * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.195 2009/12/12 00:35:33 rhaas Exp $ + * $PostgreSQL: pgsql/src/backend/commands/explain.c,v 1.196 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -125,6 +125,8 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString, es.verbose = defGetBoolean(opt); else if (strcmp(opt->defname, "costs") == 0) es.costs = defGetBoolean(opt); + else if (strcmp(opt->defname, "buffers") == 0) + es.buffers = defGetBoolean(opt); else if (strcmp(opt->defname, "format") == 0) { char *p = defGetString(opt); @@ -150,6 +152,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString, opt->defname))); } + if (es.buffers && !es.analyze) + ereport(ERROR, + (errcode(ERRCODE_INVALID_PARAMETER_VALUE), + errmsg("EXPLAIN option BUFFERS requires ANALYZE"))); + /* * Run parse analysis and rewrite. Note this also acquires sufficient * locks on the source table(s). @@ -339,6 +346,12 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es, instr_time starttime; double totaltime = 0; int eflags; + int instrument_option = 0; + + if (es->analyze) + instrument_option |= INSTRUMENT_TIMER; + if (es->buffers) + instrument_option |= INSTRUMENT_BUFFERS; /* * Use a snapshot with an updated command ID to ensure this query sees @@ -349,7 +362,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es, /* Create a QueryDesc requesting no output */ queryDesc = CreateQueryDesc(plannedstmt, queryString, GetActiveSnapshot(), InvalidSnapshot, - None_Receiver, params, es->analyze); + None_Receiver, params, instrument_option); INSTR_TIME_SET_CURRENT(starttime); @@ -1042,6 +1055,84 @@ ExplainNode(Plan *plan, PlanState *planstate, break; } + /* Show buffer usage */ + if (es->buffers) + { + const BufferUsage *usage = &planstate->instrument->bufusage; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + bool has_shared = (usage->shared_blks_hit > 0 || + usage->shared_blks_read > 0 || + usage->shared_blks_written); + bool has_local = (usage->local_blks_hit > 0 || + usage->local_blks_read > 0 || + usage->local_blks_written); + bool has_temp = (usage->temp_blks_read > 0 || + usage->temp_blks_written); + + /* Show only positive counter values. */ + if (has_shared || has_local || has_temp) + { + appendStringInfoSpaces(es->str, es->indent * 2); + appendStringInfoString(es->str, "Buffers:"); + + if (has_shared) + { + appendStringInfoString(es->str, " shared"); + if (usage->shared_blks_hit > 0) + appendStringInfo(es->str, " hit=%ld", + usage->shared_blks_hit); + if (usage->shared_blks_read > 0) + appendStringInfo(es->str, " read=%ld", + usage->shared_blks_read); + if (usage->shared_blks_written > 0) + appendStringInfo(es->str, " written=%ld", + usage->shared_blks_written); + if (has_local || has_temp) + appendStringInfoChar(es->str, ','); + } + if (has_local) + { + appendStringInfoString(es->str, " local"); + if (usage->local_blks_hit > 0) + appendStringInfo(es->str, " hit=%ld", + usage->local_blks_hit); + if (usage->local_blks_read > 0) + appendStringInfo(es->str, " read=%ld", + usage->local_blks_read); + if (usage->local_blks_written > 0) + appendStringInfo(es->str, " written=%ld", + usage->local_blks_written); + if (has_temp) + appendStringInfoChar(es->str, ','); + } + if (has_temp) + { + appendStringInfoString(es->str, " temp"); + if (usage->temp_blks_read > 0) + appendStringInfo(es->str, " read=%ld", + usage->temp_blks_read); + if (usage->temp_blks_written > 0) + appendStringInfo(es->str, " written=%ld", + usage->temp_blks_written); + } + appendStringInfoChar(es->str, '\n'); + } + } + else + { + ExplainPropertyLong("Shared Hit Blocks", usage->shared_blks_hit, es); + ExplainPropertyLong("Shared Read Blocks", usage->shared_blks_read, es); + ExplainPropertyLong("Shared Written Blocks", usage->shared_blks_written, es); + ExplainPropertyLong("Local Hit Blocks", usage->local_blks_hit, es); + ExplainPropertyLong("Local Read Blocks", usage->local_blks_read, es); + ExplainPropertyLong("Local Written Blocks", usage->local_blks_written, es); + ExplainPropertyLong("Temp Read Blocks", usage->temp_blks_read, es); + ExplainPropertyLong("Temp Written Blocks", usage->temp_blks_written, es); + } + } + /* Get ready to display the child plans */ haschildren = plan->initPlan || outerPlan(plan) || diff --git a/src/backend/commands/tablecmds.c b/src/backend/commands/tablecmds.c index 2344b79547..d7b6d9bc2e 100644 --- a/src/backend/commands/tablecmds.c +++ b/src/backend/commands/tablecmds.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/commands/tablecmds.c,v 1.309 2009/12/11 03:34:55 itagaki Exp $ + * $PostgreSQL: pgsql/src/backend/commands/tablecmds.c,v 1.310 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -936,7 +936,7 @@ ExecuteTruncate(TruncateStmt *stmt) rel, 0, /* dummy rangetable index */ CMD_DELETE, /* don't need any index info */ - false); + 0); resultRelInfo++; } estate->es_result_relations = resultRelInfos; diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index ebb6d8ea82..25d26f8446 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -26,7 +26,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.337 2009/12/11 18:14:43 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/executor/execMain.c,v 1.338 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -180,7 +180,7 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) */ estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot); estate->es_crosscheck_snapshot = RegisterSnapshot(queryDesc->crosscheck_snapshot); - estate->es_instrument = queryDesc->doInstrument; + estate->es_instrument = queryDesc->instrument_options; /* * Initialize the plan state tree @@ -859,7 +859,7 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, Relation resultRelationDesc, Index resultRelationIndex, CmdType operation, - bool doInstrument) + int instrument_options) { /* * Check valid relkind ... parser and/or planner should have noticed this @@ -914,10 +914,8 @@ InitResultRelInfo(ResultRelInfo *resultRelInfo, palloc0(n * sizeof(FmgrInfo)); resultRelInfo->ri_TrigWhenExprs = (List **) palloc0(n * sizeof(List *)); - if (doInstrument) - resultRelInfo->ri_TrigInstrument = InstrAlloc(n); - else - resultRelInfo->ri_TrigInstrument = NULL; + if (instrument_options) + resultRelInfo->ri_TrigInstrument = InstrAlloc(n, instrument_options); } else { diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 21b973d3f8..ee867d9dde 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -12,7 +12,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.68 2009/10/12 18:10:41 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.69 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -321,7 +321,7 @@ ExecInitNode(Plan *node, EState *estate, int eflags) /* Set up instrumentation for this node if requested */ if (estate->es_instrument) - result->instrument = InstrAlloc(1); + result->instrument = InstrAlloc(1, estate->es_instrument); return result; } diff --git a/src/backend/executor/functions.c b/src/backend/executor/functions.c index 7a9c319c7b..8ac98236ec 100644 --- a/src/backend/executor/functions.c +++ b/src/backend/executor/functions.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/executor/functions.c,v 1.137 2009/12/14 02:15:51 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/executor/functions.c,v 1.138 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -414,7 +414,7 @@ postquel_start(execution_state *es, SQLFunctionCachePtr fcache) fcache->src, snapshot, InvalidSnapshot, dest, - fcache->paramLI, false); + fcache->paramLI, 0); else es->qd = CreateUtilityQueryDesc(es->stmt, fcache->src, diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index eeac0d0d95..cd76698ea2 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -7,7 +7,7 @@ * Copyright (c) 2001-2009, PostgreSQL Global Development Group * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.22 2009/01/01 17:23:41 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.23 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -17,14 +17,28 @@ #include "executor/instrument.h" +BufferUsage pgBufferUsage; + +static void BufferUsageAccumDiff(BufferUsage *dst, + const BufferUsage *add, const BufferUsage *sub); /* Allocate new instrumentation structure(s) */ Instrumentation * -InstrAlloc(int n) +InstrAlloc(int n, int instrument_options) { - Instrumentation *instr = palloc0(n * sizeof(Instrumentation)); + Instrumentation *instr; + + /* timer is always required for now */ + Assert(instrument_options & INSTRUMENT_TIMER); - /* we don't need to do any initialization except zero 'em */ + instr = palloc0(n * sizeof(Instrumentation)); + if (instrument_options & INSTRUMENT_BUFFERS) + { + int i; + + for (i = 0; i < n; i++) + instr[i].needs_bufusage = true; + } return instr; } @@ -37,6 +51,10 @@ InstrStartNode(Instrumentation *instr) INSTR_TIME_SET_CURRENT(instr->starttime); else elog(DEBUG2, "InstrStartNode called twice in a row"); + + /* initialize buffer usage per plan node */ + if (instr->needs_bufusage) + instr->bufusage_start = pgBufferUsage; } /* Exit from a plan node */ @@ -59,6 +77,11 @@ InstrStopNode(Instrumentation *instr, double nTuples) INSTR_TIME_SET_ZERO(instr->starttime); + /* Adds delta of buffer usage to node's count. */ + if (instr->needs_bufusage) + BufferUsageAccumDiff(&instr->bufusage, + &pgBufferUsage, &instr->bufusage_start); + /* Is this the first tuple of this cycle? */ if (!instr->running) { @@ -95,3 +118,19 @@ InstrEndLoop(Instrumentation *instr) instr->firsttuple = 0; instr->tuplecount = 0; } + +static void +BufferUsageAccumDiff(BufferUsage *dst, + const BufferUsage *add, + const BufferUsage *sub) +{ + /* dst += add - sub */ + dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit; + dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read; + dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written; + dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit; + dst->local_blks_read += add->local_blks_read - sub->local_blks_read; + dst->local_blks_written += add->local_blks_written - sub->local_blks_written; + dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read; + dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written; +} diff --git a/src/backend/executor/spi.c b/src/backend/executor/spi.c index fcea0a1e62..09644950c1 100644 --- a/src/backend/executor/spi.c +++ b/src/backend/executor/spi.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.211 2009/11/04 22:26:06 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.212 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -1908,7 +1908,7 @@ _SPI_execute_plan(SPIPlanPtr plan, ParamListInfo paramLI, plansource->query_string, snap, crosscheck_snapshot, dest, - paramLI, false); + paramLI, 0); res = _SPI_pquery(qdesc, fire_triggers, canSetTag ? tcount : 0); FreeQueryDesc(qdesc); diff --git a/src/backend/storage/buffer/buf_init.c b/src/backend/storage/buffer/buf_init.c index 2f20d96f09..53a3b2fd6c 100644 --- a/src/backend/storage/buffer/buf_init.c +++ b/src/backend/storage/buffer/buf_init.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/buffer/buf_init.c,v 1.82 2009/01/01 17:23:47 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/storage/buffer/buf_init.c,v 1.83 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -22,16 +22,6 @@ BufferDesc *BufferDescriptors; char *BufferBlocks; int32 *PrivateRefCount; -/* statistics counters */ -long int ReadBufferCount; -long int ReadLocalBufferCount; -long int BufferHitCount; -long int LocalBufferHitCount; -long int BufferFlushCount; -long int LocalBufferFlushCount; -long int BufFileReadCount; -long int BufFileWriteCount; - /* * Data Structures: diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index be4c86bd38..315493ad2a 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.252 2009/06/11 14:49:01 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/storage/buffer/bufmgr.c,v 1.253 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -34,6 +34,7 @@ #include #include "catalog/catalog.h" +#include "executor/instrument.h" #include "miscadmin.h" #include "pg_trace.h" #include "pgstat.h" @@ -300,22 +301,23 @@ ReadBuffer_common(SMgrRelation smgr, bool isLocalBuf, ForkNumber forkNum, if (isLocalBuf) { - ReadLocalBufferCount++; bufHdr = LocalBufferAlloc(smgr, forkNum, blockNum, &found); if (found) - LocalBufferHitCount++; + pgBufferUsage.local_blks_hit++; + else + pgBufferUsage.local_blks_read++; } else { - ReadBufferCount++; - /* * lookup the buffer. IO_IN_PROGRESS is set if the requested block is * not currently in memory. */ bufHdr = BufferAlloc(smgr, forkNum, blockNum, strategy, &found); if (found) - BufferHitCount++; + pgBufferUsage.shared_blks_hit++; + else + pgBufferUsage.shared_blks_read++; } /* At this point we do NOT hold any locks. */ @@ -1610,54 +1612,6 @@ SyncOneBuffer(int buf_id, bool skip_recently_used) } -/* - * Return a palloc'd string containing buffer usage statistics. - */ -char * -ShowBufferUsage(void) -{ - StringInfoData str; - float hitrate; - float localhitrate; - - initStringInfo(&str); - - if (ReadBufferCount == 0) - hitrate = 0.0; - else - hitrate = (float) BufferHitCount *100.0 / ReadBufferCount; - - if (ReadLocalBufferCount == 0) - localhitrate = 0.0; - else - localhitrate = (float) LocalBufferHitCount *100.0 / ReadLocalBufferCount; - - appendStringInfo(&str, - "!\tShared blocks: %10ld read, %10ld written, buffer hit rate = %.2f%%\n", - ReadBufferCount - BufferHitCount, BufferFlushCount, hitrate); - appendStringInfo(&str, - "!\tLocal blocks: %10ld read, %10ld written, buffer hit rate = %.2f%%\n", - ReadLocalBufferCount - LocalBufferHitCount, LocalBufferFlushCount, localhitrate); - appendStringInfo(&str, - "!\tDirect blocks: %10ld read, %10ld written\n", - BufFileReadCount, BufFileWriteCount); - - return str.data; -} - -void -ResetBufferUsage(void) -{ - BufferHitCount = 0; - ReadBufferCount = 0; - BufferFlushCount = 0; - LocalBufferHitCount = 0; - ReadLocalBufferCount = 0; - LocalBufferFlushCount = 0; - BufFileReadCount = 0; - BufFileWriteCount = 0; -} - /* * AtEOXact_Buffers - clean up at end of transaction. * @@ -1916,7 +1870,7 @@ FlushBuffer(volatile BufferDesc *buf, SMgrRelation reln) (char *) BufHdrGetBlock(buf), false); - BufferFlushCount++; + pgBufferUsage.shared_blks_written++; /* * Mark the buffer as clean (unless BM_JUST_DIRTIED has become set) and diff --git a/src/backend/storage/buffer/localbuf.c b/src/backend/storage/buffer/localbuf.c index 3caa42a1a6..10e5025cf8 100644 --- a/src/backend/storage/buffer/localbuf.c +++ b/src/backend/storage/buffer/localbuf.c @@ -9,13 +9,14 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/buffer/localbuf.c,v 1.87 2009/06/11 14:49:01 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/storage/buffer/localbuf.c,v 1.88 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ #include "postgres.h" #include "catalog/catalog.h" +#include "executor/instrument.h" #include "storage/buf_internals.h" #include "storage/bufmgr.h" #include "storage/smgr.h" @@ -209,7 +210,7 @@ LocalBufferAlloc(SMgrRelation smgr, ForkNumber forkNum, BlockNumber blockNum, /* Mark not-dirty now in case we error out below */ bufHdr->flags &= ~BM_DIRTY; - LocalBufferFlushCount++; + pgBufferUsage.local_blks_written++; } /* diff --git a/src/backend/storage/file/buffile.c b/src/backend/storage/file/buffile.c index 9516c88acd..b5806c5980 100644 --- a/src/backend/storage/file/buffile.c +++ b/src/backend/storage/file/buffile.c @@ -7,7 +7,7 @@ * Portions Copyright (c) 1994, Regents of the University of California * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/storage/file/buffile.c,v 1.34 2009/06/11 14:49:01 momjian Exp $ + * $PostgreSQL: pgsql/src/backend/storage/file/buffile.c,v 1.35 2009/12/15 04:57:47 rhaas Exp $ * * NOTES: * @@ -34,6 +34,7 @@ #include "postgres.h" +#include "executor/instrument.h" #include "storage/fd.h" #include "storage/buffile.h" #include "storage/buf_internals.h" @@ -240,7 +241,7 @@ BufFileLoadBuffer(BufFile *file) file->offsets[file->curFile] += file->nbytes; /* we choose not to advance curOffset here */ - BufFileReadCount++; + pgBufferUsage.temp_blks_read++; } /* @@ -304,7 +305,7 @@ BufFileDumpBuffer(BufFile *file) file->curOffset += bytestowrite; wpos += bytestowrite; - BufFileWriteCount++; + pgBufferUsage.temp_blks_written++; } file->dirty = false; diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index b6a892a30f..71ae42dab7 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.575 2009/11/04 22:26:06 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.576 2009/12/15 04:57:47 rhaas Exp $ * * NOTES * this is the "main" module of the postgres backend and @@ -3901,7 +3901,6 @@ ResetUsage(void) { getrusage(RUSAGE_SELF, &Save_r); gettimeofday(&Save_t, NULL); - ResetBufferUsage(); } void @@ -3912,7 +3911,6 @@ ShowUsage(const char *title) sys; struct timeval elapse_t; struct rusage r; - char *bufusage; getrusage(RUSAGE_SELF, &r); gettimeofday(&elapse_t, NULL); @@ -3986,10 +3984,6 @@ ShowUsage(const char *title) r.ru_nvcsw, r.ru_nivcsw); #endif /* HAVE_GETRUSAGE */ - bufusage = ShowBufferUsage(); - appendStringInfo(&str, "! buffer usage stats:\n%s", bufusage); - pfree(bufusage); - /* remove trailing newline */ if (str.data[str.len - 1] == '\n') str.data[--str.len] = '\0'; diff --git a/src/backend/tcop/pquery.c b/src/backend/tcop/pquery.c index f07bb49b53..aabaa9edf3 100644 --- a/src/backend/tcop/pquery.c +++ b/src/backend/tcop/pquery.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/tcop/pquery.c,v 1.132 2009/10/10 01:43:49 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/tcop/pquery.c,v 1.133 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -67,7 +67,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt, Snapshot crosscheck_snapshot, DestReceiver *dest, ParamListInfo params, - bool doInstrument) + int instrument_options) { QueryDesc *qd = (QueryDesc *) palloc(sizeof(QueryDesc)); @@ -80,7 +80,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt, qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot); qd->dest = dest; /* output dest */ qd->params = params; /* parameter values passed into query */ - qd->doInstrument = doInstrument; /* instrumentation wanted? */ + qd->instrument_options = instrument_options; /* instrumentation wanted? */ /* null these fields until set by ExecutorStart */ qd->tupDesc = NULL; @@ -111,7 +111,7 @@ CreateUtilityQueryDesc(Node *utilitystmt, qd->crosscheck_snapshot = InvalidSnapshot; /* RI check snapshot */ qd->dest = dest; /* output dest */ qd->params = params; /* parameter values passed into query */ - qd->doInstrument = false; /* uninteresting for utilities */ + qd->instrument_options = false; /* uninteresting for utilities */ /* null these fields until set by ExecutorStart */ qd->tupDesc = NULL; @@ -178,7 +178,7 @@ ProcessQuery(PlannedStmt *plan, */ queryDesc = CreateQueryDesc(plan, sourceText, GetActiveSnapshot(), InvalidSnapshot, - dest, params, false); + dest, params, 0); /* * Set up to collect AFTER triggers @@ -515,7 +515,7 @@ PortalStart(Portal portal, ParamListInfo params, Snapshot snapshot) InvalidSnapshot, None_Receiver, params, - false); + 0); /* * We do *not* call AfterTriggerBeginQuery() here. We assume diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 75b5ed3d3c..d0b4c15e2c 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -6,7 +6,7 @@ * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group * Portions Copyright (c) 1994-5, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/commands/explain.h,v 1.43 2009/12/12 00:35:34 rhaas Exp $ + * $PostgreSQL: pgsql/src/include/commands/explain.h,v 1.44 2009/12/15 04:57:47 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -30,6 +30,7 @@ typedef struct ExplainState bool verbose; /* be verbose */ bool analyze; /* print actual times */ bool costs; /* print costs */ + bool buffers; /* print buffer usage */ ExplainFormat format; /* output format */ /* other states */ PlannedStmt *pstmt; /* top of plan */ diff --git a/src/include/executor/execdesc.h b/src/include/executor/execdesc.h index 9682c4b73a..46df1bf6bd 100644 --- a/src/include/executor/execdesc.h +++ b/src/include/executor/execdesc.h @@ -8,7 +8,7 @@ * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/executor/execdesc.h,v 1.40 2009/01/02 20:42:00 tgl Exp $ + * $PostgreSQL: pgsql/src/include/executor/execdesc.h,v 1.41 2009/12/15 04:57:48 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -42,7 +42,7 @@ typedef struct QueryDesc Snapshot crosscheck_snapshot; /* crosscheck for RI update/delete */ DestReceiver *dest; /* the destination for tuple output */ ParamListInfo params; /* param values being passed in */ - bool doInstrument; /* TRUE requests runtime instrumentation */ + int instrument_options; /* OR of InstrumentOption flags */ /* These fields are set by ExecutorStart */ TupleDesc tupDesc; /* descriptor for result tuples */ @@ -60,7 +60,7 @@ extern QueryDesc *CreateQueryDesc(PlannedStmt *plannedstmt, Snapshot crosscheck_snapshot, DestReceiver *dest, ParamListInfo params, - bool doInstrument); + int instrument_options); extern QueryDesc *CreateUtilityQueryDesc(Node *utilitystmt, const char *sourceText, diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h index 76c075f75f..98f8063601 100644 --- a/src/include/executor/executor.h +++ b/src/include/executor/executor.h @@ -7,7 +7,7 @@ * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/executor/executor.h,v 1.164 2009/12/07 05:22:23 tgl Exp $ + * $PostgreSQL: pgsql/src/include/executor/executor.h,v 1.165 2009/12/15 04:57:48 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -161,7 +161,7 @@ extern void InitResultRelInfo(ResultRelInfo *resultRelInfo, Relation resultRelationDesc, Index resultRelationIndex, CmdType operation, - bool doInstrument); + int instrument_options); extern ResultRelInfo *ExecGetTriggerResultRel(EState *estate, Oid relid); extern bool ExecContextForcesOids(PlanState *planstate, bool *hasoids); extern void ExecConstraints(ResultRelInfo *resultRelInfo, diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 1ae6eebe8d..5eea68d2fe 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -6,7 +6,7 @@ * * Copyright (c) 2001-2009, PostgreSQL Global Development Group * - * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.20 2009/01/01 17:23:59 momjian Exp $ + * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.21 2009/12/15 04:57:48 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -16,22 +16,46 @@ #include "portability/instr_time.h" +typedef struct BufferUsage +{ + long shared_blks_hit; /* # of shared buffer hits */ + long shared_blks_read; /* # of shared disk blocks read */ + long shared_blks_written; /* # of shared disk blocks written */ + long local_blks_hit; /* # of local buffer hits */ + long local_blks_read; /* # of local disk blocks read */ + long local_blks_written; /* # of local disk blocks written */ + long temp_blks_read; /* # of temp blocks read */ + long temp_blks_written; /* # of temp blocks written */ +} BufferUsage; + +typedef enum InstrumentOption +{ + INSTRUMENT_TIMER = 1 << 0, /* needs timer */ + INSTRUMENT_BUFFERS = 1 << 1, /* needs buffer usage */ + INSTRUMENT_ALL = 0x7FFFFFFF +} InstrumentOption; + typedef struct Instrumentation { /* Info about current plan cycle: */ bool running; /* TRUE if we've completed first tuple */ + bool needs_bufusage; /* TRUE if we need buffer usage */ instr_time starttime; /* Start time of current iteration of node */ instr_time counter; /* Accumulated runtime for this node */ double firsttuple; /* Time for first tuple of this cycle */ double tuplecount; /* Tuples emitted so far this cycle */ + BufferUsage bufusage_start; /* Buffer usage at start */ /* Accumulated statistics across all completed cycles: */ double startup; /* Total startup time (in seconds) */ double total; /* Total total time (in seconds) */ double ntuples; /* Total tuples produced */ double nloops; /* # of run cycles for this node */ + BufferUsage bufusage; /* Total buffer usage */ } Instrumentation; -extern Instrumentation *InstrAlloc(int n); +extern BufferUsage pgBufferUsage; + +extern Instrumentation *InstrAlloc(int n, int instrument_options); extern void InstrStartNode(Instrumentation *instr); extern void InstrStopNode(Instrumentation *instr, double nTuples); extern void InstrEndLoop(Instrumentation *instr); diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index 7e4cfe9d71..ac11b496fc 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -7,7 +7,7 @@ * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/nodes/execnodes.h,v 1.213 2009/12/07 05:22:23 tgl Exp $ + * $PostgreSQL: pgsql/src/include/nodes/execnodes.h,v 1.214 2009/12/15 04:57:48 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -370,7 +370,7 @@ typedef struct EState uint32 es_processed; /* # of tuples processed */ Oid es_lastoid; /* last oid processed (by INSERT) */ - bool es_instrument; /* true requests runtime instrumentation */ + int es_instrument; /* OR of InstrumentOption flags */ bool es_select_into; /* true if doing SELECT INTO */ bool es_into_oids; /* true to generate OIDs in SELECT INTO */ diff --git a/src/include/storage/buf_internals.h b/src/include/storage/buf_internals.h index 7084343037..e38017e575 100644 --- a/src/include/storage/buf_internals.h +++ b/src/include/storage/buf_internals.h @@ -8,7 +8,7 @@ * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/storage/buf_internals.h,v 1.102 2009/06/11 14:49:12 momjian Exp $ + * $PostgreSQL: pgsql/src/include/storage/buf_internals.h,v 1.103 2009/12/15 04:57:48 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -173,16 +173,6 @@ extern PGDLLIMPORT BufferDesc *BufferDescriptors; /* in localbuf.c */ extern BufferDesc *LocalBufferDescriptors; -/* event counters in buf_init.c */ -extern long int ReadBufferCount; -extern long int ReadLocalBufferCount; -extern long int BufferHitCount; -extern long int LocalBufferHitCount; -extern long int BufferFlushCount; -extern long int LocalBufferFlushCount; -extern long int BufFileReadCount; -extern long int BufFileWriteCount; - /* * Internal routines: only called by bufmgr diff --git a/src/include/storage/bufmgr.h b/src/include/storage/bufmgr.h index af3562a79d..8fdb22f0fa 100644 --- a/src/include/storage/bufmgr.h +++ b/src/include/storage/bufmgr.h @@ -7,7 +7,7 @@ * Portions Copyright (c) 1996-2009, PostgreSQL Global Development Group * Portions Copyright (c) 1994, Regents of the University of California * - * $PostgreSQL: pgsql/src/include/storage/bufmgr.h,v 1.121 2009/06/11 14:49:12 momjian Exp $ + * $PostgreSQL: pgsql/src/include/storage/bufmgr.h,v 1.122 2009/12/15 04:57:48 rhaas Exp $ * *------------------------------------------------------------------------- */ @@ -173,8 +173,6 @@ extern Buffer ReleaseAndReadBuffer(Buffer buffer, Relation relation, extern void InitBufferPool(void); extern void InitBufferPoolAccess(void); extern void InitBufferPoolBackend(void); -extern char *ShowBufferUsage(void); -extern void ResetBufferUsage(void); extern void AtEOXact_Buffers(bool isCommit); extern void PrintBufferLeakWarning(Buffer buffer); extern void CheckPointBuffers(int flags); -- GitLab