Re: Proposal: Log inability to lock pages during vacuum

On 12/01/2014 08:55 PM, Jim Nasby wrote:
> On 12/1/14, 11:57 AM, Andres Freund wrote:
>> On 2014-11-30 20:46:51 -0600, Jim Nasby wrote:
>>> On 11/10/14, 7:52 PM, Tom Lane wrote:
>>>> On the whole, I'm +1 for just logging the events and seeing what we learn
>>>> that way. That seems like an appropriate amount of effort for finding out
>>>> whether there is really an issue.
>>>
>>> Attached is a patch that does this.
>>
>> Unless somebody protests I plan to push this soon. I'll change two
>> things:
>>
>> * Always use the same message, independent of scan_all. For one Jim's
>> version would be untranslatable, for another it's not actually
>> correct. In most cases we'll *not* wait, even if scan_all is
>> true as we'll often just balk after !lazy_check_needs_freeze().
>
> Good point.
>
>> * Change the new bit in the errdetail. "could not acquire cleanup lock"
>> sounds too much like an error to me. "skipped %u pinned pages" maybe?
>
> Seems reasonable.

Well, that's not always true either; when freezing, it doesn't skip the
pinned pages, it waits for them.

How about the attached (I also edited the comments a bit)? It looks like
this:

postgres=# vacuum verbose foo;
INFO: vacuuming "public.foo"
INFO: "foo": found 0 removable, 0 nonremovable row versions in 0 out of
7256 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
1 pages were pinned.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: "foo": stopping truncate due to conflicting lock request
INFO: vacuuming "pg_toast.pg_toast_16384"
INFO: index "pg_toast_16384_index" now contains 0 row versions in 1 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.

and for autovacuum log:

LOG: automatic vacuum of table "postgres.public.foo": index scans: 0
pages: 0 removed, 7256 remain, 0 pinned
tuples: 79415 removed, 513156 remain, 0 are dead but not yet removable
buffer usage: 14532 hits, 6 misses, 6241 dirtied
avg read rate: 0.003 MB/s, avg write rate: 3.413 MB/s
system usage: CPU 0.00s/0.30u sec elapsed 14.28 sec

I.e. this just says how many pages were pinned, without saying what was
done about them. That's not very meaningful to an average DBA, but
that's true for many of the numbers printed in vacuum verbose.

- Heikki