Subject: Re: Restore of a reference database kills the auto analyze processing.

From: HORDER Philip <[email-masked]>
Date: Wed, 22 May 2024 08:33:39 +0000

Classified as: {OPEN}

> Just for confirmation your settings are still?:

> autovacuum_max_workers = 10
> log_autovacuum_min_duration = 0

Yes.

> You said previously:
> "The only way I can find of getting the analyzer back is to restart Postgres."
>
> To be clear this means:
> 1) The lfm database is dropped/created.
Yes, using dropdb and pg_restore

> 2) There is a round of autovacuum immediately after the lfm is restored.
Yes, some tables in the lfm database, but not all, an apparently random selection, anywhere between 2 and 21 tables, across the lfm schemas, public & pg_catalog.

> 3) autovacuum then goes silent.
Yes. Dead in a ditch. But with no errors.

> 4) Before the next drop/create lfm you restart the Postgres server and autovacuum starts again.
I haven't restarted in a week, and the pattern remains, with a bit of analyze at each reload of lfm, and then nothing.

> What is in the logs when you do the restart?
Nothing notable:
1) denied connections, while restarting
2) authorized connections
3) auto analyze going into overdrive:
See below

> Is there some process that runs shortly after the drop/create lfm cycle?
Not that I can see.

Extract of postgres log for a typical restart :
2024-05-13 05:56:19.151 GMT [4688]: [99-1] db=,user=,app=,client= LOG:  shutting down
2024-05-13 05:56:19.162 GMT [4688]: [100-1] db=,user=,app=,client= LOG:  checkpoint starting: shutdown immediate
2024-05-13 05:56:19.751 GMT [344]: [1-1] db=[unknown],user=[unknown],app=[unknown],client=11.22.33.44 LOG:  connection received: host=11.22.33.44 port=54730
2024-05-13 05:56:19.752 GMT [344]: [2-1] db=postgres,user=a_a,app=[unknown],client=11.22.33.44 FATAL:  the database system is shutting down
2024-05-13 05:56:19.843 GMT [4324]: [1-1] db=[unknown],user=[unknown],app=[unknown],client=11.22.33.44 LOG:  connection received: host=11.22.33.44 port=54731
2024-05-13 05:56:19.845 GMT [4324]: [2-1] db=lfm2,user=fs_admin,app=[unknown],client=11.22.33.44 FATAL:  the database system is shutting down
...
2024-05-13 05:56:20.319 GMT [4688]: [101-1] db=,user=,app=,client= LOG:  checkpoint complete: wrote 326 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.073 s, sync=1.006 s, total=1.168 s; sync files=33, longest=0.281 s, average=0.031 s; distance=588 kB, estimate=26425 kB
2024-05-13 05:57:13.889 GMT [4220]: [1-1] db=,user=,app=,client= LOG:  database system was shut down at 2024-05-13 05:56:20 GMT
2024-05-13 05:57:13.921 GMT [4236]: [1-1] db=[unknown],user=[unknown],app=[unknown],client=11.22.33.44 LOG:  connection received: host=11.22.33.44 port=54863
2024-05-13 05:57:13.922 GMT [4236]: [2-1] db=postgres,user=a_a,app=[unknown],client=11.22.33.44 FATAL:  the database system is starting up
...
2024-05-13 05:57:14.572 GMT [4868]: [1-1] db=[unknown],user=[unknown],app=[unknown],client=11.22.33.44 LOG:  connection received: host=11.22.33.44 port=54869
2024-05-13 05:57:14.608 GMT [4868]: [2-1] db=lfm2,user=fs_admin,app=[unknown],client=11.22.33.44 LOG:  connection authenticated: identity="fs_admin" method=md5 (E:/PostgreSQL/15/data/pg_hba.conf:108)
2024-05-13 05:57:14.608 GMT [4868]: [3-1] db=lfm2,user=fs_admin,app=[unknown],client=11.22.33.44 LOG:  connection authorized: user=fs_admin database=lfm2
...
2024-05-13 05:57:29.305 GMT [6048]: [1-1] db=,user=,app=,client= LOG:  automatic analyze of table "lfm.fs.ij"
avg read rate: 7.813 MB/s, avg write rate: 0.000 MB/s
buffer usage: 350 hits, 5 misses, 0 dirtied
system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.00 s
2024-05-13 05:57:44.209 GMT [6140]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "lfm2.fs.ij": index scans: 0
pages: 0 removed, 2 remain, 2 scanned (100.00% of total)
tuples: 1 removed, 2 remain, 0 are dead but not yet removable
removable cutoff: 597176608, which was 0 XIDs old when operation ended
new relfrozenxid: 597176605, which is 372 XIDs ahead of previous value
index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed
avg read rate: 7.481 MB/s, avg write rate: 5.611 MB/s
buffer usage: 37 hits, 4 misses, 3 dirtied
WAL usage: 3 records, 2 full page images, 15749 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2024-05-13 05:57:59.312 GMT [6064]: [1-1] db=,user=,app=,client= LOG:  automatic vacuum of table "postgres.a.acap": index scans: 1
pages: 0 removed, 1 remain, 1 scanned (100.00% of total)
tuples: 56 removed, 24 remain, 0 are dead but not yet removable
removable cutoff: 597176633, which was 0 XIDs old when operation ended
new relfrozenxid: 597176559, which is 14186 XIDs ahead of previous value
index scan needed: 1 pages from table (100.00% of total) had 56 dead item identifiers removed
index "app_ctxt_area_pk": pages: 6 in total, 0 newly deleted, 3 currently deleted, 3 reusable
index "acap_area_hix": pages: 27 in total, 0 newly deleted, 0 currently deleted, 0 reusable
index "acap_process_id_ix": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable
avg read rate: 18.881 MB/s, avg write rate: 6.743 MB/s
buffer usage: 104 hits, 14 misses, 5 dirtied
WAL usage: 1 records, 1 full page images, 7577 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s

Phil Horder
Database Mechanic

Thales
Land & Air Systems

{OPEN}
The information contained in this e-mail is confidential. It is intended only for the stated addressee(s) and access to it by any other person is unauthorised. If you are not an addressee, you must not disclose, copy, circulate or in any other way use or rely on the information contained in this e-mail. Such unauthorised use may be unlawful. If you have received this e-mail in error, please inform the originator immediately and delete it and all copies from your system.

Thales UK Limited. A company registered in England and Wales. Registered Office: 350 Longwater Avenue, Green Park, Reading, Berks RG2 6GF. Registered Number: 868273

Please consider the environment before printing a hard copy of this e-mail.

---

From: Adrian Klaver <[email-masked]>
Date: Wed, 22 May 2024 08:38:47 -0700

>> Is there some process that runs shortly after the drop/create lfm cycle?

I was hoping more coffee would lead to enlightenment, it did not. It did 
lead me to do what I should have done at the start which is look at the 
release notes for 15.x. You are on Postgres 15.3 and current is 15.7. On 
the path from .5 --> .7 is:

https://www.postgresql.org/docs/15/release-15-5.html#id-1.11.6.7.4

Fix race condition in database dropping that could lead to the 
autovacuum launcher getting stuck (Andres Freund, Will Mortensen, Jacob 
Speidel)

The race could lead to a statistics entry for the removed database 
remaining present, confusing the launcher's selection of which database 
to process.

-- 
Adrian Klaver
[email-masked]