Something Weird Going on with VACUUM ANALYZE

Hey,

This is PostgreSQL 9.1.9.

So we've had "vacuumdb -avz" launched via cron at 3am for a few years
now, and recently noticed some queries behaving very badly. While
checking pg_stat_user_tables, I see this for several hundred of them:

relname | last_analyze
---------------------+----------------------------------
some_table | 13-SEP-13 03:27:13.289291 -05:00
another_table | 13-SEP-13 03:33:51.262007 -05:00
yet_another_table | 13-SEP-13 03:23:27.630734 -05:00

Yet last_vacuum shows this:

relname | last_vacuum
--------------------+----------------------------------
some_table | 17-SEP-13 03:23:41.84311 -05:00
another_table | 17-SEP-13 03:21:25.588267 -05:00
yet_another_table | 17-SEP-13 03:21:28.944848 -05:00

So I thought to myself, "Self, that's pretty freaking odd." The last
vacuumdb (with analyze flag enabled) was this morning at 3am.

Apparently something magical happened last Friday, and now analyze is
broken somehow? Am I missing something, here? The log claims everything
worked out OK:

2013-09-17 03:20:37 CDT|STATEMENT: VACUUM (VERBOSE, ANALYZE);
2013-09-17 03:37:31 CDT|LOG: duration: 2246467.567 ms statement:
VACUUM (VERBOSE, ANALYZE);

These are from the same pid doing the vacuum. What's weird, is that the
lines don't match up in time. The reported duration is 37 minutes, and
since the vacuum launches at 3:00am, it matches with the last line. If
that's the case, what on Earth is that line at 3:20 all about? The
durations for the last few days have also been about 50% shorter than
historically, which is mysterious all by itself.

I mean...

WITH stats AS (
SELECT relname,
ceil(extract(epoch FROM last_vacuum)) AS vac_sec,
ceil(extract(epoch FROM last_analyze)) AS an_sec
FROM pg_stat_all_tables
WHERE last_vacuum IS NOT NULL
AND last_analyze IS NOT NULL
)
SELECT sum(CASE WHEN vac_sec = an_sec THEN 1 ELSE 0 END) AS same_vac,
sum(CASE WHEN vac_sec != an_sec THEN 1 ELSE 0 END) AS diff_vac
FROM stats

same_vac | diff_vac
----------+----------
508 | 739

I can't really figure this out. Any help would be appreciated. Since
VACUUM ANALYZE as a single statement is being wonky, I'm willing to use
a script like this until we can figure out the cause:

DO $$
DECLARE
tablename VARCHAR;
schemaname VARCHAR;
BEGIN
FOR schemaname, tablename IN
SELECT s.schemaname, s.relname
FROM pg_stat_all_tables s
WHERE s.last_analyze < CURRENT_DATE
LOOP
EXECUTE 'ANALYZE ' || quote_ident(schemaname) || '.' ||
quote_ident(tablename);
END LOOP;
END;
$$ LANGUAGE plpgsql;

--
Shaun Thomas
OptionsHouse | 141 W. Jackson Blvd. | Suite 500 | Chicago IL, 60604
312-676-8870
sthomas(at)optionshouse(dot)com

______________________________________________

See http://www.peak6.com/email_disclaimer/ for terms and conditions related to this email