On Fri, 6 Jan 2006, Tom Lane wrote:

> OK, this must be a different issue then. I think we have seen reports
> like this one before, but not been able to reproduce it.
>
> Could you rebuild with Asserts enabled and see if any asserts trigger?

I got an assert to fail. I'm not entirely sure if this is helpful, but I
managed to get a core dump with --enable-debug and --enable-cassert (with
optimizations still on). Let me know if there is anything else that would
be useful to get out of this core file...

(gdb) bt
#0 0x00002aaaab8a0cf9 in kill () from /usr/lib64/libc.so.6
#1 0x00002aaaab8a0a3d in raise () from /usr/lib64/libc.so.6
#2 0x00002aaaab8a1c82 in abort () from /usr/lib64/libc.so.6
#3 0x00000000005f9838 in ExceptionalCondition (
conditionName=0x1abc <Address 0x1abc out of bounds>,
errorType=0x6 <Address 0x6 out of bounds>, fileName=0x0,
lineNumber=-1)
at assert.c:51
#4 0x00000000005eec5d in AtEOXact_CatCache (isCommit=-68 '')
at catcache.c:575
#5 0x000000000047464f in CommitTransaction () at xact.c:1573
#6 0x0000000000474d07 in CommitTransactionCommand () at xact.c:2184
#7 0x00000000005581da in AutoVacMain (argc=6844, argv=0x6) at
autovacuum.c:688
#8 0x0000000000558907 in autovac_start () at autovacuum.c:170
#9 0x000000000055e66b in ServerLoop () at postmaster.c:1269
#10 0x000000000055f9b9 in PostmasterMain (argc=3, argv=0x8832e0)
at postmaster.c:943
#11 0x000000000051fb43 in main (argc=3, argv=0x8832e0) at main.c:256
(gdb) frame 4
#4 0x00000000005eec5d in AtEOXact_CatCache (isCommit=-68 '')
at catcache.c:575
575 Assert(!ct->dead);
(gdb) l
570 {
571 CatCTup *ct = (CatCTup *) DLE_VAL(elt);
572
573 Assert(ct->ct_magic == CT_MAGIC);
574 Assert(ct->refcount == 0);
575 Assert(!ct->dead);
576 }
577 }
578 #endif
579 }
(gdb) set print pretty
(gdb) p *ct
$1 = {
ct_magic = 1462113538,
my_cache = 0x2aaaaaac3060,
lrulist_elem = {
dle_next = 0x0,
dle_prev = 0x939ab0,
dle_val = 0x2aaaaab19e18,
dle_list = 0x93b1a8
},
cache_elem = {
dle_next = 0x0,
dle_prev = 0x934b58,
dle_val = 0x2aaaaab19e18,
dle_list = 0x2aaaaaac36c8
},
c_list = 0x0,
refcount = 0,
dead = 1 '\001',
negative = 0 '\0',
hash_value = 15438,
tuple = {
t_len = 48,
t_self = {
ip_blkid = {
bi_hi = 0,
bi_lo = 0
},
ip_posid = 70
},
t_tableOid = 2602,
t_datamcxt = 0x914998,
t_data = 0x2aaaaab19f30
}
}


---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Jeremy Drake <pgsql@jdrake.com> writes:
> I got an assert to fail. I'm not entirely sure if this is helpful, but I
> managed to get a core dump with --enable-debug and --enable-cassert (with
> optimizations still on). Let me know if there is anything else that would
> be useful to get out of this core file...

Fascinating --- that's not anywhere near where I thought your problem
was. Which cache is this tuple in? (Print *ct->my_cache)

The tableOid implies it's one of the caches on pg_amop, which makes
the whole thing stranger yet. pg_amop doesn't change during normal
operation so there's no reason for one of its tuples to become dead.
You aren't creating/deleting operator classes in this database are
you?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

On Sat, 7 Jan 2006, Tom Lane wrote:

> Fascinating --- that's not anywhere near where I thought your problem
> was. Which cache is this tuple in? (Print *ct->my_cache)

$2 = {
id = 3,
cc_next = 0x2aaaaaac1048,
cc_relname = 0x2aaaaab19df8 "pg_amop",
cc_reloid = 2602,
cc_indexoid = 2654,
cc_relisshared = 0 '\0',
cc_tupdesc = 0x2aaaaab199e0,
cc_reloidattr = 0,
cc_ntup = 3,
cc_nbuckets = 256,
cc_nkeys = 2,
cc_key = {5, 1, 0, 0},
cc_hashfunc = {0x44e1a0 <hashoid>, 0x44e1a0 <hashoid>, 0, 0},
cc_skey = {{
sk_flags = 0,
sk_attno = 5,
sk_strategy = 3,
sk_subtype = 0,
sk_func = {
fn_addr = 0x5bb8c0 <oideq>,
fn_oid = 184,
fn_nargs = 2,
fn_strict = 1 '\001',
fn_retset = 0 '\0',
fn_extra = 0x0,
fn_mcxt = 0x914998,
fn_expr = 0x0
},
sk_argument = 0
}, {
sk_flags = 0,
sk_attno = 1,
sk_strategy = 3,
sk_subtype = 0,
sk_func = {
fn_addr = 0x5bb8c0 <oideq>,
fn_oid = 184,
fn_nargs = 2,
fn_strict = 1 '\001',
fn_retset = 0 '\0',
fn_extra = 0x0,
fn_mcxt = 0x914998,
fn_expr = 0x0
},
sk_argument = 0
}, {
sk_flags = 0,
sk_attno = 0,
sk_strategy = 0,
sk_subtype = 0,
sk_func = {
fn_addr = 0,
fn_oid = 0,
fn_nargs = 0,
fn_strict = 0 '\0',
fn_retset = 0 '\0',
fn_extra = 0x0,
fn_mcxt = 0x0,
fn_expr = 0x0
},
sk_argument = 0
}, {
sk_flags = 0,
sk_attno = 0,
sk_strategy = 0,
sk_subtype = 0,
sk_func = {
fn_addr = 0,
fn_oid = 0,
fn_nargs = 0,
fn_strict = 0 '\0',
fn_retset = 0 '\0',
fn_extra = 0x0,
fn_mcxt = 0x0,
fn_expr = 0x0
},
sk_argument = 0
}},
cc_isname = "\000\000\000",
cc_lists = {
dll_head = 0x935018,
dll_tail = 0x934c50
},
cc_bucket = {{
dll_head = 0x0,
dll_tail = 0x0
}}
}

Am I correct in interpreting this as the hash opclass for Oid? That's
really bizarre. Definately didn't change that.

> The tableOid implies it's one of the caches on pg_amop, which makes
> the whole thing stranger yet. pg_amop doesn't change during normal
> operation so there's no reason for one of its tuples to become dead.
> You aren't creating/deleting operator classes in this database are
> you?

Nope. As a matter of fact, I never created any custom operator classes in
this database.

>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 6: explain analyze is your friend
>

--
Given my druthers, I'd druther not.

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Jeremy Drake <pgsql@jdrake.com> writes:
> Am I correct in interpreting this as the hash opclass for Oid?

No, it's the AMOPOPID catalog cache (containing rows from pg_amop
indexed by amopopr/amopclaid).

After digging around for a bit I noticed that catalog caches get
flushed if someone vacuums the associated catalog. I have a
theory now: somebody vacuumed pg_amop while this process had an
open CatCList of entries from this catcache. ResetCatalogCache
would mark both the CatCList and its member entries as "dead",
because they can't be released while the CatCList has a positive
refcount. When ReleaseCatCacheList is called, it would in turn
call CatCacheRemoveCList ... which would remove the list, but
it doesn't remove the member entries. That's a bug, because the
entries should go away if they're dead and no longer have any
reference counts keeping them in the "zombie" state.

However, AFAICS the only consequence of this bug is to trigger
that Assert failure if you've got Asserts enabled. Dead catcache
entries aren't actually harmful except for wasting some space.
So I don't think this is related to your pg_type duplicate key
problem.

One weak spot in this theory is the assumption that somebody was
vacuuming pg_amop. It seems unlikely that autovacuum would do so
since the table never changes (unless you had reached the point
where an anti-XID-wraparound vacuum was needed, which is unlikely
in itself). Do you have any background processes that do full-database
VACUUMs?

I'll go fix CatCacheRemoveCList, but I think this is not the bug
we're looking for.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

On Sat, 7 Jan 2006, Tom Lane wrote:

> Jeremy Drake <pgsql@jdrake.com> writes:
> > Am I correct in interpreting this as the hash opclass for Oid?
>
> However, AFAICS the only consequence of this bug is to trigger
> that Assert failure if you've got Asserts enabled. Dead catcache
> entries aren't actually harmful except for wasting some space.
> So I don't think this is related to your pg_type duplicate key
> problem.
>
> One weak spot in this theory is the assumption that somebody was
> vacuuming pg_amop. It seems unlikely that autovacuum would do so
> since the table never changes (unless you had reached the point
> where an anti-XID-wraparound vacuum was needed, which is unlikely
> in itself). Do you have any background processes that do full-database
> VACUUMs?

No. Just the autovacuum, which is actually the process which had the
assert failure.

This appears to give the current xid
(gdb) p *s
$10 = {
transactionId = 13568516,
subTransactionId = 1,
name = 0x0,
savepointLevel = 0,
state = TRANS_COMMIT,
blockState = TBLOCK_STARTED,
nestingLevel = 1,
curTransactionContext = 0x9529c0,
curTransactionOwner = 0x92eb40,
childXids = 0x0,
currentUser = 0,
prevXactReadOnly = 0 '\0',
parent = 0x0
}

>
> I'll go fix CatCacheRemoveCList, but I think this is not the bug
> we're looking for.

Incidentally, one of my processes did get that error at the same time.
All of the other processes had an error
DBD::Pg::st execute failed: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

But this one had the DBD::Pg::st execute failed: ERROR: duplicate key
violates unique constraint "pg_type_typname_nsp_index"

It looks like my kernel did not have the option to append the pid to core
files ,so perhaps they both croaked at the same time but only this one got
to write a core file?

I will enable this and try again, see if I can't get it to make 2 cores.

BTW, nothing of any interest made it into the backend log regarding what
assert(s) failed.


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Jeremy Drake <pgsql@jdrake.com> writes:
> On Sat, 7 Jan 2006, Tom Lane wrote:
>> I'll go fix CatCacheRemoveCList, but I think this is not the bug
>> we're looking for.

> Incidentally, one of my processes did get that error at the same time.
> All of the other processes had an error
> DBD::Pg::st execute failed: server closed the connection unexpectedly
> This probably means the server terminated abnormally
> before or while processing the request.
> But this one had the DBD::Pg::st execute failed: ERROR: duplicate key
> violates unique constraint "pg_type_typname_nsp_index"

Oh, that's interesting ... maybe there is some relation after all?
Hard to see what ...

> It looks like my kernel did not have the option to append the pid to core
> files ,so perhaps they both croaked at the same time but only this one got
> to write a core file?

Yeah, they'd all be dumping into the same directory. It's reasonable to
suppose that the corefile you have is from the one that aborted last.
That would suggest that this is effect not cause ... hmmm ...

A bit of a leap in the dark, but: maybe the triggering event for this
situation is not a "VACUUM pg_amop" but a global cache reset due to
sinval message buffer overrun. It's fairly clear how that would lead
to the CatCacheRemoveCList bug. The duplicate-key failure could be an
unrelated bug triggered by the same condition. I have no idea yet what
the mechanism could be, but cache reset is a sufficiently seldom-exercised
code path that it's entirely plausible that there are bugs lurking in it.

If this is correct then we could vastly increase the probability of
seeing the bug by setting up something to force cache resets at a high
rate. If you're interested I could put together a code patch for that.

> BTW, nothing of any interest made it into the backend log regarding what
> assert(s) failed.

What you'd be looking for is a line starting "TRAP:".

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

On Sat, 7 Jan 2006, Tom Lane wrote:

> Jeremy Drake <pgsql@jdrake.com> writes:
> > On Sat, 7 Jan 2006, Tom Lane wrote:
> >> I'll go fix CatCacheRemoveCList, but I think this is not the bug
> >> we're looking for.
>
> A bit of a leap in the dark, but: maybe the triggering event for this
> situation is not a "VACUUM pg_amop" but a global cache reset due to
> sinval message buffer overrun. It's fairly clear how that would lead
> to the CatCacheRemoveCList bug. The duplicate-key failure could be an
> unrelated bug triggered by the same condition. I have no idea yet what
> the mechanism could be, but cache reset is a sufficiently seldom-exercised
> code path that it's entirely plausible that there are bugs lurking in it.
>
> If this is correct then we could vastly increase the probability of
> seeing the bug by setting up something to force cache resets at a high
> rate. If you're interested I could put together a code patch for that.

I tried that function you sent, while running my other code. It died, but
not the same way. None of my processes had the unique constraint error,
but two had failed during commit. Both of them died in that same place as
the last one, on pg_amop.

I think I am going to just run without the function running this time and
see if it does the duplicate type error and if it will generate two cores.




--
To kick or not to kick...
-- Somewhere on IRC, inspired by Shakespeare

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

On Sun, 8 Jan 2006, Tom Lane wrote:

> Yeah, that's not very surprising. Running the forced-cache-resets
> function will definitely expose that catcache bug pretty quickly.
> You'd need to apply the patches I put in yesterday to have a system
> that has any chance of withstanding that treatment for any length of time.
>
> > I think I am going to just run without the function running this time and
> > see if it does the duplicate type error and if it will generate two cores.

I ran without that function you made, and it got the error, but not a
crash. I stuck an Assert(false) right before the ereport for that
particular error, and I did end up with a core there, but I don't see
anything out of the ordinary (what little I know of the ordinary

#0 0x00002aaaab8a0cf9 in kill () from /usr/lib64/libc.so.6
#1 0x00002aaaab8a0a3d in raise () from /usr/lib64/libc.so.6
#2 0x00002aaaab8a1c82 in abort () from /usr/lib64/libc.so.6
#3 0x00000000005f9878 in ExceptionalCondition (
conditionName=0x2c53 <Address 0x2c53 out of bounds>,
errorType=0x6 <Address 0x6 out of bounds>, fileName=0x0,
lineNumber=-1)
at assert.c:51
#4 0x0000000000460967 in _bt_doinsert (rel=0x2aaaaab05568,
btitem=0xbec2c0,
index_is_unique=1 '\001', heapRel=0x8bf0f0) at nbtinsert.c:247
#5 0x0000000000463773 in btinsert (fcinfo=0x2c53) at nbtree.c:228
#6 0x00000000005fe869 in FunctionCall6 (flinfo=0x8, arg1=6, arg2=0,
arg3=18446744073709551615, arg4=0, arg5=0, arg6=0) at fmgr.c:1267
#7 0x000000000045bf4f in index_insert (indexRelation=0x2aaaaab05568,
values=0x7fffffdfde20, isnull=0x7fffffdfde00 "", heap_t_ctid=0xbebeac,
heapRelation=0x8bf0f0, check_uniqueness=1 '\001') at indexam.c:215
#8 0x000000000048f8fa in CatalogIndexInsert (indstate=0x2c53,
heapTuple=0xbebb88) at indexing.c:124
#9 0x000000000048f994 in CatalogUpdateIndexes (heapRel=0x2c53,
heapTuple=0xbebea8) at indexing.c:149
#10 0x000000000049bc67 in TypeCreate (typeName=0x7fffffdfe3e0
"push_tmp",
typeNamespace=11057063, relationOid=12171371, relationKind=114 'r',
internalSize=-16728, typeType=99 'c', typDelim=44 ',',
inputProcedure=2290, outputProcedure=2291, receiveProcedure=2402,
sendProcedure=2403, analyzeProcedure=0, elementType=0, baseType=0,
defaultTypeValue=0x0, defaultTypeBin=0x0, passedByValue=-16 '',
alignment=100 'd', storage=120 'x', typeMod=-1, typNDims=0,
typeNotNull=0 '\0') at pg_type.c:316
#11 0x000000000048c361 in heap_create_with_catalog (
relname=0x7fffffdfe3e0 "push_tmp", relnamespace=11057063,
reltablespace=0, relid=12171371, ownerid=16384, tupdesc=0xbeb8e8,
relkind=114 'r', shared_relation=0 '\0', oidislocal=0 '\0',
oidinhcount=0,
oncommit=ONCOMMIT_DROP, allow_system_table_mods=0 '\0') at heap.c:634
#12 0x00000000004de220 in DefineRelation (stmt=0x93fc30, relkind=114 'r')
at tablecmds.c:423
#13 0x000000000058bfd0 in ProcessUtility (parsetree=0x93fc30, params=0x0,
dest=0x814b40, completionTag=0x0) at utility.c:497
#14 0x0000000000515cb5 in _SPI_execute_plan (plan=0x93f9a8,
Values=0x9c5798,
Nulls=0x9c57b8 "~", '\177' <repeats 199 times>..., snapshot=0x0,
crosscheck_snapshot=0x0, read_only=0 '\0', tcount=0) at spi.c:1449
#15 0x00000000005165fc in SPI_execute_plan (plan=0x93f9a8,
Values=0x9c5798,
Nulls=0x9c57b8 "~", '\177' <repeats 199 times>..., read_only=0 '\0',
tcount=0) at spi.c:336
#16 0x00002aaaac95d8a4 in exec_stmts (estate=0x7fffffdfe950, stmts=0x6)
at pl_exec.c:2280
#17 0x00002aaaac95ebc2 in exec_stmt_block (estate=0x7fffffdfe950,
block=0x8f2c70) at pl_exec.c:936
#18 0x00002aaaac95f5ab in plpgsql_exec_function (func=0x913bc8,
fcinfo=0x7fffffdfea90) at pl_exec.c:286
#19 0x00002aaaac9573f5 in plpgsql_call_handler (fcinfo=0x7fffffdfea90)
at pl_handler.c:123
#20 0x0000000000501a74 in ExecMakeFunctionResult (fcache=0x90a7f0,
econtext=0x90a6c0, isNull=0x90ae38
"\177~\177\177\177\177\177\177!\006",
isDone=0x90aef0) at execQual.c:1095
#21 0x0000000000505543 in ExecProject (projInfo=0x90ae58,
isDone=0x7fffffdfeef4) at execQual.c:3669
#22 0x000000000050ff5a in ExecResult (node=0x90a5a8) at nodeResult.c:157
#23 0x000000000050034d in ExecProcNode (node=0x90a5a8) at
execProcnode.c:306
#24 0x00000000004ff5ea in ExecutorRun (queryDesc=0x90a5a8,
direction=ForwardScanDirection, count=0) at execMain.c:1110
#25 0x000000000058a5de in PortalRunSelect (portal=0x8e6c68, forward=1
'\001',
count=0, dest=0x8dad30) at pquery.c:794
#26 0x000000000058abdf in PortalRun (portal=0x8e6c68,
count=9223372036854775807, dest=0x8dad30, altdest=0x8dad30,
completionTag=0x7fffffdff320 "") at pquery.c:646
#27 0x0000000000588fcb in PostgresMain (argc=9333864, argv=0x8dac18,
username=0x8853f0 "jeremyd") at postgres.c:1754
#28 0x000000000055e20a in ServerLoop () at postmaster.c:2853
#29 0x000000000055f9f9 in PostmasterMain (argc=3, argv=0x8832e0)
at postmaster.c:943
#30 0x000000000051fb83 in main (argc=3, argv=0x8832e0) at main.c:256

>
> Please also look at putting together a test case so others can poke at
> this.

I sent some emails around which should hopefully set this in motion.


---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

Jeremy Drake <pgsql@jdrake.com> writes:
> I ran without that function you made, and it got the error, but not a
> crash. I stuck an Assert(false) right before the ereport for that
> particular error, and I did end up with a core there, but I don't see
> anything out of the ordinary (what little I know of the ordinary

Yeah, that's just the CREATE TEMP TABLE doing what it's supposed to do.
The problem is presumably that a prior DROP operation failed to remove
the pg_type row associated with a previous temp table of the same name
.... but why that would happen is still really unclear.

Does your application drop these temp tables explicitly, or leave them
to be dropped automatically during commit? It might be interesting to
see whether changing that makes any difference. I'm also curious
whether the transaction that makes the temp table is ever rolled back
instead of committed.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

On Mon, 9 Jan 2006, Tom Lane wrote:

> Does your application drop these temp tables explicitly, or leave them
> to be dropped automatically during commit? It might be interesting to
> see whether changing that makes any difference.

I drop them explicitly at the end of the function.

> I'm also curious
> whether the transaction that makes the temp table is ever rolled back
> instead of committed.

Not intentionally/explicitly. The only time it should roll back is if it
gets an error (which tends to be this error). I do sometimes hit ^C on
the perl scripts to tweak something, which would roll it back if in this
particular code, but I don't think i did that on the last run at least.

>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
> choose an index scan if your joining column's datatypes do not
> match
>

--
Every little picofarad has a nanohenry all its own.
-- Don Vonada

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly