On Sat, May 19, 2018 at 11:08:23AM -0400, Tom Lane wrote:
> Justin Pryzby <pryzby@xxxxxxxxxxxxx> 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 LEFT JOIN 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 WHERE inhparent='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_0700 LIMIT 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_statistic s 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
