ExecutorEnd gets run twice, which is not good

[Heikki Linnakangas]

I ran into an assertion failure, and it appears that under some
circumstances, ExecutorEnd is run twice on the same query.

(I first bumped into this while testing pull request #386, because that
patch seems to make this situation happen more often, with crash from
interconnect cleanup code, but I can reproduce this assertion on master
too. The root cause of both seems to be that ExecutorEnd is called
twice. This is a bit of a yak-shaving exercise; I started by looking
into the OLAP window error test case being added by PR #417, and
specifically why that test case test takes so long to run, and ended up
staring at this assertion failure.)

Stack trace for the assertion failure looks like this:

#0 0x00007ff6b2f95ae3 in select () at ../sysdeps/unix/syscall-template.S:81
#1 0x0000000000b46988 in pg_usleep (microsec=30000000) at pgsleep.c:43
#2 0x00000000009b5899 in elog_debug_linger (edata=0xf287a8
<errordata+1128>) at elog.c:4088
#3 0x00000000009ae21c in errfinish (dummy=0) at elog.c:602
#4 0x00000000009aca38 in ExceptionalCondition (
conditionName=0xd5f4b0 "!(querySpaceNestingLevel >= 0)",
errorType=0xd5f2d4 "FailedAssertion", fileName=0xd5f3b4
"workfile_queryspace.c",
lineNumber=314) at assert.c:48
#5 0x0000000000a3302c in WorkfileQueryspace_ReleaseEntry () at
workfile_queryspace.c:314
#6 0x00000000006c4f55 in ExecutorEnd (queryDesc=0x2acaa30) at
execMain.c:1064
#7 0x00000000006635f0 in PortalCleanupHelper (portal=0x2abef98,
cleanupstate=0x7ffc3e74900c)
at portalcmds.c:359
#8 0x00000000006634ed in PortalCleanup (portal=0x2abef98) at
portalcmds.c:295
#9 0x00000000009ec24b in AtAbort_Portals () at portalmem.c:660
#10 0x00000000004f47e0 in AbortTransaction () at xact.c:4103
#11 0x00000000004f563f in AbortCurrentTransaction () at xact.c:4738
#12 0x00000000008b2a63 in PostgresMain (argc=1, argv=0x294c490,
dbname=0x294c2c8 "postgres",
username=0x294c288 "heikki") at postgres.c:4504
#13 0x000000000084aee9 in BackendRun (port=0x29536d0) at postmaster.c:6679
#14 0x000000000084a5cb in BackendStartup (port=0x29536d0) at
postmaster.c:6366
#15 0x000000000084336e in ServerLoop () at postmaster.c:2450
#16 0x0000000000841bc4 in PostmasterMain (argc=4, argv=0x292a4a0) at
postmaster.c:1528
#17 0x00000000007646a7 in main (argc=4, argv=0x292a4a0) at main.c:203

The way I can reproduce this is by doing:

set client_min_messages='debug1';
\i sql/cf_olap_windowerr.sql

Where cf_olap_windowerr.sql is the file added by PR #417. While that
runs, I hit CTRL-C to interrupt it, around line 187 in the sql file, so
that the output looks like this:

psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: Interconnect State:
isSender 0 isReceiver 1 snd_queue_depth 2 recv_queue_depth 4
Gp_max_packet_size 8192 UNACK_QUEUE_RING_SLOTS_NUM 2000 TIMER_SPAN 5000
DEFAULT_RTT 20000 forceEOS 1, gp_interconnect_id 380 ic_id_last_teardown
0 snd_buffer_pool.count 0 snd_buffer_pool.maxCount 0 snd_sock_bufsize
2097152 recv_sock_bufsize 2097152 snd_pkt_count 0 retransmits 0
crc_errors 0 recv_pkt_count 0 recv_ack_num 0 recv_queue_size_avg
0.000000 capacity_avg -nan freebuf_avg -nan mismatch_pkt_num 0
disordered_pkt_num 0 duplicated_pkt_num 0 rtt/dev [0/0,
0.000000/0.000000, 0/0] cwnd 0.000000 status_query_msg_num 0
psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: TeardownUDPIFCInterconnect
successful
psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: Deleted entry for query
(sessionid=4, commandcnt=681)
psql:/tmp/cf_olap_windowerr.sql:187: LOG: Process interrupt for 'query
cancel pending'.
psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: closing workfile set:
complete=0 location: pgsql_tmp/workfile_set_Material_Slice0.XXXXwiM8xh,
size=0 in_progress_size=0
psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: workfile mgr cleanup
deleting set: key=0xccccccccd, size=0 in_progress_size=0
path=pgsql_tmp/workfile_set_Material_Slice0.XXXXwiM8xh
psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: deleting spill file set
directory base/12035/pgsql_tmp/workfile_set_Material_Slice0.XXXXwiM8xh
psql:/tmp/cf_olap_windowerr.sql:187: DEBUG1: Subtracting 0 from
workfile diskspace
psql:/tmp/cf_olap_windowerr.sql:187: ERROR: canceling statement due to
user request
FATAL: Unexpected internal error (workfile_queryspace.c:314)
DETAIL: FailedAssertion("!(querySpaceNestingLevel >= 0)", File:
"workfile_queryspace.c", Line: 314)

The test stops at that point for about two seconds, and if you hit
CTRL-C while it's stopped, it will produce the assertion if you're
lucky. The "set client_min_messages=on" is needed, the extra logging
apparently skews the timing just enough to make this happen.

So long story short, I think what's happening is the query is already
doomed, because it hit an ERROR. After the ERROR has been received from
segment, we start to do ExecutorEnd() to clean up. As part of the
cleanup, we send a message to all the segments to cancel the query, and
wait for them to finish. After at least some of the interconnects have
already been teared down, the CTRL-C interrupt arrives, and we jump out
into Abort processing. That in turn calls ExecutorEnd() again, to clean
up. And it gets all confused because we were already in the middle of
the cleanup.

I'm not 100% sure of the details, but something along those lines.

Now, how do we fix that? I think the underlying problem is that we
assume that ExecutorEnd() gets called, and rely on that for resource
cleanup. In PostgreSQL, we specifically *don't* call ExecutorEnd() on a
portal that's already failed, see PortalCleanup(). It does not get
called at abort.

I think we should adopt that convention in GPDB too. It's error-prone to
try to ensure that ExecutorEnd always gets called, even at abort, and
that it only gets called once. Especially when upstream code doesn't try
to guarantee any of that, on the contrary.

So why do we require ExecutorEnd to be called? We should be relying on
MemoryContexts and ResourceOwners for cleaning up, but I'm guessing that
we don't use those mechanisms in all places.

My plan is to change the error handling so that ExecutorEnd() is no
longer called at Abort, and hunt down places where we have currently
relied on that, and make them use ResourceOwners instead. I think some
of the gang management and interconnect code at least needs to be hooked
into ResourceOwners.

Thoughts? Anyone aware of any pitfalls with that? What else does
ExecutorEnd() currently do that we need to take care of, if it's no
longer called on abort?

- Heikki

[Daniel Gustafsson]

> On 23 Feb 2016, at 23:06, Heikki Linnakangas <hlinna...@pivotal.io> wrote:
>
> <snip ...>

>
> Now, how do we fix that? I think the underlying problem is that we assume that ExecutorEnd() gets called, and rely on that for resource cleanup. In PostgreSQL, we specifically *don't* call ExecutorEnd() on a portal that's already failed, see PortalCleanup(). It does not get called at abort.
>
> I think we should adopt that convention in GPDB too. It's error-prone to try to ensure that ExecutorEnd always gets called, even at abort, and that it only gets called once. Especially when upstream code doesn't try to guarantee any of that, on the contrary.

Agreed, it seems a pretty unsafe assumption when upstream breaks it on purpose.

> So why do we require ExecutorEnd to be called? We should be relying on MemoryContexts and ResourceOwners for cleaning up, but I'm guessing that we don't use those mechanisms in all places.
>
> My plan is to change the error handling so that ExecutorEnd() is no longer called at Abort, and hunt down places where we have currently relied on that, and make them use ResourceOwners instead. I think some of the gang management and interconnect code at least needs to be hooked into ResourceOwners.

+1

> Thoughts? Anyone aware of any pitfalls with that? What else does ExecutorEnd() currently do that we need to take care of, if it's no longer called on abort?

There is probably more but the perfmon updates to register the failed query
come to mind. This should be trivial to handle elsewhere though.

cheers ./daniel

[Xin Zhang]

Looping in Ashwin to comment on the ERROR handling.

There might be something relates to the distributed transaction manager (DTM).

I just learned that from DTM talk https://wiki.postgresql.org/images/8/8f/Deciphering_2phase_commit_FOSDEM_2016.pdf

Thanks,

Shin

[Foyzur Rahman]

Executor team will look into it. Subplan/initplan might have something to do with it.

[Xin Zhang]

Wonderful! Thanks. Sorry for misleading here. :)

[Foyzur Rahman]

Nothing to be sorry about. I don't have much clue either. The plan might not even have any subplan/initplan :-)

[Heikki Linnakangas]

(replying to old thread)

On Thursday, February 25, 2016 at 5:09:43 PM UTC+2, Daniel wrote:

> Thoughts? Anyone aware of any pitfalls with that? What else does ExecutorEnd() currently do that we need to take care of, if it's no longer called on abort?

There is probably more but the perfmon updates to register the failed query
come to mind.  This should be trivial to handle elsewhere though.

I just checked, that's handled in mppExecutorCleanup(), which would still get called on abort.

- Heikki