Re: postgres=# VACUUM FULL pg_statistic => ERROR: missing chunknumber 0 for toast value .. in pg_toast_2619

On Sat, May 19, 2018 at 11:08:23AM -0400, Tom Lane wrote:
> Justin Pryzby <pryzby@telsasoft.com> writes:
> > I'll defer fixing this for awhile in case someone wants me to save a copy of
> > the relation/toast/index.  From last time, I recall this just needs the right
> > combination of REINDEX/VACUUM/ANALYZE, and the only complication was me
> > needing to realize the right combination of affected DB(s).
> 
> If you could come up with such a sequence that causes the problem
> reproducibly, that would be of huge interest, and probably lead to
> a fix promptly.  But I don't think that we can do much by looking
> at the post-mortem state --- once the toast rows are gone, they're
> gone, especially if the table's been vacuumed since.

This is unlikely to allow reproducing it, but for sake of completeness here's a
fuller log.  I'll try to trigger on another DB.

postgres=# SELECT log_time, database, session_id, left(message,99) FROM postgres_log WHERE log_time BETWEEN '2018-05-19
07:49:01'AND '2018-05-19 07:50' AND (database IS NULL OR database='postgres') ORDER BY 1 ;
 
 2018-05-19 07:49:02.232-06 |          | 5afbc238.382f | checkpoint complete: wrote 32175 buffers (6.1%); 0 WAL file(s)
added,0 removed, 8 recycled; write=
 
 2018-05-19 07:49:02.261-06 | postgres | 5b002b4e.65f2 | statement: SHOW server_version
 2018-05-19 07:49:02.278-06 | postgres | 5b002b4e.65f7 | statement: SELECT
pg_get_indexdef('jrn_postgres_log_log_time_idx'::regclass)
 2018-05-19 07:49:02.29-06  | postgres | 5b002b4e.65f9 | statement: SELECT 1 FROM information_schema.tables WHERE
table_name='postgres_log'LIMIT 1
 
 2018-05-19 07:49:02.311-06 | postgres | 5b002b4e.65fb | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log'
 2018-05-19 07:49:02.324-06 | postgres | 5b002b4e.65fd | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_unique_idx'
 2018-05-19 07:49:02.338-06 | postgres | 5b002b4e.65ff | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_log_time_idx'
 2018-05-19 07:49:02.353-06 | postgres | 5b002b4e.6601 | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_error_severity_idx'
 2018-05-19 07:49:02.37-06  | postgres | 5b002b4e.6603 | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_message_system_idx'
 2018-05-19 07:49:02.39-06  | postgres | 5b002b4e.6605 | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_error_message_idx'
 2018-05-19 07:49:02.405-06 | postgres | 5b002b4e.6607 | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_duration_idx'
 2018-05-19 07:49:02.422-06 | postgres | 5b002b4e.6609 | statement: SELECT 1 FROM pg_class WHERE
relname='jrn_postgres_log_quotedquoted_idx'
 2018-05-19 07:49:02.464-06 | postgres | 5b002b4e.6619 | statement: SELECT 1 FROM pg_class WHERE
relname='postgres_log_2018_05_19_0700'
 2018-05-19 07:49:02.482-06 | postgres | 5b002b4e.661c | statement: COPY postgres_log_2018_05_19_0700 FROM
'/var/log/postgresql/postgresql-2018-05-19_074617
 2018-05-19 07:49:04.711-06 | postgres | 5b002b50.6627 | statement: SELECT 1 FROM pg_class WHERE
relname='postgres_log_2018_05_19_0700'
 2018-05-19 07:49:04.724-06 | postgres | 5b002b50.662a | statement: COPY postgres_log_2018_05_19_0700 FROM
'/var/log/postgresql/postgresql-2018-05-19_074643
 2018-05-19 07:49:06.803-06 | postgres | 5b002b52.6637 | statement: SELECT
pg_get_indexdef('jrn_postgres_log_duration_idx'::regclass)
 2018-05-19 07:49:06.837-06 | postgres | 5b002b52.6639 | statement: SELECT inhrelid::regclass::text FROM pg_inherits i
LEFTJOIN pg_constraint c ON i.inhrel
 
 2018-05-19 07:49:06.867-06 | postgres | 5b002b52.663b | statement: SELECT inhrelid::regclass::text FROM pg_inherits
WHEREinhparent='postgres_log'::regclas
 
 2018-05-19 07:49:06.918-06 | postgres | 5b002b52.6641 | statement: SELECT log_time<now()-'25 hours'::interval FROM
postgres_log_2018_05_18_0700LIMIT 1
 
 2018-05-19 07:49:14.126-06 | postgres | 5b002b5a.66c9 | statement: SELECT DISTINCT ON (session_id) log_time,
session_id,replace(regexp_replace(detail,'^(.
 
 2018-05-19 07:49:32.264-06 |          | 5afbc238.382f | checkpoint starting: time
 2018-05-19 07:49:33.972-06 |          | 5b002b59.66c1 | automatic analyze of table
"ts.public.cdrs_huawei_sgwrecord_2018_05_19"system usage: CPU: user: 6.
 
 2018-05-19 07:49:38.192-06 | postgres | 5b002b72.69d5 | statement: SELECT starelid::regclass, attname FROM
pg_statistics JOIN pg_attribute a              +
 
                            |          |               |                 ON a.attrel
 2018-05-19 07:49:38.232-06 | postgres | 5b002b72.69d8 | statement: DELETE FROM pg_statistic s USING pg_attribute a
WHERE                                  +
 
                            |          |               |                 a.attrelid=s.starelid AND a.attn
 2018-05-19 07:49:38.266-06 | postgres | 5b002b72.69da | statement: SELECT n.nspname as "Schema",
                                   +
 
                            |          |               |   c.relname as "Name",
                                   +
 
                            |          |               |   CASE c.relkind WHEN 'r' THEN 'tab
 2018-05-19 07:49:38.292-06 | postgres | 5b002b72.69dd | statement: VACUUM FULL pg_statistic
 2018-05-19 07:49:38.373-06 | postgres | 5b002b72.69dd | missing chunk number 0 for toast value 730125403 in
pg_toast_2619
...

I doubt it's related, but before VACUUM FULLing pg_statistic, the script does
this (attempting to avoid huge pg_statistic on wide tables partitioned daily,
for which only a handful of the columns are used in query conditions - as an
alternative to SET STATISTICS 0 on 1000+ columns):

DELETE FROM pg_statistic s USING pg_attribute a WHERE
s.starelid::regclass::text~'(_[0-9]{6}|_[0-9]{8})$'
AND NOT (attnotnull OR attname='start_time' OR attname LIKE '%_id')
AND [ some even uglier conditions ]

And the preceding SELECT is to display (with LIMIT) a sample of what's being
DELETEd, since it's not very exact ..

Justin