pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedRepeated crashes in GENERATED ... AS IDENTITY tests
4+ messages / 3 participants
[nested] [flat]
Commits from this thread:
2018-04-20 676858bcb4 Don't run fast_default regression test in parallel with other tests.
2018-04-20 b1b71f1658 c76d0eed27 168df1b844 fab4ecacc4 Fix race conditions when an event trigger is added concurrently with DDL.
* Repeated crashes in GENERATED ... AS IDENTITY tests
@ 2018-04-17 19:59 Tom Lane <tgl@sss.pgh.pa.us>
2018-04-19 20:49 ` Re: Repeated crashes in GENERATED ... AS IDENTITY tests Alvaro Herrera <alvherre@alvh.no-ip.org>
0 siblings, 1 reply; 4+ messages in thread
From: Tom Lane @ 2018-04-17 19:59 UTC (permalink / raw)
To: pgsql-hackers@lists.postgresql.org
woodlouse just showed a failure that looked a bit familiar:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=woodlouse&dt=2018-04-17%2016%3A42%3A43
I trawled the buildfarm logs for similar failures, and there are several:
sysname | snapshot | stage | l
-----------+---------------------+-------+------------------------------------------------------------------------------------------------------------------------------------------------------------
whelk | 2018-03-28 05:41:30 | Check | 2018-03-28 07:52:26.987 CEST [4928:6] DETAIL: Failed process was running: ALTER TABLE itest13 ADD COLUMN c int GENERATED BY DEFAULT AS IDENTITY;\r
conchuela | 2018-04-03 10:00:00 | Check | 2018-04-03 12:11:47.520 CEST [5ac35311.5248:5] DETAIL: Failed process was running: ALTER TABLE itest13 ADD COLUMN b int GENERATED BY DEFAULT AS IDENTITY;
gharial | 2018-04-10 00:32:08 | Check | 2018-04-09 18:59:39.075 MDT [5acc0b05.32ea:5] DETAIL: Failed process was running: ALTER TABLE itest13 ADD COLUMN b int GENERATED BY DEFAULT AS IDENTITY;
whelk | 2018-04-14 19:41:24 | Check | 2018-04-14 21:52:07.700 CEST [3760:6] DETAIL: Failed process was running: ALTER TABLE itest13 ADD COLUMN c int GENERATED BY DEFAULT AS IDENTITY;\r
woodlouse | 2018-04-17 16:42:43 | Check | 2018-04-17 18:54:04.311 CEST [864:6] DETAIL: Failed process was running: ALTER TABLE itest13 ADD COLUMN b int GENERATED BY DEFAULT AS IDENTITY;\r
(5 rows)
The test case that's failing, in identity.sql, has been there since
early February; the lack of any crashes till more recently suggests
that something committed in mid-to-late March broke it.
I have no idea what's going on there, but I think this is clearly
something we need to consider an open item for PG11. I'll put it
on the list.
regards, tom lane
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Repeated crashes in GENERATED ... AS IDENTITY tests
2018-04-17 19:59 Repeated crashes in GENERATED ... AS IDENTITY tests Tom Lane <tgl@sss.pgh.pa.us>
@ 2018-04-19 20:49 ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2018-04-19 21:23 ` Re: Repeated crashes in GENERATED ... AS IDENTITY tests Tom Lane <tgl@sss.pgh.pa.us>
2018-04-19 21:54 ` Re: Repeated crashes in GENERATED ... AS IDENTITY tests Andrew Gierth <andrew@tao11.riddles.org.uk>
0 siblings, 2 replies; 4+ messages in thread
From: Alvaro Herrera @ 2018-04-19 20:49 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-hackers@lists.postgresql.org
Tom Lane wrote:
> The test case that's failing, in identity.sql, has been there since
> early February; the lack of any crashes till more recently suggests
> that something committed in mid-to-late March broke it.
>
> I have no idea what's going on there, but I think this is clearly
> something we need to consider an open item for PG11. I'll put it
> on the list.
Grumble.
Of the machines you listed, conchuela has gdb installed, which gives us
a nice backtrace of the crash, pasted below, which seems to blame event
triggers. Of the tests in the same parallel group as identity, the test
fast_default seems to be the only one with an event trigger and was
added on March 28th by 16828d5c0273. That combination seems to explain
why the crashes appeared late ...
I can't look further into this now -- maybe next week if nobody has
beaten me into it. My guess is that the identity stuff is not setting
state like event triggers expect.
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=conchuela&dt=2018-04-03%2010%3A00%3A00
================== stack trace: pgsql.build/src/test/regress/tmp_check/data/postgres.core ==================
[New <main task>]
Core was generated by `postgres'.
Program terminated with signal 11, Segmentation fault.
#0 EventTriggerTableRewrite (parsetree=parsetree@entry=0x80a852670, tableOid=49861, reason=2) at event_trigger.c:974
974 currentEventTriggerState->table_rewrite_oid = tableOid;
#0 EventTriggerTableRewrite (parsetree=parsetree@entry=0x80a852670, tableOid=49861, reason=2) at event_trigger.c:974
#1 0x0000000000601bfc in ATRewriteTables (lockmode=8, wqueue=0x7fffffffe3d8, parsetree=0x80a852670) at tablecmds.c:4326
#2 ATController (parsetree=parsetree@entry=0x80a852670, rel=<optimized out>, cmds=<optimized out>, recurse=<optimized out>, lockmode=lockmode@entry=8) at tablecmds.c:3536
#3 0x00000000006021af in AlterTable (relid=relid@entry=49861, lockmode=lockmode@entry=8, stmt=stmt@entry=0x80a852670) at tablecmds.c:3206
#4 0x000000000077df9f in ProcessUtilitySlow (pstate=pstate@entry=0x80a852118, pstmt=pstmt@entry=0x801647110, queryString=queryString@entry=0x801646118 "ALTER TABLE itest13 ADD COLUMN b int GENERATED BY DEFAULT AS IDENTITY;", context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=0x7fffffffe830 "", dest=0x801647400) at utility.c:1116
#5 0x000000000077c632 in standard_ProcessUtility (pstmt=0x801647110, queryString=0x801646118 "ALTER TABLE itest13 ADD COLUMN b int GENERATED BY DEFAULT AS IDENTITY;", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x801647400, completionTag=0x7fffffffe830 "") at utility.c:919
#6 0x0000000000779e05 in PortalRunUtility (portal=0x80a60c118, pstmt=0x801647110, isTopLevel=<optimized out>, setHoldSnapshot=<optimized out>, dest=0x801647400, completionTag=0x7fffffffe830 "") at pquery.c:1183
#7 0x000000000077a925 in PortalRunMulti (portal=portal@entry=0x80a60c118, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=dest@entry=0x801647400, altdest=altdest@entry=0x801647400, completionTag=completionTag@entry=0x7fffffffe830 "") at pquery.c:1336
#8 0x000000000077b5be in PortalRun (portal=portal@entry=0x80a60c118, count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true, run_once=run_once@entry=true, dest=dest@entry=0x801647400, altdest=altdest@entry=0x801647400, completionTag=0x7fffffffe830 "") at pquery.c:804
#9 0x00000000007771e5 in exec_simple_query (query_string=0x801646118 "ALTER TABLE itest13 ADD COLUMN b int GENERATED BY DEFAULT AS IDENTITY;") at postgres.c:1121
#10 0x000000000077869b in PostgresMain (argc=<optimized out>, argv=argv@entry=0x8012f03e8, dbname=0x8012f0190 "regression", username=<optimized out>) at postgres.c:4149
#11 0x0000000000480398 in BackendRun (port=0x8016c0280) at postmaster.c:4409
#12 BackendStartup (port=0x8016c0280) at postmaster.c:4081
#13 ServerLoop () at postmaster.c:1754
#14 0x0000000000701009 in PostmasterMain (argc=argc@entry=8, argv=argv@entry=0x7ffffffff5d0) at postmaster.c:1362
#15 0x0000000000481978 in main (argc=8, argv=0x7ffffffff5d0) at main.c:228
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Repeated crashes in GENERATED ... AS IDENTITY tests
2018-04-17 19:59 Repeated crashes in GENERATED ... AS IDENTITY tests Tom Lane <tgl@sss.pgh.pa.us>
2018-04-19 20:49 ` Re: Repeated crashes in GENERATED ... AS IDENTITY tests Alvaro Herrera <alvherre@alvh.no-ip.org>
@ 2018-04-19 21:23 ` Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 0 replies; 4+ messages in thread
From: Tom Lane @ 2018-04-19 21:23 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: pgsql-hackers@lists.postgresql.org
Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Of the machines you listed, conchuela has gdb installed, which gives us
> a nice backtrace of the crash, pasted below, which seems to blame event
> triggers. Of the tests in the same parallel group as identity, the test
> fast_default seems to be the only one with an event trigger and was
> added on March 28th by 16828d5c0273. That combination seems to explain
> why the crashes appeared late ...
Hm. Our past policy has been that tests involving event triggers must not
run in parallel with any other test, precisely because the event triggers
interact with anything else happening at the same time, and will
inevitably create irreproducible test failures.
I'm inclined to say that whether or not there's a bug here (and there
well may be, it doesn't seem like a crash is a good thing), this is
bad test design and we need to change it.
regards, tom lane
^ permalink raw reply [nested|flat] 4+ messages in thread
* Re: Repeated crashes in GENERATED ... AS IDENTITY tests
2018-04-17 19:59 Repeated crashes in GENERATED ... AS IDENTITY tests Tom Lane <tgl@sss.pgh.pa.us>
2018-04-19 20:49 ` Re: Repeated crashes in GENERATED ... AS IDENTITY tests Alvaro Herrera <alvherre@alvh.no-ip.org>
@ 2018-04-19 21:54 ` Andrew Gierth <andrew@tao11.riddles.org.uk>
1 sibling, 0 replies; 4+ messages in thread
From: Andrew Gierth @ 2018-04-19 21:54 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-hackers@lists.postgresql.org
>>>>> "Alvaro" == Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
Alvaro> I can't look further into this now -- maybe next week if nobody
Alvaro> has beaten me into it. My guess is that the identity stuff is
Alvaro> not setting state like event triggers expect.
I think this is unrelated to the identity stuff. I suspect a race
condition: the event trigger code is implicitly assuming that the event
trigger cache can't pick up new entries in between
EventTriggerStartCompleteQuery and actually firing a table rewrite
operation.
If initially there are no event triggers that require
currentEventTriggerState, then EventTriggerStartCompleteQuery won't
allocate one. But that's done before actually executing the command, so
if we accept invalidations on the cache afterwards, a newly added
trigger might show up, so by the time we reach EventTriggerTableRewrite
we think we have work to do, but currentEventTriggerState is still null.
I haven't been able to reproduce it yet, so this is conjecture, but I
think it's correct. It being a relatively narrow race explains the
relative rarity of the failure.
For the other event trigger types, SQL_DROP checks for
currentEventTriggerState's validity, so it'll simply fail to run the
trigger if one wasn't already present at command start; DDL_COMMAND_END
doesn't actually access currentEventTriggerState at all unless the
trigger function calls pg_event_trigger_ddl_commands, which will falsely
return an error in the race case but won't crash.
So the obvious simple fix would be to have EventTriggerTableRewrite
likewise do nothing if currentEventTriggerState is not set (and it would
be more consistent to do the same for command_end triggers too).
--
Andrew (irc:RhodiumToad)
^ permalink raw reply [nested|flat] 4+ messages in thread
end of thread, other threads:[~2018-04-19 21:54 UTC | newest]
Thread overview: 4+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2018-04-17 19:59 Repeated crashes in GENERATED ... AS IDENTITY tests Tom Lane <tgl@sss.pgh.pa.us>
2018-04-19 20:49 ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2018-04-19 21:23 ` Tom Lane <tgl@sss.pgh.pa.us>
2018-04-19 21:54 ` Andrew Gierth <andrew@tao11.riddles.org.uk>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox