Something Weird Going on with VACUUM ANALYZE - Mailing list pgsql-general

From Shaun Thomas
Subject Something Weird Going on with VACUUM ANALYZE
Date
Msg-id 5238BDF6.2080102@optionshouse.com
Whole thread Raw
Responses Re: Something Weird Going on with VACUUM ANALYZE  (Albe Laurenz <laurenz.albe@wien.gv.at>)
Re: Something Weird Going on with VACUUM ANALYZE  (Jeff Janes <jeff.janes@gmail.com>)
List pgsql-general
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@optionshouse.com

______________________________________________

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


pgsql-general by date:

Previous
From: Gregory Haase
Date:
Subject: Re: ZFS snapshots - to use pg_start_backup() and pg_stop_backup() or no?
Next
From: Andreas 'ads' Scherbaum
Date:
Subject: Registration for the German-speaking PostgreSQL Conference is open