On 09/18/2013 11:50 AM, Jeff Janes wrote:
> That line is the final line of a multi-line log entry. To know what
> it is about, you need to look at the lines before it in the logfile.
> Perhaps it is failing to obtain a lock or something.
Thanks for the input, Jeff. The full chunk for that PID (22078) is:
|2013-09-17 03:20:08 CDT|LOG: automatic vacuum of table
"table_redacted": could not (re)acquire exclusive lock for truncate scan
2013-09-17 03:20:08 CDT|STATEMENT: VACUUM (VERBOSE, ANALYZE);
2013-09-17 03:20:37 CDT|LOG: sending cancel to blocking autovacuum PID
23000
DETAIL: Process 22078 waits for ShareUpdateExclusiveLock on relation
18745 of database 16384.
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);
Which suggests an autovacuum was screwing with the launch time of the
database-wide VACUUM VERBOSE, or at least interfered with that one
table. What that doesn't explain, is why the VACUUM VERBOSE would finish
much sooner when this happens. 17 minutes in this case (if it was
blocking, or 37 if it was just stuck on that one table) instead of the
usual 55. I could see it starting later, but it should still take 55
minutes.
It did it again today, but this time, it "finished" in 25 minutes, and
didn't send a cancel to the other autovacuum. The fact it's so much
faster after encountering the truncate scan error, makes me wonder if
the analyze portion (high CPU usage) just plain stops working after that.
The first line also seems extremely misleading. a manually launched
vacuum is not an autovacuum, so why is it complaining about an
autovacuum? Shouldn't the PID doing the autovacuum emit the log message?
This all seems a little sketchy.
--
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