public inbox for [email protected]
help / color / mirror / Atom feedFrom: Christophe Courtois <[email protected]>
To: pgsql-bugs <[email protected]>
Subject: No access to TOAST tables shown in EXPLAIN ( ANALYZE, BUFFERS )
Date: Thu, 27 Jan 2022 11:11:50 +0100
Message-ID: <[email protected]> (raw)
Hi,
I've found that EXPLAIN (ANALYZE,BUFFERS) does not show any access to the TOAST tables when a toasted column is only SELECTed and 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 think there 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 is much 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 EXPLAIN plan.
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/
-- Table de démo
\pset pager off
\pset footer off
SET track_io_timing TO on;
-- some uncompressible noise
CREATE OR REPLACE FUNCTION random_string_pavel(int) RETURNS text AS $$
SELECT array_to_string(
ARRAY (SELECT substring('0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZ' FROM (random() *36)::int FOR 1) FROM generate_series(1, $1) ), '' )
$$ LANGUAGE sql;
\echo "8 MB test table"
DROP TABLE IF EXISTS noises ;
CREATE UNLOGGED TABLE noises AS SELECT random_string_pavel (2500) AS noise FROM generate_series (1, 3000) j ;
VACUUM noises ;
\dt+ noises
SELECT 'noises'::regclass::oid::text AS hoid \gset
SELECT reltoastrelid AS toid FROM pg_class WHERE oid=:hoid \gset
SELECT indexrelid::text AS txoid FROM pg_index WHERE indrelid=:toid \gset
\echo "** Reset stats **"
SELECT pg_sleep(1); -- stats are not updated instantly
SELECT pg_stat_reset_single_table_counters (:hoid),pg_stat_reset_single_table_counters (:toid),pg_stat_reset_single_table_counters (:txoid);
SELECT pg_sleep(1); -- stats are not updated instantly
\echo "**"
\echo "** Query : SELECT noises : ~ about 10-20 ms **"
\echo "**"
\timing on
\o /dev/null
SELECT noise FROM noises ;
\timing off
\o
SELECT pg_sleep(1);
SELECT * FROM pg_statio_all_tables WHERE relid IN (:hoid, :toid);
\echo "** Reset stats **"
SELECT pg_stat_reset_single_table_counters (:hoid),pg_stat_reset_single_table_counters (:toid),pg_stat_reset_single_table_counters (:txoid);
SELECT pg_sleep(1);
\echo "**"
\echo "** Same query + EXPLAIN ANALYZE : < 1 ms , 20 hits **"
\echo "**"
EXPLAIN (ANALYZE,BUFFERS,VERBOSE, COSTS OFF)
SELECT noise FROM noises ;
SELECT pg_sleep(1);
SELECT * FROM pg_statio_all_tables WHERE relid IN (:hoid, :toid);
\echo "** Reset stats **"
SELECT pg_stat_reset_single_table_counters (:hoid),pg_stat_reset_single_table_counters (:toid),pg_stat_reset_single_table_counters (:txoid);
SELECT pg_sleep(1);
\echo "**"
\echo "** Force use of toast data + EXPLAIN ANALYZE : 10-20 ms, 9020 hits **"
\echo "**"
EXPLAIN (ANALYZE,BUFFERS,VERBOSE,COSTS OFF)
SELECT noise||'' FROM noises ;
SELECT pg_sleep(1);
SELECT * FROM pg_statio_all_tables WHERE relid IN (:hoid, :toid);
DROP TABLE noises ;
Attachments:
[text/plain] explain_court-circuite_toasts.sql.txt (2.1K, 2-explain_court-circuite_toasts.sql.txt)
download | inline:
-- Table de démo
\pset pager off
\pset footer off
SET track_io_timing TO on;
-- some uncompressible noise
CREATE OR REPLACE FUNCTION random_string_pavel(int) RETURNS text AS $$
SELECT array_to_string(
ARRAY (SELECT substring('0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZ' FROM (random() *36)::int FOR 1) FROM generate_series(1, $1) ), '' )
$$ LANGUAGE sql;
\echo "8 MB test table"
DROP TABLE IF EXISTS noises ;
CREATE UNLOGGED TABLE noises AS SELECT random_string_pavel (2500) AS noise FROM generate_series (1, 3000) j ;
VACUUM noises ;
\dt+ noises
SELECT 'noises'::regclass::oid::text AS hoid \gset
SELECT reltoastrelid AS toid FROM pg_class WHERE oid=:hoid \gset
SELECT indexrelid::text AS txoid FROM pg_index WHERE indrelid=:toid \gset
\echo "** Reset stats **"
SELECT pg_sleep(1); -- stats are not updated instantly
SELECT pg_stat_reset_single_table_counters (:hoid),pg_stat_reset_single_table_counters (:toid),pg_stat_reset_single_table_counters (:txoid);
SELECT pg_sleep(1); -- stats are not updated instantly
\echo "**"
\echo "** Query : SELECT noises : ~ about 10-20 ms **"
\echo "**"
\timing on
\o /dev/null
SELECT noise FROM noises ;
\timing off
\o
SELECT pg_sleep(1);
SELECT * FROM pg_statio_all_tables WHERE relid IN (:hoid, :toid);
\echo "** Reset stats **"
SELECT pg_stat_reset_single_table_counters (:hoid),pg_stat_reset_single_table_counters (:toid),pg_stat_reset_single_table_counters (:txoid);
SELECT pg_sleep(1);
\echo "**"
\echo "** Same query + EXPLAIN ANALYZE : < 1 ms , 20 hits **"
\echo "**"
EXPLAIN (ANALYZE,BUFFERS,VERBOSE, COSTS OFF)
SELECT noise FROM noises ;
SELECT pg_sleep(1);
SELECT * FROM pg_statio_all_tables WHERE relid IN (:hoid, :toid);
\echo "** Reset stats **"
SELECT pg_stat_reset_single_table_counters (:hoid),pg_stat_reset_single_table_counters (:toid),pg_stat_reset_single_table_counters (:txoid);
SELECT pg_sleep(1);
\echo "**"
\echo "** Force use of toast data + EXPLAIN ANALYZE : 10-20 ms, 9020 hits **"
\echo "**"
EXPLAIN (ANALYZE,BUFFERS,VERBOSE,COSTS OFF)
SELECT noise||'' FROM noises ;
SELECT pg_sleep(1);
SELECT * FROM pg_statio_all_tables WHERE relid IN (:hoid, :toid);
DROP TABLE noises ;
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected]
Subject: Re: No access to TOAST tables shown in EXPLAIN ( ANALYZE, BUFFERS )
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox