Re: Planning counters in pg_stat_statements

On Tue, Nov 7, 2017 at 6:39 PM, Tsunakawa, Takayuki
<tsunakawa(dot)takay(at)jp(dot)fujitsu(dot)com> wrote:
> From: pgsql-hackers-owner(at)postgresql(dot)org
>> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Thomas Munro
>> I have often wanted $SUBJECT and was happy to find that Fujii-san had posted
>> a patch five years ago[1]. The reception then seemed positive.
>> So here is a refurbished and (hopefully) improved version of his patch with
>> a new column for the replan count. Thoughts?
>
> That's a timely proposal. I sometimes faced performance problems where the time pg_stat_statements shows is much shorter than the application perceives. The latest experience was that the execution time of a transaction, which consists of dozens of DMLs and COMMIT, was about 200ms from the application's perspective, while pg_stat_statements showed only about 10ms in total. The network should not be the cause because the application ran on the same host as the database server. I wanted to know how long the parsing and planning time was.

Note that this patch doesn't include the parse or parse analysis
times. I guess they would be less interesting? But perhaps someone
would want to have the complete query production line measured.

BTW the reason I was looking into this was because an Oracle user
asked me how to see "hard parse" times on Postgres, and I've talked to
others who seem strangely concerned with "parsing" time. On Oracle I
believe that term covers (among other things) actually planning, and I
guess planning is the most interesting component. Planning is the
thing I've wanted to measure myself, to diagnose problems relating to
partition/inheritance planning and join explosions and to figure out
which things should be changed to PREPARE/EXECUTE. Perhaps a separate
parse/analysis counter might become more interesting for us if we ever
add automatic plan cache so you could assess how often you're getting
an implicit prepared statement (something like Oracle's "soft parse")?

> BTW, the current pg_stat_statement shows unexpected time for COMMIT. I expect it to include the whole COMMIT processing, including the long WAL flush and sync rep wait. However, it only shows the time for the transaction state change in memory.

That's an interesting point. You could install a transaction hook to
measure that easily enough, but I'm not sure how useful it'd be: you'd
be grouping together COMMIT timing data from transactions that are
doing very different things (including nothing). Would that tell you
anything actionable? If you include commit time for COMMIT statements
then you'd also have to decide whether to include it for DML
statements that run in an implicit transaction. The trouble with that
is that the same statement inside an explicit transaction wouldn't
have any commit time, so you'd be mixing oranges and apples. I guess
you could fix that by putting adding "commits" and "commit_time"
columns (= counters for this statement run as implicit transaction),
but I wonder if commit time monitoring really belongs somewhere else.

For sync rep waits, that's what the pg_stat_replication.XXX_lag
columns tell you.

--
Thomas Munro
http://www.enterprisedb.com