No access to TOAST tables shown in EXPLAIN ( ANALYZE, BUFFERS )

Hi,

I've found that EXPLAIN (ANALYZE,BUFFERS) does not show any access to the TOAST tables when a toasted column is only
SELECTedand not used in any way in the query.
 
pg_statio_all_tables only shows access to the heap.
I imagine that some optimization does not bother to go into the TOAST table, as its content is neither printed neither
used.

As a consequence, EXPLAIN plans can show huge differences against the actual query results, in buffers count and query
time.As EXPLAIN is supposed to  "display the true row counts and true run time accumulated within each plan node", I
thinkthere may be a problem.
 
I didn't see any related caveats in https://www.postgresql.org/docs/14/using-explain.html#USING-EXPLAIN-CAVEATS



For example, a simple "SELECT" from my one-column table takes ~ 20 ms and reads 9000 buffers, but the EXPLAIN ANALYZE
ismuch much quicker:
 

                               QUERY PLAN                               
------------------------------------------------------------------------
 Seq Scan on public.noises (actual time=0.025..0.393 rows=3000 loops=1)
   Output: noise
   Buffers: shared hit=20
 Query Identifier: 2512658633781838584
 Planning Time: 0.030 ms
 Execution Time: 0.689 ms


If I force the use of the result in the query (concatenation, length…), I see the 9000 missing hits again in the
EXPLAINplan.
 

This seems to be this way since 9.1 at least.
I'm wondering if this can be changed, or at least documented.



SQL script for a full demo is joined. The main parts of the output are below (I hope this is readable):


"8 MB test table"
                                    List of relations
 Schema |  Name  | Type  |  Owner   | Persistence | Access method |  Size   | Description 
--------+--------+-------+----------+-------------+---------------+---------+-------------
 public | noises | table | postgres | unlogged    | heap          | 8384 kB | 

"** Reset stats **"
 

"**"
"** Query : SELECT noise FROM noises  : ~ about 10-20 ms **"
"**"

Time: 16.350 ms
 

  relid  | schemaname |     relname      | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit |
toast_blks_read| toast_blks_hit | tidx_blks_read | tidx_blks_hit 
 

---------+------------+------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 4697174 | public     | noises           |              0 |            20 |               |              |
0 |           3000 |              0 |          6001
 
 4697177 | pg_toast   | pg_toast_4697174 |              0 |          3000 |             0 |         6001 |
  |                |                |              
 

"** Reset stats **"
 

"**"
"** Same query + EXPLAIN ANALYZE : < 1 ms , 20 hits **"
"**"
                               QUERY PLAN                               
------------------------------------------------------------------------
 Seq Scan on public.noises (actual time=0.006..0.199 rows=3000 loops=1)
   Output: noise
   Buffers: shared hit=20
 Query Identifier: 1313741123942831781
 Planning Time: 0.028 ms
 Execution Time: 0.334 ms

 pg_sleep 
----------
 

  relid  | schemaname |     relname      | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit |
toast_blks_read| toast_blks_hit | tidx_blks_read | tidx_blks_hit 
 

---------+------------+------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 4697174 | public     | noises           |              0 |            20 |               |              |
0 |              0 |              0 |             0
 
 4697177 | pg_toast   | pg_toast_4697174 |              0 |             0 |             0 |            0 |
  |                |                |              
 

"** Reset stats **"

"**"
"** Force use of toast data + EXPLAIN ANALYZE : 10-20 ms, 9020 hits **"
"**"
                               QUERY PLAN                               
------------------------------------------------------------------------
 Seq Scan on public.noises (actual time=0.023..9.679 rows=3000 loops=1)
   Output: (noise || ''::text)
   Buffers: shared hit=9020
 Query Identifier: -6122032322937607654
 Planning Time: 0.026 ms
 Execution Time: 9.843 ms

 

  relid  | schemaname |     relname      | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit |
toast_blks_read| toast_blks_hit | tidx_blks_read | tidx_blks_hit 
 

---------+------------+------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 4697174 | public     | noises           |              0 |            20 |               |              |
0 |           3000 |              0 |          6000
 
 4697177 | pg_toast   | pg_toast_4697174 |              0 |          3000 |             0 |         6000 |
  |                |                |              
 





-- 
Christophe Courtois
Consultant Dalibo
https://dalibo.com/