Re: vacuum as flags in PGPROC

Tom Lane wrote:
> Alvaro Herrera <alvherre(at)commandprompt(dot)com> writes:
> > Also, I forgot to mention it on the first email, but this patch adds
> > errcontext() lines when an autovacuum/analyze is being aborted. It
> > works fine, but I'm not seeing code anywhere else that does something
> > like this.
>
> This is a little bit scary because you might be invoking system catalog
> reads after the transaction has already failed. What would it take to
> save the names involved before starting the TRY block? I'm not worried
> about the errcontext() call per se, only about the syscache fetches.

Hmm, now it's misbehaving strangely. I just got this log output. The
interesting thing is the previous-to-last line (CONTEXT).

29789 DEBUG: autovacuum: processing database "alvherre"
29789 DEBUG: autovac_balance_cost(pid=29789 db=16384, rel=16413, cost_limit=200, cost_delay=20)
29789 DEBUG: vacuuming "public.a"
29790 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29790) exited with exit code 0
29791 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29791) exited with exit code 0
29792 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29792) exited with exit code 0
29793 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29793) exited with exit code 0
29789 DEBUG: "a": removed 1000000 row versions in 4425 pages
29789 DEBUG: "a": found 1000000 removable, 1000000 nonremovable row versions in 8850 pages
29789 DETAIL: 0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
4426 pages contain useful free space.
0 pages are entirely empty.
CPU 0.00s/0.25u sec elapsed 23.91 sec.
29794 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29794) exited with exit code 0
29800 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29800) exited with exit code 0
29744 DEBUG: recycled transaction log file "000000010000000000000064"
29744 DEBUG: recycled transaction log file "000000010000000000000065"
29744 DEBUG: recycled transaction log file "000000010000000000000063"
29806 DEBUG: autovacuum: processing database "alvherre"
29742 DEBUG: server process (PID 29806) exited with exit code 0
29744 LOG: checkpoints are occurring too frequently (9 seconds apart)
29744 HINT: Consider increasing the configuration parameter "checkpoint_segments".
29753 DEBUG: drop auto-cascades to type pg_temp_16413
29753 DEBUG: drop auto-cascades to type pg_temp_16413[]
29789 DEBUG: analyzing "public.a"
29753 DEBUG: sending cancel to blocking autovacuum pid = 29789
29789 ERROR: canceling statement due to user request
29789 CONTEXT: automatic vacuum of table ".."
29742 DEBUG: server process (PID 29789) exited with exit code 0

Note how the cancel log line has a context of ".." instead of the
qualified table name.

What I did was create a big table using Simon's suggested
create table a as select generate_series(1,1000000)::integer as col1;
then launch
update a set col1 = col1 + 1;

When this is finished, autovac starts to vacuum the table; and I run

alter table a alter column col1 type bigint;

This does not cancel the vacuum (because I'm only cancelling in
analyze). When the vacuum is finished, alter table proceeds. When
alter table finishes, the ANALYZE corresponding to the vacuum starts;
then I start another ALTER TABLE and this one is cancelled. That's the
errcontext message that's messed up.

I don't really know what's going on ... I suppose the sigsetjmp() in
PG_TRY is messing things up, but I'm not sure how to fix it. Any
thoughts?

--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.