Re: [HACKERS] Inefficient shutdown of pg_basebackup

[Simon Riggs]

On 27 April 2017 at 05:31, Tom Lane  wrote:

> The attached draft patch fixes this by expanding the StreamCtl API
> with a socket that the low-level wait routine should check for input.
> For me, this consistently knocks about 10 seconds off the runtime of
> 001_stream_rep.pl.

That is good. I noticed that delay many times.

> It could be argued that this isn't too significant in the real world
> because pg_basebackup would always run far longer than 10 seconds
> anyway for non-toy data.  But it still looks like a bug to me.

Not sure its a bug, but if it causes people to avoid running tests
then it is clearly a reliability issue.

I don't see anything to gain by waiting a year to apply this, so +1 to
move on it now.

-- 
Simon Riggshttp://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services


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

[HACKERS] Inefficient shutdown of pg_basebackup

[Tom Lane]

I griped before that the src/test/recovery/ tests take an unreasonably
long time.  My interest in that was piqued further when I noticed that
the tests consume not very much CPU time, and aren't exactly saturating
my disks either.  That suggests that the problem isn't so much that the
tests do too much work, as that we've got dire performance problems in
either the test harness or the code under test.

While I'm continuing to poke at it, I've identified one such problem:
the system basically stops dead for about ten seconds at the end of
the pg_basebackup run invoked by t/001_stream_rep.pl.  The length of
the idle time corresponds to pg_basebackup's -s (standby_message_timeout)
parameter; you can make it even worse by increasing that parameter or
setting it to zero.  (In principle, setting it to zero ought to cause
pg_basebackup to never terminate at all :-( ... but apparently there is
some other effect that will wake it up after 30 seconds or so.  I've not
found out what yet.)

The reason for this appears to be that by the time the pg_basebackup
parent process has determined the xlogend position and sent it down
the bgpipe to the child process, the child process has already read
all the WAL that the source server is going to send, and is waiting
for more such input with a timeout corresponding to
standby_message_timeout.  Only after that timeout elapses does it
get around to noticing that some input is available from the bgpipe
and then realizing that it's time to stop streaming.

The attached draft patch fixes this by expanding the StreamCtl API
with a socket that the low-level wait routine should check for input.
For me, this consistently knocks about 10 seconds off the runtime of
001_stream_rep.pl.

It could be argued that this isn't too significant in the real world
because pg_basebackup would always run far longer than 10 seconds
anyway for non-toy data.  But it still looks like a bug to me.

regards, tom lane

diff --git a/src/bin/pg_basebackup/pg_basebackup.c b/src/bin/pg_basebackup/pg_basebackup.c
index 40ec0e1..e2a2ebb 100644
*** a/src/bin/pg_basebackup/pg_basebackup.c
--- b/src/bin/pg_basebackup/pg_basebackup.c
*** LogStreamerMain(logstreamer_param *param
*** 480,485 
--- 480,490 
  	stream.timeline = param->timeline;
  	stream.sysidentifier = param->sysidentifier;
  	stream.stream_stop = reached_end_position;
+ #ifndef WIN32
+ 	stream.stop_socket = bgpipe[0];
+ #else
+ 	stream.stop_socket = PGINVALID_SOCKET;
+ #endif
  	stream.standby_message_timeout = standby_message_timeout;
  	stream.synchronous = false;
  	stream.do_sync = do_sync;
diff --git a/src/bin/pg_basebackup/pg_receivewal.c b/src/bin/pg_basebackup/pg_receivewal.c
index 1a9fe81..09385c5 100644
*** a/src/bin/pg_basebackup/pg_receivewal.c
--- b/src/bin/pg_basebackup/pg_receivewal.c
*** StreamLog(void)
*** 409,414 
--- 409,415 
  stream.timeline);
  
  	stream.stream_stop = stop_streaming;
+ 	stream.stop_socket = PGINVALID_SOCKET;
  	stream.standby_message_timeout = standby_message_timeout;
  	stream.synchronous = synchronous;
  	stream.do_sync = true;
diff --git a/src/bin/pg_basebackup/receivelog.c b/src/bin/pg_basebackup/receivelog.c
index 8511e57..c41bba2 100644
*** a/src/bin/pg_basebackup/receivelog.c
--- b/src/bin/pg_basebackup/receivelog.c
*** static bool still_sending = true;		/* fe
*** 39,46 
  
  static PGresult *HandleCopyStream(PGconn *conn, StreamCtl *stream,
   XLogRecPtr *stoppos);
! static int	CopyStreamPoll(PGconn *conn, long timeout_ms);
! static int	CopyStreamReceive(PGconn *conn, long timeout, char **buffer);
  static bool ProcessKeepaliveMsg(PGconn *conn, StreamCtl *stream, char *copybuf,
  	int len, XLogRecPtr blockpos, TimestampTz *last_status);
  static bool ProcessXLogDataMsg(PGconn *conn, StreamCtl *stream, char *copybuf, int len,
--- 39,47 
  
  static PGresult *HandleCopyStream(PGconn *conn, StreamCtl *stream,
   XLogRecPtr *stoppos);
! static int	CopyStreamPoll(PGconn *conn, long timeout_ms, pgsocket stop_socket);
! static int CopyStreamReceive(PGconn *conn, long timeout, pgsocket stop_socket,
!   char **buffer);
  static bool ProcessKeepaliveMsg(PGconn *conn, StreamCtl *stream, char *copybuf,
  	int len, XLogRecPtr blockpos, TimestampTz *last_status);
  static bool ProcessXLogDataMsg(PGconn *conn, StreamCtl *stream, char *copybuf, int len,
*** CheckServerVersionForStreaming(PGconn *c
*** 417,424 
--- 418,432 
   * return. As long as it returns false, streaming will continue
   * indefinitely.
   *
+  * If stream_stop() checks for external input, stop_socket should be set to
+  * the FD it checks.  This will allow such input to be detected promptly
+  * rather than after standby_message_timeout (which might be indefinite).
+  * Note that signals will interrupt waits for input as well, but that is
+  * race-y since a signal received while busy won't interrupt the wait.
+  *
   *