Segfault in MemoryContextAlloc

Hi,

On 2016-01-27 13:24:35 +0300, Dmitriy Sarafannikov wrote:

Hi,�i caught segfault with a simple select query (column and table names in query were changed).
select id_pk2 from table1 where id_pk1 = '9751302'

primary key is (id_pk1, id_pk2)
table1 is (id_pk1 bigint, id_pk2 bigint, date_add timestamp)

(gdb) bt full
#0 MemoryContextAlloc (context=0x0, size=120) at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/utils/mmgr/mcxt.c:584
No locals.
#1 0x00007f6ecc5b8eec in AfterTriggerBeginXact () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/commands/trigger.c:3913
No locals.
#2 0x00007f6ecc4e8c21 in StartTransaction () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:1848
s = 0x7f6eccbc4480 <TopTransactionStateData>
#3 StartTransactionCommand () at /build/postgresql-9.4-MZhK6O/postgresql-9.4-9.4.5/build/../src/backend/access/transam/xact.c:2534
s = 0x7f6eccbc4480 <TopTransactionStateData>
__func__ = "StartTransactionCommand"

That's, uh, weird. TopTransactionContext should never be NULL here. This
is with a stock 9.4.5, without any further extensions configured?

My best guess is that some cache invalidation callback did something
invalid. With
AtStart_Inval();
AtStart_Cache();
AfterTriggerBeginXact();
in StartTransaction(), AtStart_Inval() still had a valid
TopTransactionContext, but AfterTriggerBeginXact() didn't anymore, that
seems like a good guess.

Greetings,

Andres Freund

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

That's, uh, weird. TopTransactionContext should never be NULL here. This
is with a stock 9.4.5, without any further extensions configured?

It is a stock 9.4.5 with pg_buffercache (1.0) and plv8 (1.4.0) installed extensions.

--
Best regards,
Dmitriy Sarafannikov

Hi

2016-01-27 11:47 GMT+01:00 Dmitriy Sarafannikov <dimon99901@mail.ru>:

That's, uh, weird. TopTransactionContext should never be NULL here. This
is with a stock 9.4.5, without any further extensions configured?

It is a stock 9.4.5 with pg_buffercache (1.0) and plv8 (1.4.0) installed
extensions.

I had to fix our log processing extension for 9.5 due NULL
TopTransactionContext. So I can confirm this issue.

When I start database vacuuming by analyze_new_cluster.sh, then Postgres
randomly fails in my extension.

Regards

Pavel

On January 27, 2016 12:23:07 PM GMT+01:00, Pavel Stehule <pavel.stehule@gmail.com> wrote:

Hi

2016-01-27 11:47 GMT+01:00 Dmitriy Sarafannikov <dimon99901@mail.ru>:

That's, uh, weird. TopTransactionContext should never be NULL here.

This

is with a stock 9.4.5, without any further extensions configured?

It is a stock 9.4.5 with pg_buffercache (1.0) and plv8 (1.4.0)

installed

extensions.

I had to fix our log processing extension for 9.5 due NULL
TopTransactionContext. So I can confirm this issue.

But this report isn't about 9.5 afaics.

When I start database vacuuming by analyze_new_cluster.sh, then
Postgres
randomly fails in my extension.

What exactly does your extension do? And where did you add that null check?

Andres

--- 
Please excuse brevity and formatting - I am writing this on my mobile phone.

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

2016-01-27 13:26 GMT+01:00 Andres Freund <andres@anarazel.de>:

On January 27, 2016 12:23:07 PM GMT+01:00, Pavel Stehule <
pavel.stehule@gmail.com> wrote:

Hi

2016-01-27 11:47 GMT+01:00 Dmitriy Sarafannikov <dimon99901@mail.ru>:

That's, uh, weird. TopTransactionContext should never be NULL here.

This

is with a stock 9.4.5, without any further extensions configured?

It is a stock 9.4.5 with pg_buffercache (1.0) and plv8 (1.4.0)

installed

extensions.

I had to fix our log processing extension for 9.5 due NULL
TopTransactionContext. So I can confirm this issue.

But this report isn't about 9.5 afaics.

When I start database vacuuming by analyze_new_cluster.sh, then
Postgres
randomly fails in my extension.

What exactly does your extension do? And where did you add that null check?

this extension does some log preprocessing for syslog

extension and fix attached

Regards

Pavel

2016-01-27 13:26 GMT+01:00 Andres Freund <andres@anarazel.de>:

On January 27, 2016 12:23:07 PM GMT+01:00, Pavel Stehule <
pavel.stehule@gmail.com> wrote:

Hi

2016-01-27 11:47 GMT+01:00 Dmitriy Sarafannikov <dimon99901@mail.ru>:

That's, uh, weird. TopTransactionContext should never be NULL here.

This

is with a stock 9.4.5, without any further extensions configured?

It is a stock 9.4.5 with pg_buffercache (1.0) and plv8 (1.4.0)

installed

extensions.

I had to fix our log processing extension for 9.5 due NULL
TopTransactionContext. So I can confirm this issue.

But this report isn't about 9.5 afaics.

it should not be - we do migration from 9.2 to 9.5 - so this issue can be
related to 9.3, 9.4

Pavel

Pavel Stehule <pavel.stehule@gmail.com> writes:

2016-01-27 13:26 GMT+01:00 Andres Freund <andres@anarazel.de>:

What exactly does your extension do? And where did you add that null check?

this extension does some log preprocessing for syslog
extension and fix attached

That extension is broken on its face. You cannot have an emit_log_hook
that does catalog access, because elog() can be called outside a
transaction or in an already-failed transaction. Whatever band-aids
you put around that will just be band-aids that will fail regularly.
You need to move the catalog lookup someplace else. (Actually, I wonder
why you're doing a catalog lookup at all ... wouldn't it be sufficient to
do a DirectFunctionCall to inet_out?)

I doubt this has much to do with the OP's issue.

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

=?UTF-8?B?RG1pdHJpeSBTYXJhZmFubmlrb3Y=?= <dimon99901@mail.ru> writes:

That's, uh, weird. TopTransactionContext should never be NULL here. This
is with a stock 9.4.5, without any further extensions configured?

It is a stock 9.4.5 with pg_buffercache (1.0) and plv8 (1.4.0) installed extensions.

Both this and the other behavior you reported sure seem like "can't
happen" situations. I do have a theory though: I think you are doing
something that is spawning multiple threads inside the backend, and then
the backend logic goes nuts because it's expecting to be single-threaded.

pg_buffercache wouldn't do that, and a quick google search suggests that
V8 knows nothing of threads either. Have you got anything else going
on in there?

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

2016-02-07 0:30 GMT+01:00 Tom Lane <tgl@sss.pgh.pa.us>:

Pavel Stehule <pavel.stehule@gmail.com> writes:

2016-01-27 13:26 GMT+01:00 Andres Freund <andres@anarazel.de>:

What exactly does your extension do? And where did you add that null

check?

this extension does some log preprocessing for syslog
extension and fix attached

That extension is broken on its face. You cannot have an emit_log_hook
that does catalog access, because elog() can be called outside a
transaction or in an already-failed transaction. Whatever band-aids
you put around that will just be band-aids that will fail regularly.
You need to move the catalog lookup someplace else. (Actually, I wonder
why you're doing a catalog lookup at all ... wouldn't it be sufficient to
do a DirectFunctionCall to inet_out?)

yes - the design was unlucky - and I fixed it without the necessity to
touch system catalogue there.

The interesting on this issue is fact, so this extension in form, that I
sent (badly designed) worked without any problems on 9.1, and 9.2 and
failing with low probability on 9.4, 9.5.

Regards

Pavel

Both this and the other behavior you reported sure seem like "can't
happen" situations. I do have a theory though: I think you are doing
something that is spawning multiple threads inside the backend, and then
the backend logic goes nuts because it's expecting to be single-threaded.

pg_buffercache wouldn't do that, and a quick google search suggests that
V8 knows nothing of threads either. Have you got anything else going
on in there?

No, we don't use anything except sql, plv8 and plpgsql.
it is also sometimes crashes on simplest queries like select 'ping'.
Is it possible that some signal handler resets the TopTransactionContext to NULL?

--
Best regards,
Dmitriy Sarafannikov

Both this and the other behavior you reported sure seem like "can't
happen" situations. I do have a theory though: I think you are doing
something that is spawning multiple threads inside the backend, and then
the backend logic goes nuts because it's expecting to be single-threaded.

pg_buffercache wouldn't do that, and a quick google search suggests that
V8 knows nothing of threads either. Have you got anything else going
on in there?

I caught another segfault, which is similar to previous.
There are 2 threads and in one of this you can see libv8 functions in backtrace, and then
he was interrupted by signal.

Any ideas?

Core was generated by `postgres: xxxx xxxx x.x.x.x(58804) idle '.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 MemoryContextAlloc (context=0x0, size=120) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/utils/mmgr/mcxt.c:584
584 /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/utils/mmgr/mcxt.c: No such file or directory.

(gdb) bt
#0 MemoryContextAlloc (context=0x0, size=120) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/utils/mmgr/mcxt.c:584
#1 0x00007f0e3240c4ac in AfterTriggerBeginXact () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/commands/trigger.c:3913
#2 0x00007f0e3233bea1 in StartTransaction () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/access/transam/xact.c:1848
#3 StartTransactionCommand () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/access/transam/xact.c:2534
#4 0x00007f0e32502761 in ProcessCatchupEvent () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/storage/ipc/sinval.c:337
#5 0x00007f0e32502a5d in HandleCatchupInterrupt () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/storage/ipc/sinval.c:210
#6 0x00007f0e32500c15 in procsignal_sigusr1_handler (postgres_signal_arg=<optimized out>) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/storage/ipc/procsignal.c:272
#7 <signal handler called>
#8 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:84
#9 0x00007f0c0ef0544d in v8::internal::LinuxSemaphore::Wait (this=0x7f0c080008c0) at ../src/platform-linux.cc:880
#10 0x00007f0c0ee235d8 in v8::internal::RuntimeProfiler::WaitForSomeIsolateToEnterJS () at ../src/runtime-profiler.cc:452
#11 0x00007f0c0ee23cf8 in WaitForSomeIsolateToEnterJS () at ../src/runtime-profiler.cc:451
#12 v8::internal::RuntimeProfilerRateLimiter::SuspendIfNecessary (this=this@entry=0x7f0e3468672c) at ../src/runtime-profiler.cc:499
#13 0x00007f0c0ef05690 in v8::internal::SignalSender::Run (this=0x7f0e34686700) at ../src/platform-linux.cc:1160
#14 0x00007f0c0ef053a0 in v8::internal::ThreadEntry (arg=0x7f0e34686700) at ../src/platform-linux.cc:756
#15 0x00007f0e2ef570a4 in start_thread (arg=0x7f0e32820700) at pthread_create.c:309
#16 0x00007f0e305e887d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

(gdb) info threads
Id Target Id Frame
2 Thread 0x7f0e329d2740 (LWP 46202) 0x00007f0e305e972b in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0)
at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
* 1 Thread 0x7f0e32820700 (LWP 46918) MemoryContextAlloc (context=0x0, size=120) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/utils/mmgr/mcxt.c:584

(gdb) thread 2
[Switching to thread 2 (Thread 0x7f0e329d2740 (LWP 46202))]
#0 0x00007f0e305e972b in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
33 ../sysdeps/unix/sysv/linux/x86_64/recv.c: No such file or directory.

(gdb) bt
#0 0x00007f0e305e972b in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
#1 0x00007f0e3244c525 in recv (__flags=0, __n=8192, __buf=0x7f0e32a1b140 <PqRecvBuffer>, __fd=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/socket2.h:44
#2 secure_read (port=0x7f0e34282fe0, ptr=0x7f0e32a1b140 <PqRecvBuffer>, len=8192) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/libpq/be-secure.c:317
#3 0x00007f0e32455e40 in pq_recvbuf () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/libpq/pqcomm.c:862
#4 0x00007f0e32456bb5 in pq_getbyte () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/libpq/pqcomm.c:905
#5 0x00007f0e3251c551 in SocketBackend (inBuf=0x7ffdb8207e20) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/tcop/postgres.c:337
#6 ReadCommand (inBuf=0x7ffdb8207e20) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/tcop/postgres.c:510
#7 PostgresMain (argc=<optimized out>, argv=argv@entry=0x7f0e34241380, dbname=0x7f0e34241350 "xxxx", username=<optimized out>)
at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/tcop/postgres.c:4033
#8 0x00007f0e322e1b34 in BackendRun (port=0x7f0e34282fe0) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/postmaster/postmaster.c:4285
#9 BackendStartup (port=0x7f0e34282fe0) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/postmaster/postmaster.c:3948
#10 ServerLoop () at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/postmaster/postmaster.c:1679
#11 0x00007f0e324c4eab in PostmasterMain (argc=5, argv=<optimized out>) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/postmaster/postmaster.c:1287
#12 0x00007f0e322e2cd2 in main (argc=5, argv=0x7f0e34240570) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/main/main.c:228

Thanks for advance.

--
Best regards,
Dmitriy Sarafannikov

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

=?UTF-8?B?RG1pdHJpeSBTYXJhZmFubmlrb3Y=?= <dimon99901@mail.ru> writes:

Both this and the other behavior you reported sure seem like "can't
happen" situations. I do have a theory though: I think you are doing
something that is spawning multiple threads inside the backend, and then
the backend logic goes nuts because it's expecting to be single-threaded.

I caught another segfault, which is similar to previous.

Uh, well:

(gdb) info threads
Id Target Id Frame
2 Thread 0x7f0e329d2740 (LWP 46202) 0x00007f0e305e972b in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0)
at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
* 1 Thread 0x7f0e32820700 (LWP 46918) MemoryContextAlloc (context=0x0, size=120) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/utils/mmgr/mcxt.c:584

There's not enough information here to disclose what it is that's creating
a second thread, but you need to find that and make it stop.

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

Uh, well:

(gdb) info threads
Id Target Id Frame
2 Thread 0x7f0e329d2740 (LWP 46202) 0x00007f0e305e972b in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0)
at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
* 1 Thread 0x7f0e32820700 (LWP 46918) MemoryContextAlloc (context=0x0, size=120) at /build/postgresql-9.4-1wOG_M/postgresql-9.4-9.4.6/build/../src/backend/utils/mmgr/mcxt.c:584

There's not enough information here to disclose what it is that's creating
a second thread, but you need to find that and make it stop.

Thanks for the answer.

I create new local connection (not via connection pool)

postgres=# select 1;
?column?
----------
1
(1 row)

gdb shows 1 thread

(gdb) info thread
Id Target Id Frame
* 1 Thread 0x7f0e329d2740 (LWP 84804) "postgres" 0x00007f0e305e96cd in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0)
at ../sysdeps/unix/sysv/linux/x86_64/recv.c:29

After that i execute something on plv8

postgres=# do $$ plv8.elog(NOTICE, 'bla-bla-bla') $$ language plv8;
NOTICE: bla-bla-bla
DO

And then gdb shows 2 threads:

(gdb) info thread
Id Target Id Frame
2 Thread 0x7f0e32827700 (LWP 85903) "SignalSender" sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
* 1 Thread 0x7f0e329d2740 (LWP 84804) "postgres" 0x00007f0e305e972b in __libc_recv (fd=13, buf=buf@entry=0x7f0e32a1b140 <PqRecvBuffer>, n=n@entry=8192, flags=-1, flags@entry=0)
at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33

(gdb) thread 2
[Switching to thread 2 (Thread 0x7f0e32827700 (LWP 85903))]
#0 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
85 ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S: No such file or directory.
(gdb) bt
#0 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
#1 0x00007f0c0ed0544d in v8::internal::LinuxSemaphore::Wait (this=0x7f0c080008c0) at ../src/platform-linux.cc:880
#2 0x00007f0c0ec235d8 in v8::internal::RuntimeProfiler::WaitForSomeIsolateToEnterJS () at ../src/runtime-profiler.cc:452
#3 0x00007f0c0ec23cf8 in WaitForSomeIsolateToEnterJS () at ../src/runtime-profiler.cc:451
#4 v8::internal::RuntimeProfilerRateLimiter::SuspendIfNecessary (this=this@entry=0x7f0e342642dc) at ../src/runtime-profiler.cc:499
#5 0x00007f0c0ed05690 in v8::internal::SignalSender::Run (this=0x7f0e342642b0) at ../src/platform-linux.cc:1160
#6 0x00007f0c0ed053a0 in v8::internal::ThreadEntry (arg=0x7f0e342642b0) at ../src/platform-linux.cc:756
#7 0x00007f0e2ef570a4 in start_thread (arg=0x7f0e32827700) at pthread_create.c:309
#8 0x00007f0e305e887d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

It turns out that plv8 creates thread.

--
Best regards,
Dmitriy Sarafannikov
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

=?UTF-8?B?RG1pdHJpeSBTYXJhZmFubmlrb3Y=?= <dimon99901@mail.ru> writes:

It turns out that plv8 creates thread.

That'd be a pretty fundamental bug in plv8 ... I have to think there's
probably more to it than that.

regards, tom lane

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs