Thread: Postgres backend segfault

Hi, i caught segfault with a simple select query (column and table names in query were changed).

2016-01-26 07:59:06 GMT LOG: server process (PID 62920) was terminated by signal 11: Segmentation fault
2016-01-26 07:59:06 GMT DETAIL: Failed process was running: select field1_bigint from table1 o
where field5_bool and field2_bigint > 0
and field3_int > 0
and field4_timestamp < now() - (field3_int || ' minutes')::interval
and not exists (select 1 from table2 where field1_bigint = o.field1_bigint);
2016-01-26 07:59:06 GMT LOG: terminating any other active server processes

Program terminated with signal SIGSEGV, Segmentation fault.
#0 xactGetCommittedInvalidationMessages (msgs=msgs@entry=0x7ffd3c6b4598, RelcacheInitFileInval=RelcacheInitFileInval@entry=0x7ffd3c6b4587 "")
at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/utils/cache/inval.c:814
814 /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/utils/cache/inval.c: No such file or directory.
(gdb) bt
#0 xactGetCommittedInvalidationMessages (msgs=msgs@entry=0x7ffd3c6b4598, RelcacheInitFileInval=RelcacheInitFileInval@entry=0x7ffd3c6b4587 "")
at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/utils/cache/inval.c:814
#1 0x00007f6ecc4ea791 in RecordTransactionCommit () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:1013
#2 0x00007f6ecc4eacf9 in CommitTransaction () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:1953
#3 0x00007f6ecc4eafd5 in CommitTransactionCommand () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:2732
#4 0x00007f6ecc6ad4d6 in ProcessCatchupEvent () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/storage/ipc/sinval.c:338
#5 0x00007f6ecc6ad815 in EnableCatchupInterrupt () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/storage/ipc/sinval.c:273
#6 0x00007f6ecc6c4dfe in prepare_for_client_read () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:535
#7 0x00007f6ecc5f8d15 in secure_read (port=0x7f6eccead190, ptr=0x7f6eccbc5140 <PqRecvBuffer>, len=8192) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/libpq/be-secure.c:315
#8 0x00007f6ecc602640 in pq_recvbuf () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/libpq/pqcomm.c:862
#9 0x00007f6ecc6033b5 in pq_getbyte () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/libpq/pqcomm.c:905
#10 0x00007f6ecc6c72c1 in SocketBackend (inBuf=0x7ffd3c6b4950) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:337
#11 ReadCommand (inBuf=0x7ffd3c6b4950) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:510
#12 PostgresMain (argc=<optimized out>, argv=argv@entry=0x7f6ecce6b380, dbname=0x7f6ecce6b350 "dbname", username=<optimized out>)
at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:4033
#13 0x00007f6ecc48e92e in BackendRun (port=0x7f6eccead190) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:4252
#14 BackendStartup (port=0x7f6eccead190) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:3917
#15 ServerLoop () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:1678
#16 0x00007f6ecc67158b in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:1287
#17 0x00007f6ecc48fac2 in main (argc=5, argv=0x7f6ecce6a570) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/main/main.c:228

(gdb) bt full
#0 xactGetCommittedInvalidationMessages (msgs=msgs@entry=0x7ffd3c6b4598, RelcacheInitFileInval=RelcacheInitFileInval@entry=0x7ffd3c6b4587 "")
at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/utils/cache/inval.c:814
oldcontext = 0x7f6eccc055f8 <InterruptHoldoffCount>
#1 0x00007f6ecc4ea791 in RecordTransactionCommit () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:1013
xid = 0
markXidCommitted = 0 '\000'
latestXid = 0
nrels = 0
rels = 0x0
nchildren = 0
children = 0x0
nmsgs = 0
invalMessages = 0x0
RelcacheInitFileInval = 0 '\000'
wrote_xlog = <optimized out>
__func__ = "RecordTransactionCommit"
#2 0x00007f6ecc4eacf9 in CommitTransaction () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:1953
s = 0x7f6eccbc4480 <TopTransactionStateData>
latestXid = <optimized out>
__func__ = "CommitTransaction"
#3 0x00007f6ecc4eafd5 in CommitTransactionCommand () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:2732
s = 0x7f6eccbc4480 <TopTransactionStateData>
__func__ = "CommitTransactionCommand"
#4 0x00007f6ecc6ad4d6 in ProcessCatchupEvent () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/storage/ipc/sinval.c:338
notify_enabled = 1 '\001'
__func__ = "ProcessCatchupEvent"
#5 0x00007f6ecc6ad815 in EnableCatchupInterrupt () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/storage/ipc/sinval.c:273
No locals.
#6 0x00007f6ecc6c4dfe in prepare_for_client_read () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:535
No locals.
#7 0x00007f6ecc5f8d15 in secure_read (port=0x7f6eccead190, ptr=0x7f6eccbc5140 <PqRecvBuffer>, len=8192) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/libpq/be-secure.c:315
n = <optimized out>
__func__ = "secure_read"
#8 0x00007f6ecc602640 in pq_recvbuf () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/libpq/pqcomm.c:862
r = <optimized out>
__func__ = "pq_recvbuf"
#9 0x00007f6ecc6033b5 in pq_getbyte () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/libpq/pqcomm.c:905
No locals.
#10 0x00007f6ecc6c72c1 in SocketBackend (inBuf=0x7ffd3c6b4950) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:337
qtype = <optimized out>
#11 ReadCommand (inBuf=0x7ffd3c6b4950) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:510
result = <optimized out>
#12 PostgresMain (argc=<optimized out>, argv=argv@entry=0x7f6ecce6b380, dbname=0x7f6ecce6b350 "dbname", username=<optimized out>)
at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/tcop/postgres.c:4033
firstchar = 1
input_message = {data = 0x7f6ecce84820 "", len = 0, maxlen = 1024, cursor = 0}
local_sigjmp_buf = {{__jmpbuf = {140725617117552, -4238614924085751285, 1, 140113860801384, 140113861071248, 140113858312064, -4238614923683098101, -4320489016603241973}, __mask_was_saved = 1,
__saved_mask = {__val = {0, 140728898420735, 140113857730256, 140113860681408, 140113822954592, 0, 51, 0, 140725617117920, 140725617117920, 140113854018386, 140113858289216, 0, 140725617117920,
0, 0}}}}
send_ready_for_query = 0 '\000'
__func__ = "PostgresMain"
#13 0x00007f6ecc48e92e in BackendRun (port=0x7f6eccead190) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:4252
ac = 1
secs = 507108962
usecs = 957212
i = 1
av = 0x7f6ecce6b380
maxac = <optimized out>
#14 BackendStartup (port=0x7f6eccead190) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:3917
bn = <optimized out>
pid = <optimized out>
#15 ServerLoop () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:1678
rmask = {fds_bits = {256, 0 <repeats 15 times>}}
selres = <optimized out>
readmask = {fds_bits = {960, 0 <repeats 15 times>}}
now = <optimized out>
last_touch_time = 1453791781
__func__ = "ServerLoop"
#16 0x00007f6ecc67158b in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/postmaster/postmaster.c:1287
opt = <optimized out>
status = <optimized out>
userDoption = <optimized out>
listen_addr_saved = 1 '\001'
i = <optimized out>
output_config_variable = <optimized out>
__func__ = "PostmasterMain"
#17 0x00007f6ecc48fac2 in main (argc=5, argv=0x7f6ecce6a570) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/main/main.c:228

--
Best regards,
Dmitriy Sarafannikov

I found that transInvalInfo == NULL

(gdb) print transInvalInfo
$1 = (TransInvalidationInfo *) 0x0

Apparently, he crashes on this row 
*RelcacheInitFileInval = transInvalInfo->RelcacheInitFileInval;

in REL9_5_STABLE branch i see check if transInvalInfo == NULL

/* Quick exit if we haven't done anything with invalidation messages. */
if (transInvalInfo == NULL)
{
*RelcacheInitFileInval = false;
*msgs = NULL;
return 0;
}but in REL9_4_STABLE this check is absent

Вторник, 26 января 2016, 12:42 +03:00 от Dmitriy Sarafannikov <dimon99901@mail.ru>:

--
Best regards,
Dmitriy Sarafannikov

On Tue, Jan 26, 2016 at 6:53 PM, Dmitriy Sarafannikov
<dimon99901@mail.ru> wrote:
> I found that transInvalInfo == NULL
>
> (gdb) print transInvalInfo
> $1 = (TransInvalidationInfo *) 0x0
>
> Apparently, he crashes on this row
> *RelcacheInitFileInval = transInvalInfo->RelcacheInitFileInval;
>
> in REL9_5_STABLE branch i see check if transInvalInfo == NULL
>
> /* Quick exit if we haven't done anything with invalidation messages. */
> if (transInvalInfo == NULL)
> {
> *RelcacheInitFileInval = false;
> *msgs = NULL;
> return 0;
> }
>
> but in REL9_4_STABLE this check is absent

Yes, this check comes from 6cb4afff. In the case of a transaction
commit I am failing to see immediately why transInvalInfo would be
NULL, it is initialized by AtStart_Inval() when starting a
transaction. transInvalInfo becomes NULL only in AtEOXact_Inval()
after the transaction commit is recorded so the code involved looks
correct to me.

> #4 0x00007f6ecc6ad4d6 in ProcessCatchupEvent () at
> /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/storage/ipc/sinval.c:338
> notify_enabled = 1 '\001'
> __func__ = "ProcessCatchupEvent"
> #5 0x00007f6ecc6ad815 in EnableCatchupInterrupt () at
> /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/storage/ipc/sinval.c:273

This is telling that this process is running a cache invalidation
signal outside a transaction block. The only logical explanation that
I see here is that the transaction state of CurrentTransactionState is
not set to TBLOCK_DEFAULT, making transInvalInfo to not be
initialized, but we are sure that it is initialized via
IsTransactionOrTransactionBlock and CurrentTransactionState is set
per-backend. What kind of commands have you run in parallel for this
to happen?

If there is a bug, that's an interesting problem.
--
Michael

Thanks for answer,

This is telling that this process is running a cache invalidation
signal outside a transaction block. The only logical explanation that
I see here is that the transaction state of CurrentTransactionState is
not set to TBLOCK_DEFAULT, making transInvalInfo to not be
initialized, but we are sure that it is initialized via
IsTransactionOrTransactionBlock and CurrentTransactionState is set
per-backend. What kind of commands have you run in parallel for this
to happen?

There were performed parallel only standard commands like select, update, insert, delete, stored procedures which execute select/update/delete/insert

Value of CurrentTransactionState:

(gdb) print *CurrentTransactionState
$1 = {transactionId = 0, subTransactionId = 1, name = 0x0, savepointLevel = 0, state = TRANS_COMMIT, blockState = TBLOCK_STARTED, nestingLevel = 1, gucNestLevel = 1, curTransactionContext = 0x7f6ecdc3de10, 
curTransactionOwner = 0x7f6eccf72800, childXids = 0x0, nChildXids = 0, maxChildXids = 0, prevUser = 21339, prevSecContext = 0, prevXactReadOnly = 0 '\000', startedInRecovery = 0 '\000', 
didLogXid = 0 '\000', parent = 0x0}

--
Best regards,
Dmitriy Sarafannikov