Re: BUG #18773: オートバキュームのリトライ時にreltuplesの値が減少する

Dear David J.,

Thank you very much for your kind words.

I have created a new bug report.

Below is the detailed bug report:

----------------------------------------------------------------------------------------------------------------------------------------

1.Test Environment
① PostgreSQL 13.9 *Using Aurora PostgreSQL.
② Parameters
autovacuum=on
autovacuum_analyze_scale_factor=0.05
autovacuum_analyze_threshold=50
autovacuum_naptime=30
autovacuum_vacuum_cost_delay=20
autovacuum_vacuum_cost_limit=200
autovacuum_vacuum_insert_scale_factor=0.2
autovacuum_vacuum_insert_threshold=1000
autovacuum_vacuum_scale_factor=0.2
autovacuum_vacuum_threshold=50

2.Test to Confirm the Inaccuracy of pg_class.reltuples

The following operations were performed:

① Inserted 50,000 records into a truncated table.
Confirmed that autovacuum and autoanalyze were completed.

devsmtdb=> SELECT relname,n_tup_ins,n_tup_upd,n_tup_del,n_tup_hot_upd,
n_live_tup,n_dead_tup,n_mod_since_analyze,n_ins_since_vacuum,
last_vacuum,last_autovacuum,last_analyze,last_autoanalyze,
vacuum_count,analyze_count,autovacuum_count,autoanalyze_count
from pg_stat_user_tables where relname = 'aa_test';
-[ RECORD 1 ]-------+------------------------------
relname | aa_test
n_tup_ins | 50000
n_tup_upd | 0
n_tup_del | 0
n_tup_hot_upd | 0
n_live_tup | 50000
n_dead_tup | 0
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2025-02-10 17:24:24.507357+09
last_analyze |
last_autoanalyze | 2025-02-10 17:24:24.586928+09
vacuum_count | 0
analyze_count | 0
autovacuum_count | 1
autoanalyze_count | 1

devsmtdb=> SELECT relname,relpages,reltuples FROM PG_CLASS WHERE RELNAME = 'aa_test';
-[ RECORD 1 ]------
relname | aa_test
relpages | 271
reltuples | 50000

devsmtdb=>

② Deleted the first row of the table from Transaction 1, and waited without committing.

devsmtdb=> begin;
BEGIN
devsmtdb=*> delete from aa_test WHERE a = 1;
DELETE 1
devsmtdb=*>

③ Deleted 20,000 rows from Transaction 2 and committed.
Confirmed that autovacuum and autoanalyze were triggered afterward.
Autovacuum did not complete and was skipped.
Autoanalyze finished successfully. → pg_class.reltuples became 30,000.

devsmtdb=> begin;
BEGIN
devsmtdb=*> delete from aa_test WHERE a > 30000;
DELETE 20000
devsmtdb=*>
devsmtdb=*> commit;
COMMIT
devsmtdb=>

devsmtdb=> SELECT relname,n_tup_ins,n_tup_upd,n_tup_del,n_tup_hot_upd,
n_live_tup,n_dead_tup,n_mod_since_analyze,n_ins_since_vacuum,
last_vacuum,last_autovacuum,last_analyze,last_autoanalyze,
vacuum_count,analyze_count,autovacuum_count,autoanalyze_count
from pg_stat_user_tables where relname = 'aa_test';
-[ RECORD 1 ]-------+------------------------------
relname | aa_test
n_tup_ins | 50000
n_tup_upd | 0
n_tup_del | 20000
n_tup_hot_upd | 0
n_live_tup | 30000
n_dead_tup | 20000
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2025-02-10 17:27:24.541284+09
last_analyze |
last_autoanalyze | 2025-02-10 17:27:24.608364+09
vacuum_count | 0
analyze_count | 0
autovacuum_count | 2
autoanalyze_count | 2

devsmtdb=>
devsmtdb=> SELECT relname,relpages,reltuples FROM PG_CLASS WHERE RELNAME = 'aa_test';
-[ RECORD 1 ]------
relname | aa_test
relpages | 271
reltuples | 30000

④ The skipped autovacuum was triggered every 30 seconds. Each time it triggered, pg_class.reltuples decreased.
After about 20 triggers, pg_class.reltuples became approximately 500.

devsmtdb=> SELECT relname,n_tup_ins,n_tup_upd,n_tup_del,n_tup_hot_upd,
n_live_tup,n_dead_tup,n_mod_since_analyze,n_ins_since_vacuum,
last_vacuum,last_autovacuum,last_analyze,last_autoanalyze,
vacuum_count,analyze_count,autovacuum_count,autoanalyze_count
from pg_stat_user_tables where relname = 'aa_test';
-[ RECORD 1 ]-------+------------------------------
relname | aa_test
n_tup_ins | 50000
n_tup_upd | 0
n_tup_del | 20000
n_tup_hot_upd | 0
n_live_tup | 10931
n_dead_tup | 20000
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2025-02-10 17:28:24.572012+09
last_analyze |
last_autoanalyze | 2025-02-10 17:27:24.608364+09
vacuum_count | 0
analyze_count | 0
autovacuum_count | 4
autoanalyze_count | 2

devsmtdb=>
devsmtdb=> SELECT relname,relpages,reltuples FROM PG_CLASS WHERE RELNAME = 'aa_test';
-[ RECORD 1 ]------
relname | aa_test
relpages | 271
reltuples | 10931

・・・skip over the intermediate steps・・・

devsmtdb=> SELECT relname,n_tup_ins,n_tup_upd,n_tup_del,n_tup_hot_upd,
n_live_tup,n_dead_tup,n_mod_since_analyze,n_ins_since_vacuum,
last_vacuum,last_autovacuum,last_analyze,last_autoanalyze,
vacuum_count,analyze_count,autovacuum_count,autoanalyze_count
from pg_stat_user_tables where relname = 'aa_test';
-[ RECORD 1 ]-------+------------------------------
relname | aa_test
n_tup_ins | 50000
n_tup_upd | 0
n_tup_del | 20000
n_tup_hot_upd | 0
n_live_tup | 532
n_dead_tup | 20000
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2025-02-10 17:36:24.76081+09
last_analyze |
last_autoanalyze | 2025-02-10 17:27:24.608364+09
vacuum_count | 0
analyze_count | 0
autovacuum_count | 20
autoanalyze_count | 2

devsmtdb=>
devsmtdb=> SELECT relname,relpages,reltuples FROM PG_CLASS WHERE RELNAME = 'aa_test';
-[ RECORD 1 ]------
relname | aa_test
relpages | 271
reltuples | 532

⑤ Committed Transaction 1.

⑥ Autovacuum completed. pg_class.reltuples remained approximately 530.

devsmtdb=> SELECT relname,n_tup_ins,n_tup_upd,n_tup_del,n_tup_hot_upd,
n_live_tup,n_dead_tup,n_mod_since_analyze,n_ins_since_vacuum,
last_vacuum,last_autovacuum,last_analyze,last_autoanalyze,
vacuum_count,analyze_count,autovacuum_count,autoanalyze_count
from pg_stat_user_tables where relname = 'aa_test';
-[ RECORD 1 ]-------+------------------------------
relname | aa_test
n_tup_ins | 50000
n_tup_upd | 0
n_tup_del | 20001
n_tup_hot_upd | 0
n_live_tup | 530
n_dead_tup | 0
n_mod_since_analyze | 1
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2025-02-10 17:36:54.77512+09
last_analyze |
last_autoanalyze | 2025-02-10 17:27:24.608364+09
vacuum_count | 0
analyze_count | 0
autovacuum_count | 21
autoanalyze_count | 2

devsmtdb=>
devsmtdb=>
devsmtdb=> SELECT relname,relpages,reltuples FROM PG_CLASS WHERE RELNAME = 'aa_test';
-[ RECORD 1 ]------
relname | aa_test
relpages | 163
reltuples | 530

devsmtdb=>

⑦Execution Plan (before analyze)
devsmtdb=> explain analyze select * from aa_test;
-[ RECORD 1 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Seq Scan on aa_test (cost=0.00..168.30 rows=530 width=11) (actual time=0.003..1.359 rows=29999 loops=1)
-[ RECORD 2 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning Time: 0.226 ms
-[ RECORD 3 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution Time: 2.245 ms

devsmtdb=> explain analyze select * from aa_test where a > 20000;
-[ RECORD 1 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Seq Scan on aa_test (cost=0.00..169.62 rows=177 width=11) (actual time=1.565..2.698 rows=10000 loops=1)
-[ RECORD 2 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Filter: (a > '20000'::numeric)
-[ RECORD 3 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Rows Removed by Filter: 19999
-[ RECORD 4 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning Time: 0.095 ms
-[ RECORD 5 ]--------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution Time: 3.005 ms

devsmtdb=>

⑧Executed analyze. pg_class.reltuples became 29,999.

devsmtdb=> SELECT relname,n_tup_ins,n_tup_upd,n_tup_del,n_tup_hot_upd,
n_live_tup,n_dead_tup,n_mod_since_analyze,n_ins_since_vacuum,
last_vacuum,last_autovacuum,last_analyze,last_autoanalyze,
vacuum_count,analyze_count,autovacuum_count,autoanalyze_count
from pg_stat_user_tables where relname = 'aa_test';
-[ RECORD 1 ]-------+------------------------------
relname | aa_test
n_tup_ins | 50000
n_tup_upd | 0
n_tup_del | 20001
n_tup_hot_upd | 0
n_live_tup | 29999
n_dead_tup | 0
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2025-02-10 17:36:54.77512+09
last_analyze | 2025-02-10 17:40:55.471849+09
last_autoanalyze | 2025-02-10 17:27:24.608364+09
vacuum_count | 0
analyze_count | 1
autovacuum_count | 21
autoanalyze_count | 2

devsmtdb=> SELECT relname,relpages,reltuples FROM PG_CLASS WHERE RELNAME = 'aa_test';
-[ RECORD 1 ]------
relname | aa_test
relpages | 163
reltuples | 29999

devsmtdb=>

⑨Execution Plan (after analyze)
devsmtdb=> explain analyze select * from aa_test;
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Seq Scan on aa_test (cost=0.00..462.99 rows=29999 width=11) (actual time=0.004..1.360 rows=29999 loops=1)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning Time: 0.080 ms
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution Time: 2.245 ms

devsmtdb=> explain analyze select * from aa_test where a > 20000;
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Seq Scan on aa_test (cost=0.00..537.99 rows=10000 width=11) (actual time=1.604..2.724 rows=10000 loops=1)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Filter: (a > '20000'::numeric)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Rows Removed by Filter: 19999
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning Time: 0.085 ms
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution Time: 3.030 ms

devsmtdb=>

3.Background of the Issue
Suddenly, an SQL query experienced significant delay.
The cause was the joining of large tables.

The execution plan indicated a join between 1 row and 29 rows, thus choosing a nested loop.
However, in reality, it turned out to be a nested loop with 401,400 rows and 13,380 rows, resulting in a substantial delay.
The person in charge ran ANALYZE to prioritize recovery.
It has not been confirmed if the reduction in pg_class.reltuples was entirely the cause.

During the process of investigating the cause of the SQL query suddenly delaying, it was discovered that pg_class.reltuples had become inaccurate.
It is understood that the execution plan relies on information from pg_class.reltuples,
and the reduction in pg_class.reltuples might have been the cause.
In fact, the table that caused the delay had about 6000 in pg_stat_user_tables.autovacuum_count,
and about 200 in pg_stat_user_tables.autoanalyze_count, indicating that autovacuum retrials were occurring.

There is a concern that inefficient execution plans might occur in the future.

Here is an excerpt of the execution plan for the delayed SQL query.

-> Nested Loop (cost=21.66..26.67 rows=1 width=43) (actual time=214.306..3363978.394 rows=401400 loops=1)
Join Filter: (kn06.sykinid = tb_kn06knmknrkhninf.sykinid)
Rows Removed by Join Filter: 5405252400
-> Hash Join (cost=5.67..7.81 rows=1 width=9) (actual time=6.436..14.643 rows=13380 loops=1)
～～skip～～
-> Nested Loop (cost=15.99..18.50 rows=29 width=34) (actual time=0.012..233.294 rows=404010 loops=13380)
～～skip～～

----------------------------------------------------------------------------------------------------------------------------------------

Best regards,
________________________________
差出人: David G. Johnston <david(dot)g(dot)johnston(at)gmail(dot)com>
送信日時: 2025年2月10日 13:18
宛先: 濱中 弘和 <hamanaka7767(dot)ita(at)al(dot)asahi-life(dot)co(dot)jp>
CC: pgsql-bugs(at)lists(dot)postgresql(dot)org <pgsql-bugs(at)lists(dot)postgresql(dot)org>
件名: Re: BUG #18773: オートバキュームのリトライ時にreltuplesの値が減少する

On Sun, Feb 9, 2025 at 9:10 PM 濱中 弘和 <hamanaka7767(dot)ita(at)al(dot)asahi-life(dot)co(dot)jp<mailto:hamanaka7767(dot)ita(at)al(dot)asahi-life(dot)co(dot)jp>> wrote:
I hope this email finds you well. I would like to apologize in advance for any language mistakes, as my English is not very good. However, I will do my best to communicate clearly.

Regarding the report "BUG #18773: オートバキュームのリトライ時にreltuplesの値が減少する" submitted from the email address "antengynnnn536(at)gmail(dot)com", I am writing to inform you that I work at the same company.

Since this issue could also cause unintended SQL delays for other users, we are hoping for an improvement in this area.

Your English here is quite good. Maybe you can translate the original bug report into English, or just file your own, so that others can review it and know it is reasonably accurate. It is unusual, IME, to use a translation service to perform such conversions - especially for something as technical and precise as a bug report.

David J.

=======================================================================
このE-mailに含まれる情報は、このE-mailの名宛人のみが利用可能な限定された情報です。

万一、当方の誤送信等によりこのE-mailをお受け取りになった場合は、深くお詫び申し上げます。
誠に勝手ではございますが、このメールの印刷、コピー、転送その他
一切のご使用をお控えいただきますようお願いいたします。
お手数をお掛けいたしますが、直ちにこのE-mailを破棄して頂くとともに、誤送信である旨を送信者に通知いただきますようご協力をお願い申し上げます。
=======================================================================
[ex-al]