Обсуждение: [GENERAL] the database system is shutting down - terminating walsender processdue to replication timeout

Поиск
Список
Период
Сортировка

[GENERAL] the database system is shutting down - terminating walsender processdue to replication timeout

От
Zarko Aleksic
Дата:

Greetings everyone,


I'm looking for a bit of help understanding a particular behavior we are seeing with our PostgreSQL 9.6. After issuing a service shutdown command with "systemctl stop" on RHEL 7 our PostgreSQL instance started behaving weirdly. For the first time it wouldn't shutdown so easily / quickly. 


From the logs we could see that standby nodes that were trying to connect were rejected due to database being shutdown. After wal_sender_timeout and wal_receiver_timeout (default 60s) were reached the database finally shut down. It seems that walsender process was preventing the shutdown of the master database - until timeout was reached, a behavior we didn't experience before. 


Does anyone know why would this happen? 


We have 1 standby node in our primary site (same subnet as master DB), and two standbys in a remote site. WAL archiving is enabled to the remote site with rsync command that worked normally during this time and generally completes within a couple of seconds - definitely less than a minute. So we kind of ruled out WAL archiving. 

Would shutting down remote site standbys prevent this kind of delay, they usually have a couple of seconds lag in terms of replication (pg_xlog) location? 


Here is the postgres log from master that was being shutdown. 

2017-10-26 22:04:01 CDT [1701]: [6-1]  user=,db= LOG:  received fast shutdown request
2017-10-26 22:04:01 CDT [1701]: [7-1]  user=,db= LOG:  aborting any active transactions
2017-10-26 22:04:01 CDT [1711]: [2-1]  user=,db= LOG:  dbms_aq launcher shutting down
2017-10-26 22:04:01 CDT [1708]: [2-1]  user=,db= LOG:  autovacuum launcher shutting down
2017-10-26 22:04:01 CDT [1705]: [9971-1]  user=,db= LOG:  shutting down
2017-10-26 22:04:01 CDT [1705]: [9972-1]  user=,db= LOG:  checkpoint starting: shutdown immediate
2017-10-26 22:04:01 CDT [1705]: [9973-1]  user=,db= LOG:  checkpoint complete: wrote 54 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.017 s, sync=0.001 s, total=0.026 s; sync files=12, longest=0.000 s, average=0.000 s; distance=1100 kB, estimate=3307 kB
2017-10-26 22:04:01 CDT [1705]: [9974-1]  user=,db= LOG:  database system is shut down

2017-10-26 22:04:36 CDT [8763]: [1-1] "Local site standby IP"(49606) user=replication_user ,db=[unknown] FATAL:  the database system is shutting down

[OMITTED - a bunch of "FATAL:  the database system is shutting down" messages]

2017-10-26 22:05:00 CDT [2669]: [1-1] "Disaster recovery site standby IP" (55498) user=replication_user,db=[unknown] LOG:  terminating walsender process due to replication timeout

2017-10-26 22:05:00 CDT [1465]: [1-1] "Disaster recovery site standby IP"(36948) user=replication_user,db=[unknown] LOG:  terminating walsender process due to replication timeout
2017-10-26 22:05:01 CDT [1701]: [8-1]  user=,db= LOG:  database system is shut down

Standbys had the same message regarding walreceiver being terminated due to replication timeout.

Any help is greatly appreciated.

Thanks,
Zarko

[GENERAL] the database system is shutting down - terminating walsender processdue to replication timeout

От
Zarko Aleksic
Дата:


Greetings everyone,


I'm looking for a bit of help understanding a particular behavior we are seeing with our PostgreSQL 9.6. After issuing a service shutdown command with "systemctl stop" on RHEL 7 our PostgreSQL instance started behaving weirdly. For the first time it wouldn't shutdown so easily / quickly. 


From the logs we could see that standby nodes that were trying to connect were rejected due to database being shutdown. After wal_sender_timeout and wal_receiver_timeout (default 60s) were reached the database finally shut down. It seems that walsender process was preventing the shutdown of the master database - until timeout was reached, a behavior we didn't experience before. 


Does anyone know why would this happen? 


We have 1 standby node in our primary site (same subnet as master DB), and two standbys in a remote site. WAL archiving is enabled to the remote site with rsync command that worked normally during this time and generally completes within a couple of seconds - definitely less than a minute. So we kind of ruled out WAL archiving. 

Would shutting down remote site standbys prevent this kind of delay, they usually have a couple of seconds lag in terms of replication (pg_xlog) location? 


Here is the postgres log from master that was being shutdown. 

2017-10-26 22:04:01 CDT [1701]: [6-1]  user=,db= LOG:  received fast shutdown request
2017-10-26 22:04:01 CDT [1701]: [7-1]  user=,db= LOG:  aborting any active transactions
2017-10-26 22:04:01 CDT [1711]: [2-1]  user=,db= LOG:  dbms_aq launcher shutting down
2017-10-26 22:04:01 CDT [1708]: [2-1]  user=,db= LOG:  autovacuum launcher shutting down
2017-10-26 22:04:01 CDT [1705]: [9971-1]  user=,db= LOG:  shutting down
2017-10-26 22:04:01 CDT [1705]: [9972-1]  user=,db= LOG:  checkpoint starting: shutdown immediate
2017-10-26 22:04:01 CDT [1705]: [9973-1]  user=,db= LOG:  checkpoint complete: wrote 54 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=0.017 s, sync=0.001 s, total=0.026 s; sync files=12, longest=0.000 s, average=0.000 s; distance=1100 kB, estimate=3307 kB
2017-10-26 22:04:01 CDT [1705]: [9974-1]  user=,db= LOG:  database system is shut down

2017-10-26 22:04:36 CDT [8763]: [1-1] "Local site standby IP"(49606) user=replication_user ,db=[unknown] FATAL:  the database system is shutting down

[OMITTED - a bunch of "FATAL:  the database system is shutting down" messages]

2017-10-26 22:05:00 CDT [2669]: [1-1] "Disaster recovery site standby IP" (55498) user=replication_user,db=[unknown] LOG:  terminating walsender process due to replication timeout

2017-10-26 22:05:00 CDT [1465]: [1-1] "Disaster recovery site standby IP"(36948) user=replication_user,db=[unknown] LOG:  terminating walsender process due to replication timeout
2017-10-26 22:05:01 CDT [1701]: [8-1]  user=,db= LOG:  database system is shut down

Standbys had the same message regarding walreceiver being terminated due to replication timeout.

Any help is greatly appreciated.

Thanks,
Zarko

Re: [GENERAL] the database system is shutting down - terminating walsender process due to replication timeout

От
Tom Lane
Дата:
Zarko Aleksic <zarko.aleksic@live.com> writes:
> I'm looking for a bit of help understanding a particular behavior we are seeing with our PostgreSQL 9.6. After
issuinga service shutdown command with "systemctl stop" on RHEL 7 our PostgreSQL instance started behaving weirdly. For
thefirst time it wouldn't shutdown so easily / quickly. 
> From the logs we could see that standby nodes that were trying to connect were rejected due to database being
shutdown.After wal_sender_timeout and wal_receiver_timeout (default 60s) were reached the database finally shut down.
Itseems that walsender process was preventing the shutdown of the master database - until timeout was reached, a
behaviorwe didn't experience before. 

9.6.what?

There were several possibly-relevant bug fixes in 9.6.3 and 9.6.4,
notably this one:

Author: Tom Lane <tgl@sss.pgh.pa.us>
Branch: master Release: REL_10_BR [fca85f8ef] 2017-06-30 12:00:15 -0400
Branch: REL9_6_STABLE Release: REL9_6_4 [e9d4aa594] 2017-06-30 12:00:03 -0400
Branch: REL9_5_STABLE Release: REL9_5_8 [446914f6b] 2017-06-30 12:00:03 -0400
Branch: REL9_4_STABLE Release: REL9_4_13 [5aa8db014] 2017-06-30 12:00:03 -0400
   Fix walsender to exit promptly if client requests shutdown.      It's possible for WalSndWaitForWal to be asked to
waitfor WAL that doesn't   exist yet.  That's fine, in fact it's the normal situation if we're caught   up; but when
theclient requests shutdown we should not keep waiting.   The previous coding could wait indefinitely if the source
serverwas idle.      In passing, improve the rather weak comments in this area, and slightly   rearrange some related
codefor better readability.      Back-patch to 9.4 where this code was introduced.      Discussion:
https://postgr.es/m/14154.1498781234@sss.pgh.pa.us

I think that would only apply if the walsender's client had tried to
disconnect at the same time you were doing the master-server shutdown,
but maybe that's what happened.

There is still work going on around the walsender timeout, so maybe
what you hit is an as-yet-unresolved bug, but in any case you should
be keeping up with minor releases.
        regards, tom lane


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

Re: [GENERAL] the database system is shutting down - terminatingwalsender process due to replication timeout

От
Zarko Aleksic
Дата:

Thanks for you reply. In the meantime we figured out what the issue was. We had a virtual IP that was being released from the master server just as the master would try to stream the last checkpoint. This caused wal_sender process to hang until the timeout value was reached. Technically speaking, it was a networking problem, but not on the switch/router, rather on the host it self. Stopping the replication from standby to the (movable) master VIP was the solution that we went with.


Best regards,
Zarko

From: Tom Lane <tgl@sss.pgh.pa.us>
Sent: Wednesday, November 1, 2017 10:25 AM
To: Zarko Aleksic
Cc: pgsql-general@postgresql.org
Subject: Re: [GENERAL] the database system is shutting down - terminating walsender process due to replication timeout
 
Zarko Aleksic <zarko.aleksic@live.com> writes:
> I'm looking for a bit of help understanding a particular behavior we are seeing with our PostgreSQL 9.6. After issuing a service shutdown command with "systemctl stop" on RHEL 7 our PostgreSQL instance started behaving weirdly. For the first time it wouldn't shutdown so easily / quickly.
> From the logs we could see that standby nodes that were trying to connect were rejected due to database being shutdown. After wal_sender_timeout and wal_receiver_timeout (default 60s) were reached the database finally shut down. It seems that walsender process was preventing the shutdown of the master database - until timeout was reached, a behavior we didn't experience before.

9.6.what?

There were several possibly-relevant bug fixes in 9.6.3 and 9.6.4,
notably this one:

Author: Tom Lane <tgl@sss.pgh.pa.us>
Branch: master Release: REL_10_BR [fca85f8ef] 2017-06-30 12:00:15 -0400
Branch: REL9_6_STABLE Release: REL9_6_4 [e9d4aa594] 2017-06-30 12:00:03 -0400
Branch: REL9_5_STABLE Release: REL9_5_8 [446914f6b] 2017-06-30 12:00:03 -0400
Branch: REL9_4_STABLE Release: REL9_4_13 [5aa8db014] 2017-06-30 12:00:03 -0400

    Fix walsender to exit promptly if client requests shutdown.
   
    It's possible for WalSndWaitForWal to be asked to wait for WAL that doesn't
    exist yet.  That's fine, in fact it's the normal situation if we're caught
    up; but when the client requests shutdown we should not keep waiting.
    The previous coding could wait indefinitely if the source server was idle.
   
    In passing, improve the rather weak comments in this area, and slightly
    rearrange some related code for better readability.
   
    Back-patch to 9.4 where this code was introduced.
   
    Discussion: https://postgr.es/m/14154.1498781234@sss.pgh.pa.us

I think that would only apply if the walsender's client had tried to
disconnect at the same time you were doing the master-server shutdown,
but maybe that's what happened.

There is still work going on around the walsender timeout, so maybe
what you hit is an as-yet-unresolved bug, but in any case you should
be keeping up with minor releases.

                        regards, tom lane