Thread: Postgres 7.4.7 hang in async_notify
We saw the problem with async_notify again (See thread with subject
"Postgres 7.4.6 hang in async_notify" in first message to this list
dated "Mon, 25 Apr 2005 15:42:35 -0400") in a production setting.
Since our last instance, we converted to compiling postgres with
debugging, so we have a stack trace. Looking at it, the problem
appears at first blush like it might be pretty obvious: an ill-timed
signal which arrives during a malloc while malloc has some
data-structure locked, and one of the extensive operations that
Async_NotifyHandler did probably involved getting the same lock. That
doesn't explain everything, since the stack trace looks like it was
munged a little bit and it is not completely obvious to me how we got
from tag_hash to posix_memalign.
For the record, while this postgres should be (of two) generating
notifies out of triggers, we do not believe it should be listening for
any, and indeed examination of pg_listener suggests it does not. If
it matters, the notify should probably have been on the "wwww_aaaaa"
relname.
This was on a 64bit Opteron multiprocessor running Fedora Core 3. As
you see from the stack trace, we have SSL enabled for the connection
from the postgres client.
We have a coredump, binary, and associated build tree if anyone wants
it.
-Seth Robertson
----------------------------------------------------------------------
sysd=> select * from pg_locks;
relation | database | transaction | pid | mode | granted
----------+----------+-------------+-------+-----------------+---------
| | 1452163 | 5043 | ExclusiveLock | t
| | 1408041 | 29980 | ExclusiveLock | t
16759 | 17212 | | 5043 | AccessShareLock | t
----------------------------------------------------------------------
5043 is the above psql. 29980 is the postgres stuck in async_notify:
----------------------------------------------------------------------
sysd=> select * from pg_listener ;
relname | listenerpid | notification
------------------------------+-------------+--------------
kludge_28041 | 28055 | 0
antura_sysd_jobs | 25754 | 0
antura_sysd_files | 25754 | 0
wwww_ssssssss_eeeeeeee | 30219 | 0
sensor_rrrrrrrr_policy | 30219 | 0
kludge_30217 | 30219 | 0
antura_sysd_job_cron_actions | 25754 | 0
wwww_aaaaa | 30219 | 0
Pending | 28055 | 0
(9 rows)
----------------------------------------------------------------------
----------------------------------------------------------------------
29980 ? S 158:06 postgres: sysd sysd 127.0.0.1 async_notify
----------------------------------------------------------------------
----------------------------------------------------------------------
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu"...Using host libthread_db library "/lib64/tls/libthread_db.so.1".
Attaching to program: /usr/counterstorm/postgres/bin/postgres, process 29980
Reading symbols from /lib64/libssl.so.4...done.
Loaded symbols for /lib64/libssl.so.4
Reading symbols from /lib64/libcrypto.so.4...done.
Loaded symbols for /lib64/libcrypto.so.4
Reading symbols from /usr/lib64/libz.so.1...done.
Loaded symbols for /usr/lib64/libz.so.1
Reading symbols from /usr/lib64/libreadline.so.4...done.
Loaded symbols for /usr/lib64/libreadline.so.4
Reading symbols from /lib64/libtermcap.so.2...done.
Loaded symbols for /lib64/libtermcap.so.2
Reading symbols from /lib64/libcrypt.so.1...done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libresolv.so.2...done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /lib64/libnsl.so.1...done.
Loaded symbols for /lib64/libnsl.so.1
Reading symbols from /lib64/libdl.so.2...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/tls/libm.so.6...done.
Loaded symbols for /lib64/tls/libm.so.6
Reading symbols from /lib64/tls/libc.so.6...done.
Loaded symbols for /lib64/tls/libc.so.6
Reading symbols from /usr/lib64/libgssapi_krb5.so.2...done.
Loaded symbols for /usr/lib64/libgssapi_krb5.so.2
Reading symbols from /usr/lib64/libkrb5.so.3...done.
Loaded symbols for /usr/lib64/libkrb5.so.3
Reading symbols from /lib64/libcom_err.so.2...done.
Loaded symbols for /lib64/libcom_err.so.2
Reading symbols from /usr/lib64/libk5crypto.so.3...done.
Loaded symbols for /usr/lib64/libk5crypto.so.3
Reading symbols from /lib64/ld-linux-x86-64.so.2...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libnss_files.so.2...done.
Loaded symbols for /lib64/libnss_files.so.2
Reading symbols from /usr/counterstorm/postgres/lib/plpgsql.so...done.
Loaded symbols for /usr/counterstorm/postgres/lib/plpgsql.so
Reading symbols from /usr/counterstorm/postgres/lib/array_sz.so...done.
Loaded symbols for /usr/counterstorm/postgres/lib/array_sz.so
Reading symbols from /usr/counterstorm/postgres/lib/hostinfo.so...done.
Loaded symbols for /usr/counterstorm/postgres/lib/hostinfo.so
Reading symbols from /usr/counterstorm/postgres/lib/pending.so...done.
Loaded symbols for /usr/counterstorm/postgres/lib/pending.so
0x00000036dacd09ab in __lll_mutex_lock_wait () from /lib64/tls/libc.so.6
(gdb) where
#0 0x00000036dacd09ab in __lll_mutex_lock_wait () from /lib64/tls/libc.so.6
#1 0x00000000185d6840 in ?? ()
#2 0x000000000000000d in ?? ()
#3 0x00000036dac6d181 in posix_memalign () from /lib64/tls/libc.so.6
#4 0x0000000000000001 in ?? ()
#5 0x00000000006cd449 in tag_hash (key=0x36dae2e620, keysize=0) at hashfn.c:40
#6 0x00000000006cd076 in hash_search (hashp=0x2aa221da00, keyPtr=0x7fbfffc6a0, action=20, foundPtr=0x6ccf5c
"\205Àu×ë'A#t$\034ë\230fff\220ff\220H\213-ñ6\"")at dynahash.c:647
#7 0x00000000005ce55e in mdclose (reln=0x1e0) at md.c:384
#8 0x00000000005d0eec in smgrclose (which=-6624, reln=0x2aa221da00) at smgr.c:292
#9 0x00000000006b9dcc in RelationIdInvalidateRelationCacheByRelationId (relationId=2002738) at relcache.c:1748
#10 0x00000000006b5628 in LocalExecuteInvalidationMessage (msg=0x7fbfffc6e0) at inval.c:440
#11 0x00000000005c0388 in ReceiveSharedInvalidMessages (invalFunction=0x6b5550 <LocalExecuteInvalidationMessage>,
resetFunction=0x6b5670<InvalidateSystemCaches>) at sinval.c:125
#12 0x00000000004684d6 in StartTransactionCommand () at xact.c:446
#13 0x00000000004d3a84 in Async_NotifyHandler (postgres_signal_arg=-622664160) at async.c:814
#14 <signal handler called>
#15 0x00000036dac69094 in _int_malloc () from /lib64/tls/libc.so.6
#16 0x00000036dac6ab12 in malloc () from /lib64/tls/libc.so.6
#17 0x00000036dcb4d05b in CRYPTO_malloc () from /lib64/libcrypto.so.4
#18 0x00000036dcb99dc1 in EVP_MD_CTX_copy_ex () from /lib64/libcrypto.so.4
#19 0x00000036dcb585cc in HMAC_Final () from /lib64/libcrypto.so.4
#20 0x00000036db91fe10 in tls1_mac () from /lib64/libssl.so.4
#21 0x00000036db91bcbf in ssl3_read_bytes () from /lib64/libssl.so.4
#22 0x00000036db919a9f in ssl3_renegotiate_check () from /lib64/libssl.so.4
#23 0x000000000053492c in secure_read (port=0x929e80, ptr=0x8a7740, len=8192) at be-secure.c:261
#24 0x000000000053ba47 in pq_getbyte () at pqcomm.c:685
#25 0x00000000005d759d in PostgresMain (argc=9992288, argv=0x52, username=0x7fbfffd660 "") at postgres.c:275
#26 0x00000000005911e4 in PostmasterMain (argc=9470864, argv=0x924a80) at postmaster.c:2561
#27 0x000000000053e0ef in main (argc=4, argv=0x7fbffff6b8) at main.c:214
----------------------------------------------------------------------
pgsql-bugs@counterstorm.com writes:
> We saw the problem with async_notify again (See thread with subject
> "Postgres 7.4.6 hang in async_notify" in first message to this list
> dated "Mon, 25 Apr 2005 15:42:35 -0400") in a production setting.
> Since our last instance, we converted to compiling postgres with
> debugging, so we have a stack trace. Looking at it, the problem
> appears at first blush like it might be pretty obvious: an ill-timed
> signal which arrives during a malloc while malloc has some
> data-structure locked, and one of the extensive operations that
> Async_NotifyHandler did probably involved getting the same lock.
So it would seem. The Async_NotifyHandler mechanism was designed at a
time when ReadCommand didn't call anything of interest except read(),
and so the assumption is that it's OK for PostgresMain to do this
(oversimplified a bit):
EnableNotifyInterrupt();
firstchar = ReadCommand(&input_message);
DisableNotifyInterrupt();
Clearly, if SSL is going to be messing about with malloc() then this
assumption is no longer safe. Looking at the code, I think we have
introduced some other risks of the same ilk ourselves, but SSL is
doubtless the largest variable. This probably explains a number of
other irreproducible failures besides your hangup :-(
I think we're going to have to push the enable/disable interrupt
operations down closer to the actual read(). This doesn't seem to
be any big deal for the non-SSL case, but it's not clear to me what
we have to do to get between SSL and the socket. Anyone know offhand?
> For the record, while this postgres should be (of two) generating
> notifies out of triggers, we do not believe it should be listening for
> any, and indeed examination of pg_listener suggests it does not.
Doesn't matter --- 7.4 uses the same mechanism for SI messaging catchup
interrupts. A backend that sits idle long enough *will* get one of
these interrupts. Apparently you've managed to set up a situation where
the client starts doing something after just-the-right-delay with better
than nil probability.
regards, tom lane
pgsql-bugs@counterstorm.com writes:
> We saw the problem with async_notify again (See thread with subject
> "Postgres 7.4.6 hang in async_notify" in first message to this list
> dated "Mon, 25 Apr 2005 15:42:35 -0400") in a production setting.
I've applied a patch that (I think) will fix this. Attached is the
7.4-branch version of it.
regards, tom lane
Index: src/backend/libpq/be-secure.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/libpq/be-secure.c,v
retrieving revision 1.43.2.1
diff -c -r1.43.2.1 be-secure.c
*** src/backend/libpq/be-secure.c 18 Dec 2003 22:49:34 -0000 1.43.2.1
--- src/backend/libpq/be-secure.c 2 Jun 2005 20:43:58 -0000
***************
*** 79,85 ****
#include <sys/stat.h>
#include <signal.h>
#include <fcntl.h>
- #include <errno.h>
#include <ctype.h>
#include <sys/socket.h>
#include <unistd.h>
--- 79,84 ----
***************
*** 97,102 ****
--- 96,103 ----
#include "libpq/libpq.h"
#include "miscadmin.h"
+ #include "tcop/tcopprot.h"
+
#ifdef USE_SSL
static DH *load_dh_file(int keylength);
***************
*** 301,308 ****
--- 302,315 ----
}
else
#endif
+ {
+ prepare_for_client_read();
+
n = recv(port->sock, ptr, len, 0);
+ client_read_ended();
+ }
+
return n;
}
***************
*** 395,400 ****
--- 402,474 ----
/* SSL specific code */
/* ------------------------------------------------------------ */
#ifdef USE_SSL
+
+ /*
+ * Private substitute BIO: this wraps the SSL library's standard socket BIO
+ * so that we can enable and disable interrupts just while calling recv().
+ * We cannot have interrupts occurring while the bulk of openssl runs,
+ * because it uses malloc() and possibly other non-reentrant libc facilities.
+ *
+ * As of openssl 0.9.7, we can use the reasonably clean method of interposing
+ * a wrapper around the standard socket BIO's sock_read() method. This relies
+ * on the fact that sock_read() doesn't call anything non-reentrant, in fact
+ * not much of anything at all except recv(). If this ever changes we'd
+ * probably need to duplicate the code of sock_read() in order to push the
+ * interrupt enable/disable down yet another level.
+ */
+
+ static bool my_bio_initialized = false;
+ static BIO_METHOD my_bio_methods;
+ static int (*std_sock_read) (BIO *h, char *buf, int size);
+
+ static int
+ my_sock_read(BIO *h, char *buf, int size)
+ {
+ int res;
+
+ prepare_for_client_read();
+
+ res = std_sock_read(h, buf, size);
+
+ client_read_ended();
+
+ return res;
+ }
+
+ static BIO_METHOD *
+ my_BIO_s_socket(void)
+ {
+ if (!my_bio_initialized)
+ {
+ memcpy(&my_bio_methods, BIO_s_socket(), sizeof(BIO_METHOD));
+ std_sock_read = my_bio_methods.bread;
+ my_bio_methods.bread = my_sock_read;
+ my_bio_initialized = true;
+ }
+ return &my_bio_methods;
+ }
+
+ /* This should exactly match openssl's SSL_set_fd except for using my BIO */
+ static int
+ my_SSL_set_fd(SSL *s, int fd)
+ {
+ int ret=0;
+ BIO *bio=NULL;
+
+ bio=BIO_new(my_BIO_s_socket());
+
+ if (bio == NULL)
+ {
+ SSLerr(SSL_F_SSL_SET_FD,ERR_R_BUF_LIB);
+ goto err;
+ }
+ BIO_set_fd(bio,fd,BIO_NOCLOSE);
+ SSL_set_bio(s,bio,bio);
+ ret=1;
+ err:
+ return(ret);
+ }
+
/*
* Load precomputed DH parameters.
*
***************
*** 718,724 ****
Assert(!port->peer);
if (!(port->ssl = SSL_new(SSL_context)) ||
! !SSL_set_fd(port->ssl, port->sock) ||
SSL_accept(port->ssl) <= 0)
{
ereport(COMMERROR,
--- 792,798 ----
Assert(!port->peer);
if (!(port->ssl = SSL_new(SSL_context)) ||
! !my_SSL_set_fd(port->ssl, port->sock) ||
SSL_accept(port->ssl) <= 0)
{
ereport(COMMERROR,
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.375.2.2
diff -c -r1.375.2.2 postgres.c
*** src/backend/tcop/postgres.c 26 Sep 2004 00:26:53 -0000 1.375.2.2
--- src/backend/tcop/postgres.c 2 Jun 2005 20:43:58 -0000
***************
*** 109,114 ****
--- 109,121 ----
static bool xact_started = false;
/*
+ * Flag to indicate that we are doing the outer loop's read-from-client,
+ * as opposed to any random read from client that might happen within
+ * commands like COPY FROM STDIN.
+ */
+ static bool DoingCommandRead = false;
+
+ /*
* Flags to implement skip-till-Sync-after-error behavior for messages of
* the extended query protocol.
*/
***************
*** 400,405 ****
--- 407,456 ----
return result;
}
+ /*
+ * prepare_for_client_read -- set up to possibly block on client input
+ *
+ * This must be called immediately before any low-level read from the
+ * client connection. It is necessary to do it at a sufficiently low level
+ * that there won't be any other operations except the read kernel call
+ * itself between this call and the subsequent client_read_ended() call.
+ * In particular there mustn't be use of malloc() or other potentially
+ * non-reentrant libc functions. This restriction makes it safe for us
+ * to allow interrupt service routines to execute nontrivial code while
+ * we are waiting for input.
+ */
+ void
+ prepare_for_client_read(void)
+ {
+ if (DoingCommandRead)
+ {
+ /* Enable immediate processing of asynchronous signals */
+ EnableNotifyInterrupt();
+
+ /* Allow "die" interrupt to be processed while waiting */
+ ImmediateInterruptOK = true;
+
+ /* And don't forget to detect one that already arrived */
+ QueryCancelPending = false;
+ CHECK_FOR_INTERRUPTS();
+ }
+ }
+
+ /*
+ * client_read_ended -- get out of the client-input state
+ */
+ void
+ client_read_ended(void)
+ {
+ if (DoingCommandRead)
+ {
+ ImmediateInterruptOK = false;
+ QueryCancelPending = false; /* forget any CANCEL signal */
+
+ DisableNotifyInterrupt();
+ }
+ }
+
/*
* Parse a query string and pass it through the rewriter.
***************
*** 2706,2711 ****
--- 2757,2763 ----
CritSectionCount = 0; /* should be unnecessary, but... */
disable_sig_alarm(true);
QueryCancelPending = false; /* again in case timeout occurred */
+ DoingCommandRead = false;
DisableNotifyInterrupt();
debug_query_string = NULL;
***************
*** 2814,2833 ****
}
/*
! * (2) deal with pending asynchronous NOTIFY from other backends,
! * and enable async.c's signal handler to execute NOTIFY directly.
! * Then set up other stuff needed before blocking for input.
*/
! QueryCancelPending = false; /* forget any earlier CANCEL
! * signal */
!
! EnableNotifyInterrupt();
!
! /* Allow "die" interrupt to be processed while waiting */
! ImmediateInterruptOK = true;
! /* and don't forget to detect one that already arrived */
! QueryCancelPending = false;
! CHECK_FOR_INTERRUPTS();
/*
* (3) read a command (loop blocks here)
--- 2866,2878 ----
}
/*
! * (2) Allow asynchronous signals to be executed immediately
! * if they come in while we are waiting for client input.
! * (This must be conditional since we don't want, say, reads on
! * behalf of COPY FROM STDIN doing the same thing.)
*/
! QueryCancelPending = false; /* forget any earlier CANCEL signal */
! DoingCommandRead = true;
/*
* (3) read a command (loop blocks here)
***************
*** 2837,2846 ****
/*
* (4) disable async signal conditions again.
*/
! ImmediateInterruptOK = false;
! QueryCancelPending = false; /* forget any CANCEL signal */
!
! DisableNotifyInterrupt();
/*
* (5) check for any other interesting events that happened while
--- 2882,2888 ----
/*
* (4) disable async signal conditions again.
*/
! DoingCommandRead = false;
/*
* (5) check for any other interesting events that happened while
Index: src/include/tcop/tcopprot.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/tcop/tcopprot.h,v
retrieving revision 1.60
diff -c -r1.60 tcopprot.h
*** src/include/tcop/tcopprot.h 4 Aug 2003 02:40:15 -0000 1.60
--- src/include/tcop/tcopprot.h 2 Jun 2005 20:43:58 -0000
***************
*** 49,54 ****
--- 49,56 ----
extern void die(SIGNAL_ARGS);
extern void quickdie(SIGNAL_ARGS);
extern void authdie(SIGNAL_ARGS);
+ extern void prepare_for_client_read(void);
+ extern void client_read_ended(void);
extern int PostgresMain(int argc, char *argv[], const char *username);
extern void ResetUsage(void);
extern void ShowUsage(const char *title);
In message <28071.1117746362@sss.pgh.pa.us>, Tom Lane writes:
pgsql-bugs@counterstorm.com writes:
> We saw the problem with async_notify again (See thread with subject
> "Postgres 7.4.6 hang in async_notify" in first message to this list
> dated "Mon, 25 Apr 2005 15:42:35 -0400") in a production setting.
I've applied a patch that (I think) will fix this. Attached is the
7.4-branch version of it.
You are amazing as always. We will test it out and see how it goes.
Unfortunately since we don't have any reliable way to reproduce the
problem, it will be difficult to know immediately whether it does the
trick or not. Rest assured, we will let you know if it does not :-)
Thanks,
-Seth Robertson