Re: BUG #16109: Postgres planning time is high across version - 10.6 vs 10.10

(moved to -hackers)

On Tue, Nov 12, 2019 at 9:55 PM Andres Freund <andres@anarazel.de> wrote:
>
> This last point is more oriented towards other PG developers: I wonder
> if we ought to display buffer statistics for plan time, for EXPLAIN
> (BUFFERS). That'd surely make it easier to discern cases where we
> e.g. access the index and scan a lot of the index from cases where we
> hit some CPU time issue. We should easily be able to get that data, I
> think, we already maintain it, we'd just need to compute the diff
> between pgBufferUsage before / after planning.

That would be quite interesting to have.  I attach as a reference a
quick POC patch to implement it:

# explain (analyze, buffers) select * from pg_stat_activity;
                                                             QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------
 Hash Left Join  (cost=2.25..3.80 rows=100 width=440) (actual
time=0.259..0.276 rows=6 loops=1)
   Hash Cond: (s.usesysid = u.oid)
   Buffers: shared hit=5
   ->  Hash Left Join  (cost=1.05..2.32 rows=100 width=376) (actual
time=0.226..0.236 rows=6 loops=1)
         Hash Cond: (s.datid = d.oid)
         Buffers: shared hit=4
         ->  Function Scan on pg_stat_get_activity s  (cost=0.00..1.00
rows=100 width=312) (actual time=0.148..0.151 rows=6 loop
         ->  Hash  (cost=1.02..1.02 rows=2 width=68) (actual
time=0.034..0.034 rows=5 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 9kB
               Buffers: shared hit=1
               ->  Seq Scan on pg_database d  (cost=0.00..1.02 rows=2
width=68) (actual time=0.016..0.018 rows=5 loops=1)
                     Buffers: shared hit=1
   ->  Hash  (cost=1.09..1.09 rows=9 width=68) (actual
time=0.015..0.015 rows=9 loops=1)
         Buckets: 1024  Batches: 1  Memory Usage: 9kB
         Buffers: shared hit=1
         ->  Seq Scan on pg_authid u  (cost=0.00..1.09 rows=9
width=68) (actual time=0.004..0.008 rows=9 loops=1)
               Buffers: shared hit=1
 Planning Time: 1.902 ms
   Buffers: shared hit=37 read=29
   I/O Timings: read=0.506
 Execution Time: 0.547 ms
(21 rows)

Note that there's a related discussion in the "Planning counters in
pg_stat_statements" thread, on whether to also compute buffers from
planning or not.