[PostgreSQL-Hackers] Aborted Transaction During Vacuum

Interesting. Is there any additional message appearing in the
postmaster log? Is a core file being generated? (look in the
data/base/ subdirectory for the database in question) If there
is a corefile, a debugger backtrace from it would be helpful.

regards, tom lane

Tom,

I tried the 'vacuum verbose analyze' again today. I get the same error
with the AbortTransaction. There is a core file generated but no pg_vlock
file. The core is over 1 Gig in size (38 Megs gzipped) so I'm not so sure
you'd want to get that (you can have it if you want it though!). Plus,
there seems to be nothing written to the postmaster.log file (I re-started
the postmaster before the vacuum using 'nohup postmaster -i -B 15000 -o -F
Oliver Elphick (Oliver.Elphick@lfix.co.uk) told me that this sounds
like like a bug you patched for him a few days ago:
We're probably talking about the same bug. When I try just 'vacuum verbose'
without the analyze, the vacuum completes just fine. So it must be within
the analyze code.

-Tony

It wouldn't do me any good anyway without a copy of the executable and a
copy of gdb built for whatever platform you are on. I was hoping you
could run gdb on the corefile there and just send the backtrace output
("gdb postgres-executable core-file" and then say "bt").
I doubt it's the same bug --- the error message generated by the other
bug was different...

regards, tom lane

>
The error message I posted was the log output at level 3, which he doesn't
seem to be running; if you switch to logging at that level, look for
messages that mention pg_vlock.

As far as I recall, the only error message he has listed so far is from
psql, which merely records the unlink failure at the end of the vacuum.
Everything else looks remarkably like the vc_abort bug.

But the vc_abort problem didn't cause a backend coredump --- it just
reported an error and failed to complete the vacuum, no?

regards, tom lane

>
>

I got a coredump too; I never mentioned it, because I found the proximate
cause and curing that made it go away. When unlink failed in vc_shutdown,
it called ELOG and a segfault occurred a little later.

I forgot about that when your patch fixed the original problem.

Ah, I wish I'd known that. So what Tony is seeing is exactly the same
behavior you observed. OK, I feel better now --- I thought the coredump
was probably some platform-specific misbehavior that only Tony was seeing.

We still need to figure out what is causing it, because I can see no
reason for a coredump after vc_shutdown elog()s. Something is being
clobbered that should not be. But it sounds like installing the
vc_abort patch will get Tony on his feet, and then we can look for the
secondary bug at our leisure.

regards, tom lane

Here's the error message again:

NOTICE: --Relation ex_ellipse_proc--
NOTICE: --Relation ex_ellipse_proc--
NOTICE: Pages 2545: Changed 0, Reapped 0, Empty 0, New 0; Tup 30535: Vac 0,
Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 660, MaxLen 660; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 1/0 sec.
NOTICE: Pages 2545: Changed 0, Reapped 0, Empty 0, New 0; Tup 30535: Vac 0,
Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 660, MaxLen 660; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 1/0 sec.
NOTICE: Index pkex_ellipse_proc: Pages 138; Tuples 30535. Elapsed 0/0 sec.
NOTICE: Index pkex_ellipse_proc: Pages 138; Tuples 30535. Elapsed 0/0 sec.
NOTICE: --Relation ex_ellipse_cell--
NOTICE: --Relation ex_ellipse_cell--
NOTICE: Pages 370: Changed 0, Reapped 0, Empty 0, New 0; Tup 6109: Vac 0,
Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 80, MaxLen 2736; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 0/0 sec.
NOTICE: Pages 370: Changed 0, Reapped 0, Empty 0, New 0; Tup 6109: Vac 0,
Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 80, MaxLen 2736; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 0/0 sec.
NOTICE: Index pkex_ellipse_cell: Pages 42; Tuples 6109. Elapsed 0/0 sec.
NOTICE: Index pkex_ellipse_cell: Pages 42; Tuples 6109. Elapsed 0/0 sec.
NOTICE: --Relation ex_ellipse_opto--
NOTICE: --Relation ex_ellipse_opto--
NOTICE: Pages 26356: Changed 0, Reapped 0, Empty 0, New 0; Tup 71475: Vac
0, Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 1760, MaxLen 6108; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 3/2 sec.
NOTICE: Pages 26356: Changed 0, Reapped 0, Empty 0, New 0; Tup 71475: Vac
0, Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 1760, MaxLen 6108; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 3/2 sec.
NOTICE: Index pkex_ellipse_opto: Pages 357; Tuples 71475. Elapsed 0/0 sec.
NOTICE: Index pkex_ellipse_opto: Pages 357; Tuples 71475. Elapsed 0/0 sec.
NOTICE: --Relation ex_ellipse_opto_proc--
NOTICE: --Relation ex_ellipse_opto_proc--
NOTICE: Pages 14742: Changed 0, Reapped 0, Empty 0, New 0; Tup 30535: Vac
0, Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 1816, MaxLen 5900; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 1/1 sec.
NOTICE: Pages 14742: Changed 0, Reapped 0, Empty 0, New 0; Tup 30535: Vac
0, Keep/VTL 0/0, Crash 0, UnUsed 0,
MinLen 1816, MaxLen 5900; Re-using: Free/Avail. Space 0/0; EndEmpty/Avail.
Pages 0/0. Elapsed 1/1 sec.
NOTICE: Index pkex_ellipse_opto_proc: Pages 138; Tuples 30535. Elapsed 0/0
sec.
NOTICE: Index pkex_ellipse_opto_proc: Pages 138; Tuples 30535. Elapsed 0/0
sec.
ERROR: vacuum: can't destroy lock file!
NOTICE: AbortTransaction and not in in-progress state
NOTICE: AbortTransaction and not in in-progress state
pqReadData() -- backend closed the channel unexpectedly.
This probably means the backend terminated abnormally
before or while processing the request.
We have lost the connection to the backend, so further processing is
impossible. Terminating.
[postgres@bigred ~]$



-Tony

Yes, I have an ERROR message (either I didn't notice it before or it is
new):

NOTICE: Index pkex_ellipse_opto_proc: Pages 138; Tuples 30535. Elapsed 0/0
sec.
NOTICE: Index pkex_ellipse_opto_proc: Pages 138; Tuples 30535. Elapsed 0/0
sec.
ERROR: vacuum: can't destroy lock file!
NOTICE: AbortTransaction and not in in-progress state
NOTICE: AbortTransaction and not in in-progress state
pqReadData() -- backend closed the channel unexpectedly.
This probably means the backend terminated abnormally
before or while processing the request.
We have lost the connection to the backend, so further processing is
impossible. Terminating.


It looks like the error is either occuring on table ex_ellipse_opto_proc or
the next table in the list ex_ellipse_proc. However, I think the error is
more general than that. It appears to occur just before the last table in
the database gets vacuumed. Here's the list of my tables:

Database = db01
+------------------+----------------------------------+----------+
+------------------+----------------------------------+----------+

Yesterday, I was adding tables in one by one from a previous pg_dump. The
error didn't pop up until after I had about 9 or 10 tables restored. I
didn't think about it then, but it may have always occured after the second
to last table in the list. But don't hold me to that.

In any case, I'll try to re-build everything like you've asked to get a
better error message. Maybe if I go through step-by-step again. You'll be
able to help me find where the error is taking place.

Thanks Tom and Oliver. I'll get back to you when I finish the rebuild.

-Tony

Ah-hah! Oliver is right, then, at least in part --- that error message
from vacuum suggests that the vc_abort bug *is* biting you. However,
there may be more going on, because what Oliver and others observed did
not include a coredump (at least not that I heard about).

You can probably suppress the problem by installing the patch I posted
to pgsql-patches a few days ago. However, I'd appreciate it if you'd
first try to reproduce the problem again with debug/assert turned on,
so that we can get some idea whether there is an additional bug that's
only biting you and not the previous reporters.

BTW, if vc_abort is involved then the occurrence of the problem probably
depends on whether any other backends are using the database and what
they are doing. (The vc_abort bug escaped notice up till last week
because it doesn't trigger when vacuum is the only thing running.)
Do you have other clients running when you do the vacuum? What are
they doing?

regards, tom lane

Tom and Oliver,

I added the patch and re-built everything. No more problems with the
vacuum analyze (knock on wood since this is still Friday the 13th).

Tom, does this patch address the problem you found in your
EndPortalAllocMode comments? I'm just wondering whether another patch
will be needed or if this one should cover the problem.

Thanks again for the help guys.
-Tony


Tom wrote:

I think you need not worry. EndPortalAllocMode has a bug that ought to
be fixed IMHO, but it's only triggered if an error is reported outside
of any transaction context, and there is darn little backend processing
that happens outside of any transaction context. This vacuum shutdown
check might be the only such error, in fact. In short, it's something
to clean up for 6.6, but I doubt it's worth issuing a 6.5 patch for.

regards, tom lane