Re: EXPLAIN BUFFERS

Hi Itagaki-san,

I'm reviewing your patch. Your patch is in good shape. It applies cleanly. All
of the things are built as intended (including the two contrib modules). It
doesn't include docs but I wrote it. Basically, I produced another patch (that
are attached) correcting some minor gripes; docs are included too. The
comments are in-line.

> static bool auto_explain_log_analyze = false;
> static bool auto_explain_log_verbose = false;
> + static bool auto_explain_log_buffer = false;
Rename it to auto_explain_log_buffers. That's because I renamed the option for
plural form. See above.

> es.verbose = auto_explain_log_verbose;
> + es.buffer = auto_explain_log_buffer;
Change this check to look at es.analyze too. So the es.buffers will only be
enabled iif the es.analyze is enabled too.

> + /* Build a tuple descriptor for our result type */
> + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE)
> + elog(ERROR, "return type must be a row type");
> +
> per_query_ctx = rsinfo->econtext->ecxt_per_query_memory;
> oldcontext = MemoryContextSwitchTo(per_query_ctx);
>
> ! tupdesc = CreateTupleDescCopy(tupdesc);
>
Out of curiosity, any reason for this change?

> else if (strcmp(opt->defname, "costs") == 0)
> es.costs = defGetBoolean(opt);
> + else if (strcmp(opt->defname, "buffer") == 0)
> + es.buffer = defGetBoolean(opt);
I decided to change "buffer" to "buffers". That's because we already have
"costs" and the statistics will not be about one kind of buffer so plural form
sounds more natural.

> + if (es->format == EXPLAIN_FORMAT_TEXT)
> + {
> + appendStringInfo(es->str, " (gets=%ld reads=%ld temp=%ld)",
> + num_gets, num_reads, num_temp);
Rename "gets" and "reads" to "hit" and "read". Maybe we could prefix it with
"buf_" or something else.

Rename "num_gets" and "num_reads" to "num_hit" and "num_read". The later
terminology is used all over the code.

> + }
> + else
> + {
> + ExplainPropertyLong("Buffer Gets", num_gets, es);
> + ExplainPropertyLong("Buffer Reads", num_reads, es);
> + ExplainPropertyLong("Buffer Temp", num_temp, es);
I didn't like these terminologies. I came up with "Hit Buffers", "Read
Buffers", and "Temp Buffers". I confess that I don't like the last ones.
"Read Buffers"? We're reading from disk blocks. "Read Blocks"? "Read Disk
Blocks"? "Read Data Blocks"?
"Temp Buffers"? It could be temporary sort files, hash files (?), or temporary
relations. "Hit Local Buffers"? "Local Buffers"? "Hit Temp Buffers"?

> #include "parser/parsetree.h"
> + #include "storage/buf_internals.h"
It's not used. Removed.

> + CurrentInstrument = instr->prev;
> + }
> + else
> + elog(WARNING, "Instrumentation stack is broken");
WARNING? I changed it to DEBUG2 and return immediately (as it does some lines
of code above).

> + /* for log_[parser|planner|executor|statement]_stats */
> + static long GlobalReadBufferCount;
> + static long GlobalReadLocalBufferCount;
> + static long GlobalBufferHitCount;
> + static long GlobalLocalBufferHitCount;
> + static long GlobalBufferFlushCount;
> + static long GlobalLocalBufferFlushCount;
> + static long GlobalBufFileReadCount;
> + static long GlobalBufFileWriteCount;
> +
I'm not sure if this is the right place for these counters. Maybe we should
put it in buf_init.c. Ideas?

> bool costs; /* print costs */
> + bool buffer; /* print buffer stats */
Rename it to "buffers".

> + /* Buffer usage */
> + long buffer_gets; /* # of buffer reads */
> + long buffer_reads; /* # of disk reads */
> + long buffer_temp; /* # of temp file reads */
Rename them to "buffers_hit", "buffers_read", and "buffers_temp".

I didn't test this changes with "big" queries because I don't have some at
hand right now. Also, I didn't notice any slowdowns caused by the patch.
Comments? If none, it is ready for a committer.

--
Euler Taveira de Oliveira
http://www.timbira.com/

Euler Taveira de Oliveira <euler(at)timbira(dot)com> wrote:

> I'm reviewing your patch. Your patch is in good shape. It applies cleanly. All
> of the things are built as intended (including the two contrib modules). It
> doesn't include docs but I wrote it. Basically, I produced another patch (that
> are attached) correcting some minor gripes; docs are included too. The
> comments are in-line.

Thanks. Except choice of words, can I think the basic architecture of
the patch is ok? The codes to handle global variables like ReadBufferCount
and GlobalReadBufferCount could be rewrite in cleaner way if we could
drop supports of log_{parser|planner|executor|statement}_stats.

> > + /* Build a tuple descriptor for our result type */
> > + if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE)
> > + elog(ERROR, "return type must be a row type");
> > +
> > per_query_ctx = rsinfo->econtext->ecxt_per_query_memory;
> > oldcontext = MemoryContextSwitchTo(per_query_ctx);
> >
> > ! tupdesc = CreateTupleDescCopy(tupdesc);
> >
> Out of curiosity, any reason for this change?

That's because the new code is cleaner, I think. Since the result tuple
type is defined in OUT parameters, we don't have to re-define the result
with CreateTemplateTupleDesc().

> > + appendStringInfo(es->str, " (gets=%ld reads=%ld temp=%ld)",
> > + num_gets, num_reads, num_temp);
> Rename "gets" and "reads" to "hit" and "read". Maybe we could prefix it with
> "buf_" or something else.
>
> Rename "num_gets" and "num_reads" to "num_hit" and "num_read". The later
> terminology is used all over the code.

We should define the meanings of "get" and "hit" before rename them.
I'd like to propose the meanings as following:
* "get" : number of page access (= hit + read)
* "hit" : number of cache read (no disk read)
* "read" : number of disk read (= number of read() calls)

But there are some confusions in postgres; ReadBufferCount and
BufferHitCount are used for "get" and "hit", but "heap_blks_read"
and "heap_blks_hit" are used for "read" and "hit" in pg_statio_all_tables.
Can I rename ReadBufferCount to BufferGetCount? And which values should
we show in EXPLAIN and pg_stat_statements? (two of the three are enough)

> I didn't like these terminologies. I came up with "Hit Buffers", "Read
> Buffers", and "Temp Buffers". I confess that I don't like the last ones.
> "Read Buffers"? We're reading from disk blocks. "Read Blocks"? "Read Disk
> Blocks"? "Read Data Blocks"?
> "Temp Buffers"? It could be temporary sort files, hash files (?), or temporary
> relations. "Hit Local Buffers"? "Local Buffers"? "Hit Temp Buffers"?

I borrowed the terms "Buffer Gets" and "Buffer Reads" from STATSPACK report
in Oracle Database. But I'm willing to rename them if appropriate.
http://www.oracle.com/apps_benchmark/doc/awrrpt_20090325b_900.html#600

Presently "Temp Buffers" contains temporary sort files, hash files, and
materialized executor plan. Local buffer statistics for temp tables are
not included here but merged with shared buffer statistics. Are there
any better way to group them?

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Itagaki Takahiro escreveu:
> Thanks. Except choice of words, can I think the basic architecture of
> the patch is ok? The codes to handle global variables like ReadBufferCount
> and GlobalReadBufferCount could be rewrite in cleaner way if we could
> drop supports of log_{parser|planner|executor|statement}_stats.
>
Yes, it is. I'm afraid someone is relying on that piece of code. We can ask
people if it is ok to deprecated it; but it should be removed after 2 releases
or so. BTW, Isn't it make sense to move the Global* variables to buf_init.c,
is it?

> We should define the meanings of "get" and "hit" before rename them.
> I'd like to propose the meanings as following:
> * "get" : number of page access (= hit + read)
> * "hit" : number of cache read (no disk read)
> * "read" : number of disk read (= number of read() calls)
>
+1.

> But there are some confusions in postgres; ReadBufferCount and
> BufferHitCount are used for "get" and "hit", but "heap_blks_read"
> and "heap_blks_hit" are used for "read" and "hit" in pg_statio_all_tables.
I see. :(

> Can I rename ReadBufferCount to BufferGetCount? And which values should
> we show in EXPLAIN and pg_stat_statements? (two of the three are enough)
>
Do you want to include number of page access in the stats? If not, we don't
need to rename the variables for now (maybe a separate patch?). And IMHO we
should include "hit" and "read" because "get" is just a simple math.

> I borrowed the terms "Buffer Gets" and "Buffer Reads" from STATSPACK report
> in Oracle Database. But I'm willing to rename them if appropriate.
> http://www.oracle.com/apps_benchmark/doc/awrrpt_20090325b_900.html#600
>
Hmm... I don't have a strong opinion about those names as I said. So if you
want to revert the old names...

> Presently "Temp Buffers" contains temporary sort files, hash files, and
> materialized executor plan. Local buffer statistics for temp tables are
> not included here but merged with shared buffer statistics. Are there
> any better way to group them?
>
Are you sure? Looking at ReadBuffer_common() function I see an 'if
(isLocalBuf)' test.

As I said your patch is in good shape and if we solve those terminologies, it
is done for a committer.

Would you care to submit another patch if you want to do some modifications?

--
Euler Taveira de Oliveira
http://www.timbira.com/

Euler Taveira de Oliveira <euler(at)timbira(dot)com> writes:
> Itagaki Takahiro escreveu:
>> Thanks. Except choice of words, can I think the basic architecture of
>> the patch is ok? The codes to handle global variables like ReadBufferCount
>> and GlobalReadBufferCount could be rewrite in cleaner way if we could
>> drop supports of log_{parser|planner|executor|statement}_stats.
>>
> Yes, it is. I'm afraid someone is relying on that piece of code.

If we have a better substitute, I think there'd be nothing wrong with
removing those features. They were never anything but pretty crufty
anyway, and they are *not* a compatibility issue because applications
have no direct way to access those stats. However, you'd have to be
sure that the substitute covers all the use-cases for the old stats
... which strikes me as a lot more territory than this patch has
proposed to cover.

regards, tom lane

Euler Taveira de Oliveira <euler(at)timbira(dot)com> wrote:

> > But there are some confusions in postgres; ReadBufferCount and
> > BufferHitCount are used for "get" and "hit", but "heap_blks_read"
> > and "heap_blks_hit" are used for "read" and "hit" in pg_statio_all_tables.
> I see. :(

I fixed the confusions of get, hit and read in your patch.
long num_hit = ReadBufferCount + ReadLocalBufferCount;
long num_read = num_hit - BufferHitCount - LocalBufferHitCount;
should be
long num_get = ReadBufferCount + ReadLocalBufferCount;
long num_hit = BufferHitCount + LocalBufferHitCount;
long num_read = num_get - num_hit;

ReadBufferCount means "number of buffer access" :(

Patch attached.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Itagaki Takahiro escreveu:
> I fixed the confusions of get, hit and read in your patch.
>
Works for me. Will mark it ready for a committer.

PS> BTW, your patch (20091001112006(dot)9C36(dot)52131E4D(at)oss(dot)ntt(dot)co(dot)jp) doesn't seem
to be in archives.p.o. though I've received a copy from the server.

--
Euler Taveira de Oliveira
http://www.timbira.com/

Euler Taveira de Oliveira wrote:
> Itagaki Takahiro escreveu:
> > I fixed the confusions of get, hit and read in your patch.
> >
> Works for me. Will mark it ready for a committer.
>
> PS> BTW, your patch (20091001112006(dot)9C36(dot)52131E4D(at)oss(dot)ntt(dot)co(dot)jp) doesn't seem
> to be in archives.p.o. though I've received a copy from the server.

That's indeed very strange -- I have it locally and I wasn't CCed, so
Majordomo must have delivered it.

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Alvaro Herrera wrote:
> Euler Taveira de Oliveira wrote:
> > Itagaki Takahiro escreveu:
> > > I fixed the confusions of get, hit and read in your patch.
> > >
> > Works for me. Will mark it ready for a committer.
> >
> > PS> BTW, your patch (20091001112006(dot)9C36(dot)52131E4D(at)oss(dot)ntt(dot)co(dot)jp) doesn't seem
> > to be in archives.p.o. though I've received a copy from the server.
>
> That's indeed very strange -- I have it locally and I wasn't CCed, so
> Majordomo must have delivered it.

Something was wrong with last month's archive. For some reason it had
96000 files in that directory. I have rerun mhonarc on it and it has
normalized now (~2100 files).

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

On Wed, Sep 30, 2009 at 10:40 PM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
> Euler Taveira de Oliveira <euler(at)timbira(dot)com> wrote:
>
>> > But there are some confusions in postgres; ReadBufferCount and
>> > BufferHitCount are used for "get" and "hit", but "heap_blks_read"
>> > and "heap_blks_hit" are used for "read" and "hit" in pg_statio_all_tables.
>> I see. :(
>
> I fixed the confusions of get, hit and read in your patch.
>    long        num_hit = ReadBufferCount + ReadLocalBufferCount;
>    long        num_read = num_hit - BufferHitCount - LocalBufferHitCount;
> should be
>    long        num_get = ReadBufferCount + ReadLocalBufferCount;
>    long        num_hit = BufferHitCount + LocalBufferHitCount;
>    long        num_read = num_get - num_hit;
>
> ReadBufferCount means "number of buffer access" :(
>
> Patch attached.

I took a look at this today and I have a couple of comments. The
basic functionality looks useful, but I think the terminology is too
terse. Specific commens:

1. In the EXPLAIN output, I think that the buffers information should
be output on its own line, rather than appended to the line that
already contains costs and execution times. The current output
doesn't include the word "buffers" or "blocks" anywhere, which seems
to me to be a critical flaw. I would suggest something like "Blocks
Read: %ld Hit: %ld Temp Read: %ld\n". See the way we handle output
of sort type and space usage, for example.

2. Similarly, in pg_stat_statements, the Counters structure could
easily use the same names for the structure members that we already
use in e.g. pg_stat_database - blks_hit, blks_read, and, say,
blks_temp_read. In fact I tend to think we should stick with "blocks"
rather than "buffers" overall, for consistency with what the system
does elsewhere.

3. With respect to the doc changes in explain.sgml, we consistently
use "disk" rather than "disc" in the documentation; but it may not be
necessary to use that word at all, and I think the paragraph can be
tightened up a bit: "Include information on the number of blocks read,
the number of those that are hits (already in shared buffers and do
not need to be read in), and the number of those that are reads on
temporary, backend-local buffers. This parameter requires that the
<literal>ANALYZE</literal> parameter also be used. This parameter
defaults to <literal>FALSE</literal>".

4. "Instrumentation stack is broken" doesn't seem terribly helpful in
understanding what has gone wrong.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> 1. I would suggest something like "Blocks
> Read: %ld Hit: %ld Temp Read: %ld\n". See the way we handle output
> of sort type and space usage, for example.

I have some questions:
* Did you use single space and double spaces in your example intentionally?
* Should we use lower cases here?
* Can I use "temp" instead of "Temp Read" to shorten the name?

> 2. Similarly, in pg_stat_statements, the Counters structure could
> easily use the same names for the structure members that we already
> use in e.g. pg_stat_database - blks_hit, blks_read, and, say,
> blks_temp_read. In fact I tend to think we should stick with "blocks"
> rather than "buffers" overall, for consistency with what the system
> does elsewhere.

I agree to rename them into blks_*, but EXPLAIN (blocks) might be
misleading; EXPLAIN (buffer) can be interpreted as "buffer usage",
but normally we don't call it "block usage".

My suggestion is:
* EXPLAIN (buffers) prints (blocks read: %ld hit: %ld temp: %ld)
* auto_explain.log_buffers are not changed
* pg_stat_statements uses blks_hit and blks_read

> 4. "Instrumentation stack is broken" doesn't seem terribly helpful in
> understanding what has gone wrong.

This message is only for hackers and should not occur.
Assert() might be ok instead.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Sun, Oct 4, 2009 at 11:22 PM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
>> 1. I would suggest something like "Blocks
>> Read: %ld  Hit:  %ld  Temp Read: %ld\n".  See the way we handle output
>> of sort type and space usage, for example.
>
> I have some questions:
>  * Did you use single space and double spaces in your example intentionally?

No, that was unintentional.

>  * Should we use lower cases here?

No. We don't anywhere else in explain.c.

>  * Can I use "temp" instead of "Temp Read" to shorten the name?

I can't tell what that means without reading the source code. I think
clarity should take precedence over brevity.

>> 2. Similarly, in pg_stat_statements, the Counters structure could
>> easily use the same names for the structure members that we already
>> use in e.g. pg_stat_database - blks_hit, blks_read, and, say,
>> blks_temp_read.  In fact I tend to think we should stick with "blocks"
>> rather than "buffers" overall, for consistency with what the system
>> does elsewhere.
>
> I agree to rename them into blks_*, but EXPLAIN (blocks) might be
> misleading; EXPLAIN (buffer) can be interpreted as "buffer usage",
> but normally we don't call it "block usage".
>
> My suggestion is:
>    * EXPLAIN (buffers) prints (blocks read: %ld hit: %ld temp: %ld)
>    * auto_explain.log_buffers are not changed
>    * pg_stat_statements uses blks_hit and blks_read

I agree.

>> 4. "Instrumentation stack is broken" doesn't seem terribly helpful in
>> understanding what has gone wrong.
>
> This message is only for hackers and should not occur.
> Assert() might be ok instead.

Hmm, I think I like the idea of an Assert(). Logging a cryptic
message at DEBUG2 doesn't seem sufficient for a can't-happen condition
that probably indicates a serious bug in the code.

...Robert

Here is an update version of buffer usage patch.
* All buffers_* and bufs_* are renamed to blks_*.
* 'disc' => 'disk' in documentation
* Replace debug-log to Assert().
* Fix a bug in ResetLocalBufferUsage(). log_xxx_stats had not worked.

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> > ?* Can I use "temp" instead of "Temp Read" to shorten the name?
> I can't tell what that means without reading the source code. I think
> clarity should take precedence over brevity.

I used temp_blks_read because we have idx_blks_read in pg_statio_xxx.

=# \d pg_stat_statements
View "public.pg_stat_statements"
Column | Type | Modifiers
----------------+------------------+-----------
userid | oid |
dbid | oid |
query | text |
calls | bigint |
total_time | double precision |
rows | bigint |
blks_hit | bigint |
blks_read | bigint |
temp_blks_read | bigint |

=# SET work_mem = '1MB';
=# EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM pgbench_accounts ORDER BY bid;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------
Sort (cost=21913.32..22163.33 rows=100005 width=97) (actual time=81.345..99.054 rows=100000 loops=1)
Sort Key: bid
Sort Method: external sort Disk: 10472kB
Blocks Hit: 0 Read: 0 Temp Read: 1309
-> Seq Scan on pgbench_accounts (cost=0.00..2667.05 rows=100005 width=97) (actual time=0.018..23.129 rows=100000 loops=1)
Blocks Hit: 74 Read: 1694 Temp Read: 0
Total runtime: 105.238 ms
(7 rows)

=# SET work_mem = '18MB';
=# EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM pgbench_accounts ORDER BY bid;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------
Sort (cost=10972.32..11222.33 rows=100005 width=97) (actual time=35.437..43.069 rows=100000 loops=1)
Sort Key: bid
Sort Method: quicksort Memory: 17916kB
Blocks Hit: 0 Read: 0 Temp Read: 0
-> Seq Scan on pgbench_accounts (cost=0.00..2667.05 rows=100005 width=97) (actual time=0.028..15.030 rows=100000 loops=1)
Blocks Hit: 32 Read: 1635 Temp Read: 0
Total runtime: 52.026 ms
(7 rows)

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Itagaki Takahiro <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
> Here is an update version of buffer usage patch.

I started to look at this patch, and I have a few comments:

1. I was expecting this patch to get rid of ShowBufferUsage() and friends
altogether, instead of adding yet more static counters to support them.
Isn't that stuff pretty well superseded by having EXPLAIN support?

2. I do not understand the stuff with propagating counts into the top
instrumentation node. That seems like it's going to double-count those
counts. In any case it is 100% inconsistent to propagate only buffer
counts that way and not any other resource usage. I think you should
drop the TopInstrument variable and the logic that propagates counts up.

3. I don't believe that you've sufficiently considered the problem of
restoring the previous value of CurrentInstrument after an error. It is
not at all adequate to do it in postgres.c; consider subtransactions
for example. However, so far as I can see that variable is useless
anyway. Couldn't you just drop both that and the "prev" link?
(If you keep TopInstrument then the same objection applies to it.)

4. I don't believe this counting scheme works, except in the special
case where all buffer access happens in leaf plan nodes (which might be
enough if it weren't for Sort, Materialize, Hash, etc). It looks to
me like counts will be transferred into the instrumentation node for
the next plan node to stop execution, which could be a descendant of
the node that really ought to get charged.

You could deal with #4 by having the low-level I/O routines accumulate
counts directly into *CurrentInstrument and not have static I/O counters
at all, but then you'd have to contend with fixing #3 properly instead
of just eliminating that global variable. It might be better to add a
"start" field to struct Instrumentation for each counter, and do
something like this:
* StartNode copies static counter into start field
* StopNode computes delta = static counter - start field,
then adds delta to node's count and resets counter to start
The reason for the reset is so that the I/O isn't double counted by
parent nodes. If you wanted buffer I/O to be charged to the node
causing it *and* to all parent nodes, which would be more consistent
with the way we charge CPU time, then don't do the reset. Offhand
though that seems to me like it'd be more surprising than useful.

regards, tom lane

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> 2. I do not understand the stuff with propagating counts into the top
> instrumentation node. That seems like it's going to double-count those
> counts. In any case it is 100% inconsistent to propagate only buffer
> counts that way and not any other resource usage. I think you should
> drop the TopInstrument variable and the logic that propagates counts up.

It is required by contrib/pg_stat_statements. EXPLAIN wants per-node
accumulation, but pg_stat_statements wants the total number.

Is it enough to add a PG_TRY block to standard_ExecutorRun() to
cleanup TopInstrument on error? I'm working on your other comments,
but I cannot remove TopInstrument for pg_state_statements.

I considerd other approaches, but all of them require node-dependent
routines; for example, adding a function to walk through a plan tree
and accumulate instrumentations in it at pg_stat_statements. But it is
hard to be maintained on executor nodes changes. Are there any better idea?

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Itagaki Takahiro <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> 2. I do not understand the stuff with propagating counts into the top
>> instrumentation node.

> It is required by contrib/pg_stat_statements. EXPLAIN wants per-node
> accumulation, but pg_stat_statements wants the total number.

Well, you need to find another way or risk getting the patch rejected
altogether. Those global variables are the weakest part of the whole
design, and I'm not going to commit a patch that destabilizes the entire
system for the sake of a debatable "requirement" of a contrib module.

If you went with the alternative definition I suggested (don't reset the
static counters, so that every node includes its children's counts) then
the behavior you want would fall out automatically. Or, at the price of
running both resettable and non-resettable static counters, you could
have pg_stat_statements obtain totals that are independent of any
particular instrumentation node.

regards, tom lane

On Wed, Oct 14, 2009 at 9:56 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Itagaki Takahiro <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
>> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>>> 2. I do not understand the stuff with propagating counts into the top
>>> instrumentation node.
>
>> It is required by contrib/pg_stat_statements. EXPLAIN wants per-node
>> accumulation, but pg_stat_statements wants the total number.
>
> Well, you need to find another way or risk getting the patch rejected
> altogether.  Those global variables are the weakest part of the whole
> design, and I'm not going to commit a patch that destabilizes the entire
> system for the sake of a debatable "requirement" of a contrib module.
>
> If you went with the alternative definition I suggested (don't reset the
> static counters, so that every node includes its children's counts) then
> the behavior you want would fall out automatically.  Or, at the price of
> running both resettable and non-resettable static counters, you could
> have pg_stat_statements obtain totals that are independent of any
> particular instrumentation node.

I am marking this patch as Returned with Feedback. I hope that it
will be resubmitted for a future CommitFest, because I think this
could be pretty interesting feature.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> > Well, you need to find another way or risk getting the patch rejected
> > altogether. ?Those global variables are the weakest part of the whole
> > design, and I'm not going to commit a patch that destabilizes the entire
> > system for the sake of a debatable "requirement" of a contrib module.
>
> I am marking this patch as Returned with Feedback. I hope that it
> will be resubmitted for a future CommitFest, because I think this
> could be pretty interesting feature.

Ok, I'll reconsider them and re-submit patches for the next commitfest.
Maybe I need to split the patch into EXPLAIN-part and contrib-part.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

2009/10/14 Itagaki Takahiro <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp>:
>
> Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
>> > Well, you need to find another way or risk getting the patch rejected
>> > altogether. ?Those global variables are the weakest part of the whole
>> > design, and I'm not going to commit a patch that destabilizes the entire
>> > system for the sake of a debatable "requirement" of a contrib module.
>>
>> I am marking this patch as Returned with Feedback.  I hope that it
>> will be resubmitted for a future CommitFest, because I think this
>> could be pretty interesting feature.
>
> Ok, I'll reconsider them and re-submit patches for the next commitfest.
> Maybe I need to split the patch into EXPLAIN-part and contrib-part.

My (limited) experience is that it's usually better to get something
incremental committed, even if it's not what you really want. You can
always take another crack at the remaining issues later, but if the
whole patch gets shot down then you are out of luck.

In this case, I think that the auto_explain changes out to be part of
the same patch as the core EXPLAIN changes, but if the
pg_stat_statement stuff is severable it might make sense to push that
off until later.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> My (limited) experience is that it's usually better to get something
> incremental committed, even if it's not what you really want. You can
> always take another crack at the remaining issues later, but if the
> whole patch gets shot down then you are out of luck.

Yeah, that makes sense. But the partial change should also be
a "long-term solution" ;-). It is hard to determine whether
the partial change is a good solution until the whole features
works as expected (at least partially).

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Wed, Oct 14, 2009 at 9:38 PM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
> Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
>> My (limited) experience is that it's usually better to get something
>> incremental committed, even if it's not what you really want.  You can
>> always take another crack at the remaining issues later, but if the
>> whole patch gets shot down then you are out of luck.
>
> Yeah, that makes sense. But the partial change should also be
> a "long-term solution" ;-). It is hard to determine whether
> the partial change is a good solution until the whole features
> works as expected (at least partially).

Well, that's an indication that you've chosen too small a piece. But
I don't really believe that a change that affects only core EXPLAIN
and auto_explain is too small a piece to be independently useful. If
it is, the whole feature is probably badly conceived in the first
place...

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> In this case, I think that the auto_explain changes out to be part of
> the same patch as the core EXPLAIN changes

Here is a rewritten patch to add EXPLAIN (ANALYZE, BUFFERS) and
support for it by contrib/auto_explain. I removed pg_stat_statements
support from the patch for now.

I modifed heavily in buffer statistics conters; These counters are
put all together into struct BufferUsage. The struct is also used in
struct Instrumentation. The global buffer usage counters are saved
into 'bufusage_start' field at the InstrStartNode(), and accumulated
into 'bufusage' field and global counters are reset at InstrStopNode().

EXPLAIN BUFFERS only shows 'hit', 'read' and 'temp read' in text format
to fit in display, but xml or json format contains all of them.

I removed ShowBufferUsage() because we can retrieve the same information
from xml or json explain output, but the patch does not drop
log_statement_stats variable families nor ShowUsage() functions.
We could also remove all of them if no one use them at all.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Thu, Oct 15, 2009 at 7:29 AM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
> EXPLAIN BUFFERS only shows 'hit', 'read' and 'temp read' in text format
> to fit in display, but xml or json format contains all of them.

I was very careful when I submitted the machine-readable explain patch
to make sure that the choice of which information was displayed was
independent of the format, and I think that we should stick with that.
If you want we could have 'buffers terse' and 'buffers detail' but I
don't think we should force JSON/XML on people who want to see that
information.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Thu, Oct 15, 2009 at 7:29 AM, Itagaki Takahiro
> <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>> EXPLAIN BUFFERS only shows 'hit', 'read' and 'temp read' in text format
>> to fit in display, but xml or json format contains all of them.

> I was very careful when I submitted the machine-readable explain patch
> to make sure that the choice of which information was displayed was
> independent of the format, and I think that we should stick with that.

I thought one of the main purposes of adding the machine-readable
formats was to allow inclusion of information that we thought too
verbose for the human-readable format. Whether this info falls into
that category remains to be seen, but I don't agree with the premise
that the information content must always be exactly the same.

FWIW, the patch's output as it stood a few days ago (one extra line per
node, conditional on a BUFFERS option) did seem perfectly reasonable to
me, and I don't see the reason to change that format now.

regards, tom lane

On Thu, Oct 15, 2009 at 11:06 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> On Thu, Oct 15, 2009 at 7:29 AM, Itagaki Takahiro
>> <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>>> EXPLAIN BUFFERS only shows 'hit', 'read' and 'temp read' in text format
>>> to fit in display, but xml or json format contains all of them.
>
>> I was very careful when I submitted the machine-readable explain patch
>> to make sure that the choice of which information was displayed was
>> independent of the format, and I think that we should stick with that.
>
> I thought one of the main purposes of adding the machine-readable
> formats was to allow inclusion of information that we thought too
> verbose for the human-readable format.  Whether this info falls into
> that category remains to be seen, but I don't agree with the premise
> that the information content must always be exactly the same.

Hmm. I thought that the purpose of having a generalized options
syntax was that people could have the information they wanted,
independently of the format they chose. Even with a lot of extra
information, the human readable format is still far shorter and more
easily readable than either of the others. If we had gone with the
idea of just dumping everything in the world into the XML format,
you'd be right: but for various reasons we decided against that, which
I'm very happy about.

> FWIW, the patch's output as it stood a few days ago (one extra line per
> node, conditional on a BUFFERS option) did seem perfectly reasonable to
> me, and I don't see the reason to change that format now.

Yep, agreed.

...Robert

On Thu, Oct 15, 2009 at 3:29 AM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
> Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
>> In this case, I think that the auto_explain changes out to be part of
>> the same patch as the core EXPLAIN changes
>
> Here is a rewritten patch to add EXPLAIN (ANALYZE, BUFFERS) and
> support for it by contrib/auto_explain. I removed pg_stat_statements
> support from the patch for now.

Just a quick note: this patch does not apply cleanly to HEAD due to
the subsequent removal from explain.c of the near-by lines:

/* Convert parameter type data to the form parser wants */
getParamListTypes(params, &param_types, &num_params);

I think it is merely a text conflict and not a functional one.

Cheers,

Jeff

Jeff Janes <jeff(dot)janes(at)gmail(dot)com> wrote:

> Just a quick note: this patch does not apply cleanly to HEAD due to
> the subsequent removal from explain.c of the near-by lines:

Thanks for reporting.
The attached patch is rebased to current CVS.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Itagaki Takahiro escreveu:
> The attached patch is rebased to current CVS.
>
I'm looking at your patch now... It is almost there but has some issues.

(i) documentation: you have more than three counters and they could be
mentioned in docs too.

+ Include information on the buffers. Specifically, include the number of
+ buffer hits, number of disk blocks read, and number of local buffer read.

(ii) format: why does text output format have less counters than the other ones?

+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ appendStringInfoSpaces(es->str, es->indent * 2);
+ appendStringInfo(es->str, "Blocks Hit: %ld Read: %ld Temp Read:
%ld\n",
+ usage->blks_hit, usage->blks_read, usage->temp_blks_read);
+ }
+ else
+ {
+ ExplainPropertyLong("Hit Blocks", usage->blks_hit, es);
+ ExplainPropertyLong("Read Blocks", usage->blks_read, es);
+ ExplainPropertyLong("Written Blocks", usage->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);
+ }

(iii) string: i don't like the string in text format because (1) it is not
concise (only the first item has the word 'Blocks'), (2) what block is it
about? Shared, Local, or Temp?, (3) why don't you include the other ones?, and
(4) why don't you include the written counters?

-> Seq Scan on pg_namespace nc (cost=0.00..1.07 rows=4 width=68) (actual
time=0.015..0.165 rows=4 loops=1)
Filter: (NOT pg_is_other_temp_schema(oid))
Blocks Hit: 11 Read: 0 Temp Read: 0

(iv) text format: i don't have a good suggestion but here are some ideas. The
former is too long and the latter is too verbose. :( Another option is to
suppress words hit, read, and written; and just document it.

Shared Blocks (11 hit, 5 read, 0 written); Local Blocks (5 hit, 0 read, 0
written); Temp Blocks (0 read, 0 written)

or

Shared Blocks: 11 hit, 5 read, 0 written
Local Blocks: 5 hit, 0 read, 0 written
Temp Blocks: 0 read, 0 written

(v) accumulative: i don't remember if we discussed it but is there a reason
the number of buffers isn't accumulative? We already have cost and time that
are both accumulative. I saw BufferUsageAccumDiff() function but didn't try to
figure out why it isn't accumulating or passing the counters to parent nodes.

euler=# explain (analyze true, buffers true) select * from pgbench_branches
inner join pgbench_history using (bid) where bid > 100;
QUERY PLAN

------------------------------------------------------------------------------------------------------------------------
Hash Join (cost=1.02..18.62 rows=3 width=476) (actual time=0.136..0.136
rows=0 loops=1)
Hash Cond: (pgbench_history.bid = pgbench_branches.bid)
Blocks Hit: 2 Read: 0 Temp Read: 0
-> Seq Scan on pgbench_history (cost=0.00..15.50 rows=550 width=116)
(actual time=0.034..0.034 rows=1 loops=1)
Blocks Hit: 1 Read: 0 Temp Read: 0
-> Hash (cost=1.01..1.01 rows=1 width=364) (actual time=0.022..0.022
rows=0 loops=1)
Blocks Hit: 0 Read: 0 Temp Read: 0
-> Seq Scan on pgbench_branches (cost=0.00..1.01 rows=1 width=364)
(actual time=0.019..0.019 rows=0 loops=1)
Filter: (bid > 100)
Blocks Hit: 1 Read: 0 Temp Read: 0
Total runtime: 0.531 ms
(11 rows)

(vi) comment: the 'at start' is superfluous. Please, remove it.

+ long blks_hit; /* # of buffer hits at start */
+ long blks_read; /* # of disk blocks read at start */

(vii) all nodes: I'm thinking if we need this information in all nodes (even
in those nodes that don't read or write). It would be less verbose but it
could complicate some parser's life. Of course, if we suppress this
information, we need to include it on the top node even if we don't read or
write in it.

I didn't have time to adjust your patch per comments above but if you can
address all of those issues I certainly could check your patch again.

--
Euler Taveira de Oliveira
http://www.timbira.com/

Euler Taveira de Oliveira <euler(at)timbira(dot)com> wrote:

> I'm looking at your patch now... It is almost there but has some issues.
>
> (i) documentation: you have more than three counters and they could be
> mentioned in docs too.

I'll add documentation for all variables.

> (ii) format: why does text output format have less counters than the other ones?

That's because lines will be too long for text format. I think the
three values in it are the most important and useful ones.

> (iii) string: i don't like the string in text format
> (1) it is not concise (only the first item has the word 'Blocks'),
> (2) what block is it about? Shared, Local, or Temp?

The format was suggested here and no objections then.
http://archives.postgresql.org/pgsql-hackers/2009-10/msg00268.php
I think the current output is enough and useful in normal use.
We can use XML or JSON format for more details.

I think
Blocks Hit: 1641 Read: 0 Temp Read: 1443
means
Blocks (Hit: 1641 Read: 0 Temp Read: 1443)
i.e., Blocks of hit, blocks of reads, and Blocks of temp reads.

> (3) why don't you include the other ones?, and
> (4) why don't you include the written counters?
> (iv) text format: i don't have a good suggestion but here are some ideas. The
> former is too long and the latter is too verbose.

Their reasons are the same as (ii).

> (v) accumulative: i don't remember if we discussed it but is there a reason
> the number of buffers isn't accumulative? We already have cost and time that
> are both accumulative. I saw BufferUsageAccumDiff() function but didn't try to
> figure out why it isn't accumulating or passing the counters to parent nodes.

It's reasonable. I'll change so if no objections.

> (vi) comment: the 'at start' is superfluous. Please, remove it.

Ooops, I'll remove them.

> (vii) all nodes: I'm thinking if we need this information in all nodes (even
> in those nodes that don't read or write). It would be less verbose but it
> could complicate some parser's life. Of course, if we suppress this
> information, we need to include it on the top node even if we don't read or
> write in it.

I cannot understand what you mean -- should I suppress the lines when they
have all-zero values?

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Mon, Dec 7, 2009 at 1:28 AM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>> (ii) format: why does text output format have less counters than the other ones?
>
> That's because lines will be too long for text format. I think the
> three values in it are the most important and useful ones.

I disagree. I objected to showing only part of the information when I
looked at this patch last CommitFest, and I object again now. I do
*NOT* want to have to use JSON or XML to get at the counters you've
arbitrarily decided are not interesting to me. I think with a little
creativity we can certainly get these into the text format, and I'm
willing to help with that. In fact, if you want, I'll pick up this
patch and make it my first commit, though since you're now a committer
as well perhaps you'd prefer to do it yourself.

>> (v) accumulative: i don't remember if we discussed it but is there a reason
>> the number of buffers isn't accumulative? We already have cost and time that
>> are both accumulative. I saw BufferUsageAccumDiff() function but didn't try to
>> figure out why it isn't accumulating or passing the counters to parent nodes.
>
> It's reasonable. I'll change so if no objections.

+1 to change it.

...Robert

Itagaki Takahiro escreveu:
> I think the current output is enough and useful in normal use.
> We can use XML or JSON format for more details.
>
I don't think it is a good idea to have different information in different
formats. I'm with Robert; *don't* do that. If you want to suppress the other
ones in text format, do it in the others too. One idea is to add them only if
we prefer the VERBOSE output.

> I think
> Blocks Hit: 1641 Read: 0 Temp Read: 1443
> means
> Blocks (Hit: 1641 Read: 0 Temp Read: 1443)
> i.e., Blocks of hit, blocks of reads, and Blocks of temp reads.
>
But the latter is more clear than the former.

> I cannot understand what you mean -- should I suppress the lines when they
> have all-zero values?
>
There are nodes that don't read or write blocks. If we go this way, we need to
document this behavior.

--
Euler Taveira de Oliveira
http://www.timbira.com/

Here is an updated patch per discussion.

* Counters are accumulative. They contain I/Os by child nodes.
* Text format shows all counters.
* Add "shared_" prefix to variables representing shared buffers/blocks.

Euler Taveira de Oliveira <euler(at)timbira(dot)com> wrote:

> Itagaki Takahiro escreveu:
> > I think the current output is enough and useful in normal use.
> > We can use XML or JSON format for more details.
> >
> I don't think it is a good idea to have different information in different
> formats. I'm with Robert; *don't* do that.

I'm afraid of the human-unreadability of the text format, that is discussed
in the YAML format thread. ...but I found we say the following in the docs.

XML or JSON output contains the same information as the text output format
http://developer.postgresql.org/pgdocs/postgres/sql-explain.html

Obviously I should not hide any information only in the text format.
The new output will be: (in one line)
Shared Blocks: (hit=2 read=1641 written=0) Local Blocks: (hit=0 read=0 written=0) Temp Blocks: (read=1443 written=1443)

> There are nodes that don't read or write blocks.

This will be impossible now because we re-defined the meaning of counters
as "accumulated number of I/O". Even if the node never read or write blocks,
it might contain some child nodes with I/O.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Mon, Dec 7, 2009 at 9:58 PM, Itagaki Takahiro
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
> Here is an updated patch per discussion.
>
>  * Counters are accumulative. They contain I/Os by child nodes.
>  * Text format shows all counters.
>  * Add "shared_" prefix to variables representing shared buffers/blocks.
>
> Euler Taveira de Oliveira <euler(at)timbira(dot)com> wrote:
>
>> Itagaki Takahiro escreveu:
>> > I think the current output is enough and useful in normal use.
>> > We can use XML or JSON format for more details.
>> >
>> I don't think it is a good idea to have different information in different
>> formats. I'm with Robert; *don't* do that.
>
> I'm afraid of the human-unreadability of the text format, that is discussed
> in the YAML format thread. ...but I found we say the following in the docs.
>
>  XML or JSON output contains the same information as the text output format
>  http://developer.postgresql.org/pgdocs/postgres/sql-explain.html
>
> Obviously I should not hide any information only in the text format.
> The new output will be: (in one line)
>  Shared Blocks: (hit=2 read=1641 written=0) Local Blocks: (hit=0 read=0 written=0) Temp Blocks: (read=1443 written=1443)

Hmm, that's a little awkward. I think we could drop some of the punctuation.

Shared Blocks: hit 2 read 1641 wrote 0, Local Blocks: hit 0 read 0
wrote 0, Temp Blocks: read 1443 wrote 1443

...Robert

Robert Haas wrote:
> On Mon, Dec 7, 2009 at 9:58 PM, Itagaki Takahiro
> <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
>> Obviously I should not hide any information only in the text format.
>> The new output will be: (in one line)
>> Shared Blocks: (hit=2 read=1641 written=0) Local Blocks: (hit=0 read=0 written=0) Temp Blocks: (read=1443 written=1443)
>>
>
> Hmm, that's a little awkward. I think we could drop some of the punctuation.
>
> Shared Blocks: hit 2 read 1641 wrote 0, Local Blocks: hit 0 read 0
> wrote 0, Temp Blocks: read 1443 wrote 1443
>
Having written more things to parse log files that should have been
saved in a better format after the fact than I'd like, I'd say that
replacing the "=" signs used as a delimiter with a space is a step
backwards. That doesn't save any space anyway, and drifts too far from
what one gets out of regular EXPLAIN I think.

I was perfectly happy with proposed text format as being a reasonable
trade-off between *possible* to parse if all you have is the text
format, while still being readable. If you want to compress
horizontally, get rid of "Blocks" after the first usage is the first
thing to do:

(1) Blocks Shared: (hit=2 read=1641 written=0) Local: (hit=0 read=0
written=0) Temp: (read=1443 written=1443)

That's already at about the same length as what you suggested at 105
characters, without losing any useful formatting.

If further compression is required, you could just remove all the
parentheses:

(2) Blocks Shared:hit=2 read=1641 written=0 Local:hit=0 read=0 written=0
Temp:read=1443 written=1443

I don't really like this though. Instead you could abbreviate the rest
of the repeated text and reduce the number of spaces:

(3) Blocks Shared:(hit=2 read=1641 written=0) Local:(h=0 r=0 w=0)
Temp:(r=1443 w=1443)

And now we're at the smallest result yet without any real loss in
readability--I'd argue it's faster to read in fact. This has a good
balance of fitting on a reasonably wide console (the above is down to 82
characters), still being readable to anyone, and being possible to
machine parse in a pinch if all you have are text logs around (split on
: then =). It might be too compressed down for some tastes though.

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg(at)2ndQuadrant(dot)com www.2ndQuadrant.com

On Mon, Dec 7, 2009 at 11:09 PM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> Robert Haas wrote:
>
> On Mon, Dec 7, 2009 at 9:58 PM, Itagaki Takahiro
> <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
>
> Obviously I should not hide any information only in the text format.
> The new output will be: (in one line)
>  Shared Blocks: (hit=2 read=1641 written=0) Local Blocks: (hit=0 read=0
> written=0) Temp Blocks: (read=1443 written=1443)
>
>
> Hmm, that's a little awkward. I think we could drop some of the
> punctuation.
>
> Shared Blocks: hit 2 read 1641 wrote 0, Local Blocks: hit 0 read 0
> wrote 0, Temp Blocks: read 1443 wrote 1443
>
>
> Having written more things to parse log files that should have been saved in
> a better format after the fact than I'd like, I'd say that replacing the "="
> signs used as a delimiter with a space is a step backwards.  That doesn't
> save any space anyway, and drifts too far from what one gets out of regular
> EXPLAIN I think.
>
> I was perfectly happy with proposed text format as being a reasonable
> trade-off between *possible* to parse if all you have is the text format,
> while still being readable.  If you want to compress horizontally, get rid
> of "Blocks" after the first usage is the first thing to do:
>
> (1) Blocks Shared: (hit=2 read=1641 written=0) Local: (hit=0 read=0
> written=0) Temp: (read=1443 written=1443)
>
> That's already at about the same length as what you suggested at 105
> characters, without losing any useful formatting.
>
> If further compression is required, you could just remove all the
> parentheses:
>
> (2) Blocks Shared:hit=2 read=1641 written=0 Local:hit=0 read=0 written=0
> Temp:read=1443 written=1443
>
> I don't really like this though.  Instead you could abbreviate the rest of
> the repeated text and reduce the number of spaces:
>
> (3) Blocks Shared:(hit=2 read=1641 written=0) Local:(h=0 r=0 w=0)
> Temp:(r=1443 w=1443)
>
> And now we're at the smallest result yet without any real loss in
> readability--I'd argue it's faster to read in fact.  This has a good balance
> of fitting on a reasonably wide console (the above is down to 82
> characters), still being readable to anyone, and being possible to machine
> parse in a pinch if all you have are text logs around (split on : then =).
> It might be too compressed down for some tastes though.

I could live with the equals signs, but the use of parentheses seems
weird and inconsistent with normal english usage (which permits
parentheses as a means of making parenthetical comments). (You can
also put an entire sentence in parentheses.) But you can't: (do
this).

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> On Mon, Dec 7, 2009 at 11:09 PM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> > (1) Blocks Shared: (hit=2 read=1641 written=0) Local: (hit=0 read=0
> > written=0) Temp: (read=1443 written=1443)

> I could live with the equals signs, but the use of parentheses seems
> weird and inconsistent with normal english usage (which permits
> parentheses as a means of making parenthetical comments). (You can
> also put an entire sentence in parentheses.) But you can't: (do
> this).

+1 for (1) personally, if we could think it is not in English but just
a symbol. I have another idea to make it alike with ANALYZE output.

(4) Blocks (shared hit=2 read=1641 ...) (local hit=0 ...) (temp read=0 ...)

Which is the best? I think it's a matter of preference.
(0) 109 characters - Shared Blocks: hit 2 read 1641 wrote 0, ...
(1) 105 characters - Blocks Shared: (hit=2 ...
(2) 96 characters - Blocks Shared:hit=2 ...
(3) 82 characters - Blocks Shared:(hit=2 ...
(4) 82 characters - Blocks (shared hit=2 ...

BTW, I found text is a *bad* format because it requires much discussion ;)
We have a little choice in XML, JSON and YAML formats.

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

Robert Haas wrote:
> I could live with the equals signs, but the use of parentheses seems
> weird and inconsistent with normal english usage (which permits
> parentheses as a means of making parenthetical comments).
But it is consistent with people seeing:

Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4)

Which seems to be what was being emulated here. I though that was
pretty reasonable given this is a related feature.

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg(at)2ndQuadrant(dot)com www.2ndQuadrant.com

Itagaki Takahiro escreveu:
> Here is an updated patch per discussion.
>
> * Counters are accumulative. They contain I/Os by child nodes.
> * Text format shows all counters.
> * Add "shared_" prefix to variables representing shared buffers/blocks.
>
Nice. Despite of the other opinions, I'm satisfied with your text format
sentence. It is: (i) clear (I don't have to think or check the docs to know
what information is that.) and (ii) not so verbose (There are nodes that are
even longer than that.).

The only thing that needs some fix is:

+ Include information on the buffers. Specifically, include the number of
+ hits/reads/writes of shared blocks and local blocks, and number of reads
+ and writes of temp blocks. Shared blocks contain global tables and
+ indexes, local blocks contain temporary tables and indexes, and temp
+ blocks contain disk blocks used in sort and materialized plans.
+ The value of a parent node contains values of its children.
+ This parameter should be used with <literal>ANALYZE</literal> parameter.
+ This parameter defaults to <literal>FALSE</literal>.

That could be:

Include information on the buffers. 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 of an upper-level node includes the blocks
of all its child nodes. It should be used with <literal>ANALYZE</literal>
parameter. This parameter defaults to <literal>FALSE</literal>.

If there is no more objections, I'll flag the patch 'ready for committer' (you :).

--
Euler Taveira de Oliveira
http://www.timbira.com/

On Dec 8, 2009, at 12:05 AM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:

> Robert Haas wrote:
>> I could live with the equals signs, but the use of parentheses seems
>> weird and inconsistent with normal english usage (which permits
>> parentheses as a means of making parenthetical comments).
> But it is consistent with people seeing:
>
> Seq Scan on foo (cost=0.00..155.00 rows=10000 width=4)
>
> Which seems to be what was being emulated here. I though that was
> pretty reasonable given this is a related feature.

It's not the same at all. The essence of a parenthetical phrase is
that it can be omitted without turning what's left into nonsense - and
in fact we have COSTS OFF, which does just that. Omitting only the
parenthesized portions of the proposed output would not be sensible.

...Robert

Euler Taveira de Oliveira wrote:
> If there is no more objections, I'll flag the patch 'ready for committer'
>
I just executed that. Note that there are two bits of subjective
tweaking possible to do with this one when it's committed: slimming
down the width of the display, and Euler's suggestion's for rewording.
I linked to both of those messages in the CF app, labeled as notes the
committer might want to consider, but that the patch hasn't been updated
to include yet.

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg(at)2ndQuadrant(dot)com www.2ndQuadrant.com

Greg Smith <greg(at)2ndquadrant(dot)com> wrote:

> I just executed that. Note that there are two bits of subjective
> tweaking possible to do with this one when it's committed: slimming
> down the width of the display, and Euler's suggestion's for rewording.
> I linked to both of those messages in the CF app, labeled as notes the
> committer might want to consider, but that the patch hasn't been updated
> to include yet.

Sure, I should have merge all of the comments. Patch attached.

- Updated documentation as Euler's suggestion, but I replaced
the "It" of the second last sentence to "This parameter".
- Updated the output format as follows. I think this format is the most
similar to existing lines. ("actual" by ANALYZE and "Filter:").

Note that the patch also removes buffer counters from log_statement_stats,
but we only have brief descriptions about the options. Our documentation
say nothing about buffer counters, so I didn't modify those lines in sgml.
http://developer.postgresql.org/pgdocs/postgres/runtime-config-statistics.html#RUNTIME-CONFIG-STATISTICS-MONITOR
IMHO, we could remove those options completely because we can use
EXPLAIN BUFFERS and DTrace probes instead of them.

=# EXPLAIN (BUFFERS, ANALYZE) SELECT *
FROM pgbench_accounts a, pgbench_branches b
WHERE a.bid = b.bid AND abalance > 0 ORDER BY abalance;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------
Sort (cost=2891.03..2891.04 rows=1 width=461) (actual time=22.494..22.494 rows=0 loops=1)
Sort Key: a.abalance
Sort Method: quicksort Memory: 25kB
Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
-> Nested Loop (cost=0.00..2891.02 rows=1 width=461) (actual time=22.488..22.488 rows=0 loops=1)
Join Filter: (a.bid = b.bid)
Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
-> Seq Scan on pgbench_accounts a (cost=0.00..2890.00 rows=1 width=97) (actual time=22.486..22.486 rows=0 loops=1)
Filter: (abalance > 0)
Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
-> Seq Scan on pgbench_branches b (cost=0.00..1.01 rows=1 width=364) (never executed)
Blocks: (shared hit=0 read=0 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
Total runtime: 22.546 ms
(13 rows)

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

Takahiro Itagaki escreveu:
> Sure, I should have merge all of the comments. Patch attached.
>
Thanks for your effort. Looks sane to me.

> - Updated the output format as follows. I think this format is the most
> similar to existing lines. ("actual" by ANALYZE and "Filter:").
>
If people object to it, we can always change it later.

> IMHO, we could remove those options completely because we can use
> EXPLAIN BUFFERS and DTrace probes instead of them.
>
+1. But we need to propose some replacement options.

--
Euler Taveira de Oliveira
http://www.timbira.com/

On Wed, Dec 9, 2009 at 12:36 AM, Takahiro Itagaki
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
> Note that the patch also removes buffer counters from log_statement_stats,
> but we only have brief descriptions about the options. Our documentation
> say nothing about buffer counters, so I didn't modify those lines in sgml.
> http://developer.postgresql.org/pgdocs/postgres/runtime-config-statistics.html#RUNTIME-CONFIG-STATISTICS-MONITOR

I'm not sure whether this is a good idea or not. Let me read the
patch. I'm not sure an EXPLAIN option is really an adequate
substitute for log_statement_stats - the latter will let you get stats
for all of your queries automatically, I believe, and might still be
useful as a quick and dirty tool.

> IMHO, we could remove those options completely because we can use
> EXPLAIN BUFFERS and DTrace probes instead of them.

We certainly should NOT count on dtrace as a substitute for anything.
It's not available on Windows, or all other platforms either.

> =# EXPLAIN (BUFFERS, ANALYZE) SELECT *
>      FROM pgbench_accounts a, pgbench_branches b
>     WHERE a.bid = b.bid AND abalance > 0 ORDER BY abalance;
>                                                          QUERY PLAN
> ------------------------------------------------------------------------------------------------------------------------------
>  Sort  (cost=2891.03..2891.04 rows=1 width=461) (actual time=22.494..22.494 rows=0 loops=1)
>   Sort Key: a.abalance
>   Sort Method:  quicksort  Memory: 25kB
>   Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
>   ->  Nested Loop  (cost=0.00..2891.02 rows=1 width=461) (actual time=22.488..22.488 rows=0 loops=1)
>         Join Filter: (a.bid = b.bid)
>         Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
>         ->  Seq Scan on pgbench_accounts a  (cost=0.00..2890.00 rows=1 width=97) (actual time=22.486..22.486 rows=0 loops=1)
>               Filter: (abalance > 0)
>               Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
>         ->  Seq Scan on pgbench_branches b  (cost=0.00..1.01 rows=1 width=364) (never executed)
>               Blocks: (shared hit=0 read=0 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
>  Total runtime: 22.546 ms
> (13 rows)

I still think this is a bad format. Instead of putting "(" and ")"
around each phrase, can't we just separate them with a "," or ";"?
The filter uses parentheses in a mathematical way, for grouping
related items. Not all filters are surrounded by parentheses
(consider a filter like "WHERE x", x being a boolean column) and some
will have multiple sets, if there are ANDs and ORs in there.

...Robert

Robert Haas escreveu:
> I'm not sure whether this is a good idea or not. Let me read the
> patch. I'm not sure an EXPLAIN option is really an adequate
> substitute for log_statement_stats - the latter will let you get stats
> for all of your queries automatically, I believe, and might still be
> useful as a quick and dirty tool.
>
Why? If you want this information for all of your queries, you can always set
auto_explain.log_min_duration to 0. But if you're suggesting that we should
maintain log_statement_stats (that was not I understand from Tom's email [1]),
it's not that difficult to a change ShowBufferUsage().

> We certainly should NOT count on dtrace as a substitute for anything.
> It's not available on Windows, or all other platforms either.
>
But we can always count on EXPLAIN BUFFERS. Remember that some monitoring
tasks are _only_ available via DTrace.

> I still think this is a bad format. Instead of putting "(" and ")"
> around each phrase, can't we just separate them with a "," or ";"?
>
We already use ( and ) to group things. I don't remember us using , or ; in
any output node. The suggested output is intuitive and similar to other nodes
patterns.

[1] http://archives.postgresql.org/pgsql-hackers/2009-10/msg00718.php

--
Euler Taveira de Oliveira
http://www.timbira.com/

On Thu, Dec 10, 2009 at 9:03 AM, Euler Taveira de Oliveira
<euler(at)timbira(dot)com> wrote:
> Robert Haas escreveu:
>> I'm not sure whether this is a good idea or not.  Let me read the
>> patch.  I'm not sure an EXPLAIN option is really an adequate
>> substitute for log_statement_stats - the latter will let you get stats
>> for all of your queries automatically, I believe, and might still be
>> useful as a quick and dirty tool.
>>
> Why? If you want this information for all of your queries, you can always set
> auto_explain.log_min_duration to 0. But if you're suggesting that we should
> maintain log_statement_stats (that was not I understand from Tom's email [1]),
> it's not that difficult to a change ShowBufferUsage().

Mmm, OK, if Tom thinks we should rip it out, I'm not going to second-guess him.

>> I still think this is a bad format.  Instead of putting "(" and ")"
>> around each phrase, can't we just separate them with a "," or ";"?
>>
> We already use ( and ) to group things. I don't remember us using , or ; in
> any output node. The suggested output is intuitive and similar to other nodes
> patterns.

It isn't. In the other cases where we output multiple distinct values
on the same output row - like the sort instrumentation when ANALYZE is
turned on - they are separated with copious amounts of whitespace.
Costs are an exception, but those aren't done the same way as this
either.

The only reason anyone is even thinking that they need parentheses
here is because they're trying to put three separate groups of
buffer-related statistics - a total of 8 values - on the same output
line. If this were split up over three output lines, no one would
even be suggesting parentheses. Maybe that's a saner way to go. If
not, fine, but I don't believe for a minute that the suggested format
is either correct or parallel to what has been done elsewhere.

...Robert

Takahiro Itagaki escribió:

> =# EXPLAIN (BUFFERS, ANALYZE) SELECT *
> FROM pgbench_accounts a, pgbench_branches b
> WHERE a.bid = b.bid AND abalance > 0 ORDER BY abalance;
> QUERY PLAN
> ------------------------------------------------------------------------------------------------------------------------------
> Sort (cost=2891.03..2891.04 rows=1 width=461) (actual time=22.494..22.494 rows=0 loops=1)
> Sort Key: a.abalance
> Sort Method: quicksort Memory: 25kB
> Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)

Maybe I missed part of this discussion, but it seems a bit weird to have
an option named "buffers" turn on a line that specifies numbers of
"blocks". I kept looking for where you were specifying the BLOCKS
option to EXPLAIN in the command ...

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
> Takahiro Itagaki escribi:
>> Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)

> Maybe I missed part of this discussion, but it seems a bit weird to have
> an option named "buffers" turn on a line that specifies numbers of
> "blocks".

Agreed, and I have to agree also with the people who have been
criticizing the output format. If we were trying to put the block
counts onto the same line as everything else then maybe parentheses
would be helpful, but here they're just clutter.

Perhaps

I/O: shared hit=96 read=1544 written=0 local hit=0 read=0 written=0 temp read=0 written=0

(although this would suggest making the option name "io" which is
probably a poor choice)

I also suggest that dropping out zeroes might help --- a large fraction
of EXPLAIN work is done with SELECTs that aren't ever going to write
anything. Then the above becomes

I/O: shared hit=96 read=1544

which is vastly more readable. You wouldn't want that to happen in
machine-readable formats of course, but I think we no longer care about
whether the text format is easy for programs to parse.

regards, tom lane

On Thu, Dec 10, 2009 at 10:44 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
>> Takahiro Itagaki escribió:
>>> Blocks: (shared hit=96 read=1544 written=0) (local hit=0 read=0 written=0) (temp read=0 written=0)
>
>> Maybe I missed part of this discussion, but it seems a bit weird to have
>> an option named "buffers" turn on a line that specifies numbers of
>> "blocks".
>
> Agreed, and I have to agree also with the people who have been
> criticizing the output format.  If we were trying to put the block
> counts onto the same line as everything else then maybe parentheses
> would be helpful, but here they're just clutter.
>
> Perhaps
>
>        I/O: shared hit=96 read=1544 written=0 local hit=0 read=0 written=0 temp read=0 written=0
>
> (although this would suggest making the option name "io" which is
> probably a poor choice)
>
> I also suggest that dropping out zeroes might help --- a large fraction
> of EXPLAIN work is done with SELECTs that aren't ever going to write
> anything.  Then the above becomes
>
>        I/O: shared hit=96 read=1544
>
> which is vastly more readable.  You wouldn't want that to happen in
> machine-readable formats of course, but I think we no longer care about
> whether the text format is easy for programs to parse.

Oooh, that's a nice idea, though I think you should throw in some
commas if there is, say, both shared and local stuff:

shared hit=96 read=1544, local read=19

I don't think IO is a terrible name for an option but I like BUFFERS
better. I don't think the BUFFERS/BLOCKS confusion is too bad, but
perhaps we could use BUFFERS in both places.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> On Thu, Dec 10, 2009 at 9:03 AM, Euler Taveira de Oliveira
> <euler(at)timbira(dot)com> wrote:
>> Why? If you want this information for all of your queries, you can always set
>> auto_explain.log_min_duration to 0. But if you're suggesting that we should
>> maintain log_statement_stats (that was not I understand from Tom's email [1]),
>> it's not that difficult to a change ShowBufferUsage().

> Mmm, OK, if Tom thinks we should rip it out, I'm not going to second-guess him.

Feel free to question that. But it's ancient code and I'm not convinced
it still has a reason to live. If you want to investigate the I/O
behavior of a particular query, you'll use EXPLAIN. If you want to get
an idea of the system-wide behavior, you'll use the stats collector.
What use case is left for the backend-local counters?

regards, tom lane

Robert Haas wrote:
> I don't think IO is a terrible name for an option but I like BUFFERS
> better. I don't think the BUFFERS/BLOCKS confusion is too bad, but
> perhaps we could use BUFFERS in both places.
>
I don't know how "blocks" got into here in the first place--this concept
is "buffers" just about everywhere else already, right?

--
Greg Smith 2ndQuadrant Baltimore, MD
PostgreSQL Training, Services and Support
greg(at)2ndQuadrant(dot)com www.2ndQuadrant.com

On Thu, Dec 10, 2009 at 10:52 AM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> Robert Haas wrote:
>>
>> I don't think IO is a terrible name for an option but I like BUFFERS
>> better.  I don't think the BUFFERS/BLOCKS confusion is too bad, but
>> perhaps we could use BUFFERS in both places.
>
> I don't know how "blocks" got into here in the first place--this concept is
> "buffers" just about everywhere else already, right?

I think we have some places already in the system where we bounce back
and forth between those terms. I expect that's the reason.

...Robert

Robert Haas escreveu:
> The only reason anyone is even thinking that they need parentheses
> here is because they're trying to put three separate groups of
> buffer-related statistics - a total of 8 values - on the same output
> line. If this were split up over three output lines, no one would
> even be suggesting parentheses.
>
That's the point. I'm afraid 3 new lines per node is too verbose.

--
Euler Taveira de Oliveira
http://www.timbira.com/

On Thu, Dec 10, 2009 at 10:50 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
>> On Thu, Dec 10, 2009 at 9:03 AM, Euler Taveira de Oliveira
>> <euler(at)timbira(dot)com> wrote:
>>> Why? If you want this information for all of your queries, you can always set
>>> auto_explain.log_min_duration to 0. But if you're suggesting that we should
>>> maintain log_statement_stats (that was not I understand from Tom's email [1]),
>>> it's not that difficult to a change ShowBufferUsage().
>
>> Mmm, OK, if Tom thinks we should rip it out, I'm not going to second-guess him.
>
> Feel free to question that.  But it's ancient code and I'm not convinced
> it still has a reason to live.  If you want to investigate the I/O
> behavior of a particular query, you'll use EXPLAIN.  If you want to get
> an idea of the system-wide behavior, you'll use the stats collector.
> What use case is left for the backend-local counters?

Beats me. Tracing just your session without having to EXPLAIN each
query (and therefore not get the output rows)? OK, I'm reaching. I
tend to be very conservative about ripping things out that someone
might want unless they're actually getting in the way of doing some
new thing that we want to do - but so are you, and you know the
history of this code better than I do. I'm happy to save my
questioning for a more important issue.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> On Thu, Dec 10, 2009 at 10:52 AM, Greg Smith <greg(at)2ndquadrant(dot)com> wrote:
> >> I don't think IO is a terrible name for an option but I like BUFFERS
> >> better. ?I don't think the BUFFERS/BLOCKS confusion is too bad, but
> >> perhaps we could use BUFFERS in both places.
> >
> > I don't know how "blocks" got into here in the first place--this concept is
> > "buffers" just about everywhere else already, right?
>
> I think we have some places already in the system where we bounce back
> and forth between those terms. I expect that's the reason.

The "blocks" comes from pg_statio_all_tables.heap_blks_{read|hit},
but "buffers" might be easy to understand. One matter for concern
is that "buffer read" might not be clear whether it is a memory access
or a disk read.

Anyway, a revised patch according to the comments is attached.
The new text format is:
Buffers: shared hit=675 read=968, temp read=1443 written=1443
* Zero values are omitted. (Non-text formats could have zero values.)
* Rename "Blocks:" to "Buffers:".
* Remove parentheses and add a comma between shared, local and temp.

=# EXPLAIN (BUFFERS, ANALYZE) SELECT *
FROM pgbench_accounts a, pgbench_branches b
WHERE a.bid = b.bid AND abalance >= 0 ORDER BY abalance;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=54151.83..54401.83 rows=100000 width=461) (actual time=92.551..109.646 rows=100000 loops=1)
Sort Key: a.abalance
Sort Method: external sort Disk: 11544kB
Buffers: shared hit=675 read=968, temp read=1443 written=1443
-> Nested Loop (cost=0.00..4141.01 rows=100000 width=461) (actual time=0.048..42.190 rows=100000 loops=1)
Join Filter: (a.bid = b.bid)
Buffers: shared hit=673 read=968
-> Seq Scan on pgbench_branches b (cost=0.00..1.01 rows=1 width=364) (actual time=0.003..0.004 rows=1 loops=1)
Buffers: shared hit=1
-> Seq Scan on pgbench_accounts a (cost=0.00..2890.00 rows=100000 width=97) (actual time=0.038..22.912 rows=100000 loops=1)
Filter: (a.abalance >= 0)
Buffers: shared hit=672 read=968
Total runtime: 116.058 ms
(13 rows)

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

On Thu, Dec 10, 2009 at 9:35 PM, Takahiro Itagaki
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
> Anyway, a revised patch according to the comments is attached.
> The new text format is:
>  Buffers: shared hit=675 read=968, temp read=1443 written=1443
>    * Zero values are omitted. (Non-text formats could have zero values.)
>    * Rename "Blocks:" to "Buffers:".
>    * Remove parentheses and add a comma between shared, local and temp.

I did a bit of copy-editing of your doc changes to make the English a
bit more correct and idiomatic. Slightly revised patch attached for
your consideration. The output format looks really nice (thanks for
bearing with me), and the functionality is great.

...Robert

Robert Haas escreveu:
> On Thu, Dec 10, 2009 at 9:35 PM, Takahiro Itagaki
> <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>> Anyway, a revised patch according to the comments is attached.
>> The new text format is:
>> Buffers: shared hit=675 read=968, temp read=1443 written=1443
>> * Zero values are omitted. (Non-text formats could have zero values.)
>> * Rename "Blocks:" to "Buffers:".
>> * Remove parentheses and add a comma between shared, local and temp.
>
> I did a bit of copy-editing of your doc changes to make the English a
> bit more correct and idiomatic. Slightly revised patch attached for
> your consideration. The output format looks really nice (thanks for
> bearing with me), and the functionality is great.
>
Please, document that zero values are omitted in the text format. It seems
intuitive but could be surprise because zero values are in non-text formats.

--
Euler Taveira de Oliveira
http://www.timbira.com/

On Fri, Dec 11, 2009 at 11:36 AM, Euler Taveira de Oliveira
<euler(at)timbira(dot)com> wrote:
> Robert Haas escreveu:
>> On Thu, Dec 10, 2009 at 9:35 PM, Takahiro Itagaki
>> <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>>> Anyway, a revised patch according to the comments is attached.
>>> The new text format is:
>>>  Buffers: shared hit=675 read=968, temp read=1443 written=1443
>>>    * Zero values are omitted. (Non-text formats could have zero values.)
>>>    * Rename "Blocks:" to "Buffers:".
>>>    * Remove parentheses and add a comma between shared, local and temp.
>>
>> I did a bit of copy-editing of your doc changes to make the English a
>> bit more correct and idiomatic.  Slightly revised patch attached for
>> your consideration.  The output format looks really nice (thanks for
>> bearing with me), and the functionality is great.
>>
> Please, document that zero values are omitted in the text format. It seems
> intuitive but could be surprise because zero values are in non-text formats.

OK, done, see attached. I also noticed when looking through this that
the documentation says that auto_explain.log_buffers is ignored unless
auto_explain.log_analyze is set. That is true and seems right to me,
but for some reason explain_ExecutorEnd() had been changed to set
es.analyze if either log_analyze or log_buffers was set. It actually
didn't have any effect unless log_analyze was set, but only because
explain_ExecutorStart doesn't set queryDesc->doInstrument in that
case. So I've reverted that here for clarity.

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> OK, done, see attached. I also noticed when looking through this that
> the documentation says that auto_explain.log_buffers is ignored unless
> auto_explain.log_analyze is set. That is true and seems right to me,
> but for some reason explain_ExecutorEnd() had been changed to set
> es.analyze if either log_analyze or log_buffers was set.

Thanks. It was my bug.

Could you apply the patch? Or, may I do by myself?

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

On Sun, Dec 13, 2009 at 7:55 PM, Takahiro Itagaki
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
> Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
>> OK, done, see attached.  I also noticed when looking through this that
>> the documentation says that auto_explain.log_buffers is ignored unless
>> auto_explain.log_analyze is set.  That is true and seems right to me,
>> but for some reason explain_ExecutorEnd() had been changed to set
>> es.analyze if either log_analyze or log_buffers was set.
>
> Thanks. It was my bug.
>
> Could you apply the patch? Or, may I do by myself?

Sorry, I've been meaning to look at this a little more and have gotten
distracted.

I have a question about the comment in InstrStopNode(), which reads:
"Adds delta of buffer usage to node's count and resets counter to
start so that the counters are not double counted by parent nodes."
It then calls BufferUsageAccumDiff(), but that function doesn't
actually "reset" anything, so it seems like the comment is wrong.

Two other thoughts:

1. It doesn't appear that there is any provision to ever zero
pgBufferUsage. Shouldn't we do this, say, once per explain, just to
avoid the possibility of overflowing the counters?

2. We seem to do all the work associated with pgBufferUsage even when
the "buffers" option is not passed to explain. The overhead of
incrementing the counters is probably negligible (and we were paying
the equivalent overhead before anyway) but I'm not sure whether saving
the starting counters and accumulating the deltas might be enough to
slow down EXPLAIN ANALYZE. That's sorta slow already so I'd hate to
whack it any more - have you benchmarked this at all?

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> I have a question about the comment in InstrStopNode(), which reads:
> "Adds delta of buffer usage to node's count and resets counter to
> start so that the counters are not double counted by parent nodes."
> It then calls BufferUsageAccumDiff(), but that function doesn't
> actually "reset" anything, so it seems like the comment is wrong.

Oops, it's wrong. It just does "Adds delta of buffer usage to node's count."

> Two other thoughts:
>
> 1. It doesn't appear that there is any provision to ever zero
> pgBufferUsage. Shouldn't we do this, say, once per explain, just to
> avoid the possibility of overflowing the counters?

I think the overflowing will not be a problem because we only use
the differences of values. The delta is always corrent unless we use
2^32 buffer accesses during one execution of a node.

> 2. We seem to do all the work associated with pgBufferUsage even when
> the "buffers" option is not passed to explain. The overhead of
> incrementing the counters is probably negligible (and we were paying
> the equivalent overhead before anyway) but I'm not sure whether saving
> the starting counters and accumulating the deltas might be enough to
> slow down EXPLAIN ANALYZE. That's sorta slow already so I'd hate to
> whack it any more - have you benchmarked this at all?

There are 5% of overheads in the worst cases. The difference will be
little if we have more complex operations or some disk I/Os.

Adding Instrumentation->count_bufusage flag could reduce the overheads.
if (instr->count_bufusage)
BufferUsageAccumDiff(...)

Should I add countBufferUsage boolean arguments to all places
doInstrument booleans are currently used? This requires several
minor modifications of codes in many places.

[without patch]
=# EXPLAIN (ANALYZE) SELECT * FROM pgbench_accounts;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
Seq Scan on pgbench_accounts (cost=0.00..263935.00 rows=10000000 width=97) (actual time=0.003..571.794 rows=10000000 loops=1)
Total runtime: 899.427 ms

[with patch]
=# EXPLAIN (ANALYZE) SELECT * FROM pgbench_accounts;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
Seq Scan on pgbench_accounts (cost=0.00..263935.00 rows=10000000 width=97) (actual time=0.003..585.885 rows=10000000 loops=1)
Total runtime: 955.280 ms

- shared_buffers = 1500MB
- pgbench -i -s100
- Read all pages in the pgbench_accounts into shared buffers before runs.

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

Takahiro Itagaki <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
> Should I add countBufferUsage boolean arguments to all places
> doInstrument booleans are currently used? This requires several
> minor modifications of codes in many places.

Pushing extra arguments around would create overhead of its own ...
overhead that would be paid even when not using EXPLAIN at all.

regards, tom lane

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> Takahiro Itagaki <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
> > Should I add countBufferUsage boolean arguments to all places
> > doInstrument booleans are currently used? This requires several
> > minor modifications of codes in many places.
>
> Pushing extra arguments around would create overhead of its own ...
> overhead that would be paid even when not using EXPLAIN at all.

I cannot understand what you mean... The additional argument should
not be a performance overhead because the code path is run only once
per execution. Instrumentation structures are still not allocated
in normal or EXPLAIN queries; allocated only in "EXPLAIN ANALYZE".

Or, are you suggesting to separate buffer counters with Instrumentation
structure? It still requires extra arguments, but it could minimize the
overhead when we use EXPLAIN ANALYZE without BUFFERS. However, we need
additional codes around InstrStartNode/InstrStopNode calls.

Or, are you complaining about non-performance overheads,
something like overheads of code maintenance?

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

On Sun, Dec 13, 2009 at 10:15 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Takahiro Itagaki <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
>> Should I add countBufferUsage boolean arguments to all places
>> doInstrument booleans are currently used? This requires several
>> minor modifications of codes in many places.
>
> Pushing extra arguments around would create overhead of its own ...
> overhead that would be paid even when not using EXPLAIN at all.

Well, I think we need to do something. I don't really want to tack
another 5-6% overhead onto EXPLAIN ANALYZE. Maybe we could recast the
doInstrument argument as a set of OR'd flags?

...Robert

On Sun, Dec 13, 2009 at 10:00 PM, Takahiro Itagaki
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>> Two other thoughts:
>>
>> 1. It doesn't appear that there is any provision to ever zero
>> pgBufferUsage.  Shouldn't we do this, say, once per explain, just to
>> avoid the possibility of overflowing the counters?
>
> I think the overflowing will not be a problem because we only use
> the differences of values. The delta is always corrent unless we use
> 2^32 buffer accesses during one execution of a node.

Hmm... you might be right. I'm not savvy enough to know whether there
are any portability concerns here.

Anyone else know?

...Robert

Robert Haas <robertmhaas(at)gmail(dot)com> wrote:

> Well, I think we need to do something. I don't really want to tack
> another 5-6% overhead onto EXPLAIN ANALYZE. Maybe we could recast the
> doInstrument argument as a set of OR'd flags?

I'm thinking the same thing (OR'd flags) right now.

The attached patch adds INSTRUMENT_TIMER and INSTRUMENT_BUFFERS flags.
The types of QueryDesc.doInstrument (renamed to instrument_options) and
EState.es_instrument are changed from bool to int, and they store
OR of InstrumentOption flags. INSTRUMENT_TIMER is always enabled when
instrumetations are initialized, but INSTRUMENT_BUFFERS is enabled only if
we use EXPLAIN BUFFERS. I think the flag options are not so bad idea because
of extensibility. For example, we could support EXPLAIN CPU_USAGE someday.

One issue is in the top-level instrumentation (queryDesc->totaltime).
Since the field might be used by multiple plugins, the first initializer
need to initialize the counter with all options. I used INSTRUMENT_ALL
for it in the patch.

=# EXPLAIN (ANALYZE) SELECT * FROM pgbench_accounts;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
Seq Scan on pgbench_accounts (cost=0.00..263935.00 rows=10000000 width=97) (actual time=0.003..572.126 rows=10000000 loops=1)
Total runtime: 897.729 ms

=# EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM pgbench_accounts;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
Seq Scan on pgbench_accounts (cost=0.00..263935.00 rows=10000000 width=97) (actual time=0.002..580.642 rows=10000000 loops=1)
Buffers: shared hit=163935
Total runtime: 955.744 ms

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

On Sun, Dec 13, 2009 at 11:49 PM, Takahiro Itagaki
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
>
> Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
>> Well, I think we need to do something.  I don't really want to tack
>> another 5-6% overhead onto EXPLAIN ANALYZE.  Maybe we could recast the
>> doInstrument argument as a set of OR'd flags?
>
> I'm thinking the same thing (OR'd flags) right now.
>
> The attached patch adds INSTRUMENT_TIMER and INSTRUMENT_BUFFERS flags.
> The types of QueryDesc.doInstrument (renamed to instrument_options) and
> EState.es_instrument are changed from bool to int, and they store
> OR of InstrumentOption flags. INSTRUMENT_TIMER is always enabled when
> instrumetations are initialized, but INSTRUMENT_BUFFERS is enabled only if
> we use EXPLAIN BUFFERS. I think the flag options are not so bad idea because
> of extensibility. For example, we could support EXPLAIN CPU_USAGE someday.
>
> One issue is in the top-level instrumentation (queryDesc->totaltime).
> Since the field might be used by multiple plugins, the first initializer
> need to initialize the counter with all options. I used INSTRUMENT_ALL
> for it in the patch.
>
> =# EXPLAIN (ANALYZE) SELECT * FROM pgbench_accounts;
>                                                           QUERY PLAN
> --------------------------------------------------------------------------------------------------------------------------------
>  Seq Scan on pgbench_accounts  (cost=0.00..263935.00 rows=10000000 width=97) (actual time=0.003..572.126 rows=10000000 loops=1)
>  Total runtime: 897.729 ms
>
> =# EXPLAIN (ANALYZE, BUFFERS) SELECT * FROM pgbench_accounts;
>                                                           QUERY PLAN
> --------------------------------------------------------------------------------------------------------------------------------
>  Seq Scan on pgbench_accounts  (cost=0.00..263935.00 rows=10000000 width=97) (actual time=0.002..580.642 rows=10000000 loops=1)
>   Buffers: shared hit=163935
>  Total runtime: 955.744 ms

That seems very promising, but it's almost midnight here so I have to
turn in for now. I'll take another look at this tomorrow.

...Robert

Takahiro Itagaki <itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> writes:
> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Pushing extra arguments around would create overhead of its own ...
>> overhead that would be paid even when not using EXPLAIN at all.

> I cannot understand what you mean... The additional argument should
> not be a performance overhead because the code path is run only once
> per execution.

Hmm, maybe, but still: once you have two flags you're likely to need
more. I concur with turning doInstrument into a bitmask as per Robert's
suggestion downthread.

regards, tom lane

On Sun, Dec 13, 2009 at 11:49 PM, Takahiro Itagaki
<itagaki(dot)takahiro(at)oss(dot)ntt(dot)co(dot)jp> wrote:
> The attached patch [...]

Committed.

...Robert